From 75656712e34694460ce7b12fc5a467667e04ea21 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Mon, 9 Feb 2015 14:22:52 +0000 Subject: [PATCH] Time how long we're spending on the database thread --- synapse/app/homeserver.py | 2 ++ synapse/storage/_base.py | 25 +++++++++++++++++++++++++ 2 files changed, 27 insertions(+) diff --git a/synapse/app/homeserver.py b/synapse/app/homeserver.py index 0f175ec3f..8976ff2e8 100755 --- a/synapse/app/homeserver.py +++ b/synapse/app/homeserver.py @@ -274,6 +274,8 @@ def setup(): hs.get_pusherpool().start() + hs.get_datastore().start_profiling() + if config.daemonize: print config.pid_file daemon = Daemonize( diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py index b350fd61f..0849c5f1b 100644 --- a/synapse/storage/_base.py +++ b/synapse/storage/_base.py @@ -85,6 +85,28 @@ class SQLBaseStore(object): self._db_pool = hs.get_db_pool() self._clock = hs.get_clock() + self._previous_txn_total_time = 0 + self._current_txn_total_time = 0 + self._previous_loop_ts = 0 + + def start_profiling(self): + self._previous_loop_ts = self._clock.time_msec() + + 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_then = self._previous_loop_ts + self._previous_loop_ts = time_now + + ratio = (curr - prev)/(time_now - time_then) + + logger.info("Total database time: %.3f", ratio) + + self._clock.looping_call(loop, 1000) + @defer.inlineCallbacks def runInteraction(self, desc, func, *args, **kwargs): """Wraps the .runInteraction() method on the underlying db_pool.""" @@ -114,6 +136,9 @@ class SQLBaseStore(object): "[TXN END] {%s} %f", name, end - start ) + + self._current_txn_total_time += end - start + with PreserveLoggingContext(): result = yield self._db_pool.runInteraction( inner_func, *args, **kwargs