From 15bf32e06204b99ea4758ce6ffd9bff725c74d90 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 19 Jun 2019 21:04:58 +0100 Subject: [PATCH] Use monotonic clock where possible for metrics Fixes intermittent errors observed on Apple hardware which were caused by time.clock() appearing to go backwards when called from different threads. Also fixes a bug where database activity times were logged as 1/1000 of their correct ratio due to confusion between milliseconds and seconds. --- changelog.d/5498.bugfix | 1 + synapse/storage/_base.py | 20 ++++++++++++++------ 2 files changed, 15 insertions(+), 6 deletions(-) create mode 100644 changelog.d/5498.bugfix diff --git a/changelog.d/5498.bugfix b/changelog.d/5498.bugfix new file mode 100644 index 000000000..6ef298d20 --- /dev/null +++ b/changelog.d/5498.bugfix @@ -0,0 +1 @@ +Fix intermittent exceptions on Apple hardware. Also fix bug that caused database activity times to be under-reported in log lines. diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py index ae891aa33..d8054cd69 100644 --- a/synapse/storage/_base.py +++ b/synapse/storage/_base.py @@ -38,6 +38,14 @@ from synapse.util.caches.descriptors import Cache from synapse.util.logcontext import LoggingContext, PreserveLoggingContext from synapse.util.stringutils import exception_to_unicode +# import a function which will return a monotonic time, in seconds +try: + # on python 3, use time.monotonic, since time.clock can go backwards + from time import monotonic as monotonic_time +except ImportError: + # ... but python 2 doesn't have it + from time import clock as monotonic_time + logger = logging.getLogger(__name__) try: @@ -352,14 +360,14 @@ class SQLBaseStore(object): ) def start_profiling(self): - self._previous_loop_ts = self._clock.time_msec() + self._previous_loop_ts = monotonic_time() def loop(): curr = self._current_txn_total_time prev = self._previous_txn_total_time self._previous_txn_total_time = curr - time_now = self._clock.time_msec() + time_now = monotonic_time() time_then = self._previous_loop_ts self._previous_loop_ts = time_now @@ -385,7 +393,7 @@ class SQLBaseStore(object): def _new_transaction( self, conn, desc, after_callbacks, exception_callbacks, func, *args, **kwargs ): - start = time.time() + start = monotonic_time() txn_id = self._TXN_ID # We don't really need these to be unique, so lets stop it from @@ -451,7 +459,7 @@ class SQLBaseStore(object): logger.debug("[TXN FAIL] {%s} %s", name, e) raise finally: - end = time.time() + end = monotonic_time() duration = end - start LoggingContext.current_context().add_database_transaction(duration) @@ -525,11 +533,11 @@ class SQLBaseStore(object): ) parent_context = None - start_time = time.time() + start_time = monotonic_time() def inner_func(conn, *args, **kwargs): with LoggingContext("runWithConnection", parent_context) as context: - sched_duration_sec = time.time() - start_time + sched_duration_sec = monotonic_time() - start_time sql_scheduling_timer.observe(sched_duration_sec) context.add_database_scheduled(sched_duration_sec)