fix: use monotonic clock for timing code (#19138)

* fix: use monotonic time for timing code

`time.time()` depends on system clock which can drift away and get corrected
over time. If you're unlucky it will get corrected in your timing code
and give absurd results.

* test: dont check for status

can refresh and give wrong output

[skip ci]

frappe/core/doctype/rq_job/test_rq_job.py

@@ -38,7 +38,6 @@ class TestRQJob(FrappeTestCase):
 				"name": job.id,
 				"queue": "short",
 				"job_name": self.BG_JOB,
-				"status": "queued",
 				"exc_info": None,
 			},
 			rq_job,

frappe/email/receive.py

@@ -987,10 +987,10 @@ class TimerMixin:
 			self.sock.settimeout(self.timeout / 5.0)
 
 	def _getline(self, *args, **kwargs):
-		start_time = time.time()
+		start_time = time.monotonic()
 		ret = self._super._getline(self, *args, **kwargs)
 
-		self.elapsed_time += time.time() - start_time
+		self.elapsed_time += time.monotonic() - start_time
 		if self.timeout and self.elapsed_time > self.timeout:
 			raise EmailTimeoutError
 

frappe/modules/patch_handler.py

@@ -173,7 +173,7 @@ def execute_patch(patchmodule, method=None, methodargs=None):
 		f"Executing {patchmodule or methodargs} in {frappe.local.site} ({frappe.db.cur_db_name}){docstring}"
 	)
 
-	start_time = time.time()
+	start_time = time.monotonic()
 	frappe.db.begin()
 	frappe.db.auto_commit_on_many_writes = 0
 	try:
@@ -197,7 +197,7 @@ def execute_patch(patchmodule, method=None, methodargs=None):
 
 	else:
 		frappe.db.commit()
-		end_time = time.time()
+		end_time = time.monotonic()
 		_patch_mode(False)
 		print(f"Success: Done in {round(end_time - start_time, 3)}s")
 

frappe/parallel_test_runner.py

@@ -42,7 +42,7 @@ class ParallelTestRunner:
 		self.before_test_setup()
 
 	def before_test_setup(self):
-		start_time = time.time()
+		start_time = time.monotonic()
 		for fn in frappe.get_hooks("before_tests", app_name=self.app):
 			frappe.get_attr(fn)()
 
@@ -52,7 +52,7 @@ class ParallelTestRunner:
 			for doctype in test_module.global_test_dependencies:
 				make_test_records(doctype, commit=True)
 
-		elapsed = time.time() - start_time
+		elapsed = time.monotonic() - start_time
 		elapsed = click.style(f" ({elapsed:.03}s)", fg="red")
 		click.echo(f"Before Test {elapsed}")
 
@@ -162,7 +162,7 @@ def split_by_weight(work, weights, chunk_count):
 class ParallelTestResult(unittest.TextTestResult):
 	def startTest(self, test):
 		self.tb_locals = True
-		self._started_at = time.time()
+		self._started_at = time.monotonic()
 		super(unittest.TextTestResult, self).startTest(test)
 		test_class = unittest.util.strclass(test.__class__)
 		if not hasattr(self, "current_test_class") or self.current_test_class != test_class:
@@ -174,7 +174,7 @@ class ParallelTestResult(unittest.TextTestResult):
 
 	def addSuccess(self, test):
 		super(unittest.TextTestResult, self).addSuccess(test)
-		elapsed = time.time() - self._started_at
+		elapsed = time.monotonic() - self._started_at
 		threshold_passed = elapsed >= SLOW_TEST_THRESHOLD
 		elapsed = click.style(f" ({elapsed:.03}s)", fg="red") if threshold_passed else ""
 		click.echo(f"  {click.style(' ✔ ', fg='green')} {self.getTestMethodName(test)}{elapsed}")

frappe/recorder.py

@@ -20,9 +20,9 @@ TRACEBACK_PATH_PATTERN = re.compile(".*/apps/")
 
 
 def sql(*args, **kwargs):
-	start_time = time.time()
+	start_time = time.monotonic()
 	result = frappe.db._sql(*args, **kwargs)
-	end_time = time.time()
+	end_time = time.monotonic()
 
 	stack = list(get_current_stack_frames())
 	query = sqlparse.format(str(frappe.db.last_query).strip(), keyword_case="upper", reindent=True)

frappe/test_runner.py

@@ -148,11 +148,11 @@ def set_test_email_config():
 
 class TimeLoggingTestResult(unittest.TextTestResult):
 	def startTest(self, test):
-		self._started_at = time.time()
+		self._started_at = time.monotonic()
 		super().startTest(test)
 
 	def addSuccess(self, test):
-		elapsed = time.time() - self._started_at
+		elapsed = time.monotonic() - self._started_at
 		name = self.getDescription(test)
 		if elapsed >= SLOW_TEST_THRESHOLD:
 			self.stream.write(f"\n{name} ({elapsed:.03}s)\n")