From 3a5ad7dbd5a375023c96ee65c901f8be5ab02341 Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Mon, 9 Feb 2015 17:55:56 +0000 Subject: [PATCH 1/3] Performance counters for database transaction names --- synapse/storage/_base.py | 32 +++++++++++++++++++++++++++++++- 1 file changed, 31 insertions(+), 1 deletion(-) diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py index 310ee0104c..bcb03cbdcb 100644 --- a/synapse/storage/_base.py +++ b/synapse/storage/_base.py @@ -39,6 +39,7 @@ class LoggingTransaction(object): passed to the constructor. Adds logging to the .execute() method.""" __slots__ = ["txn", "name"] + def __init__(self, txn, name): object.__setattr__(self, "txn", txn) object.__setattr__(self, "name", name) @@ -88,6 +89,8 @@ class SQLBaseStore(object): self._previous_txn_total_time = 0 self._current_txn_total_time = 0 self._previous_loop_ts = 0 + self._txn_perf_counters = {} + self._previous_txn_perf_counters = {} def start_profiling(self): self._previous_loop_ts = self._clock.time_msec() @@ -103,7 +106,29 @@ class SQLBaseStore(object): ratio = (curr - prev)/(time_now - time_then) - logger.info("Total database time: %.3f%%", ratio * 100) + txn_counters = [] + for name, (count, cum_time) in self._txn_perf_counters.items(): + prev_count, prev_time = self._previous_txn_perf_counters.get( + name, (0,0) + ) + txn_counters.append(( + (cum_time - prev_time) / (time_now - time_then), + count - prev_count, + name + )) + + self._previous_txn_perf_counters = dict(self._txn_perf_counters) + + txn_counters.sort(reverse=True) + top_three_counters = ", ".join( + "%s(%d): %.3f%%" % (name, count, 100 * ratio) + for ratio, count, name in txn_counters[:3] + ) + + logger.info( + "Total database time: %.3f%% {%s}", + ratio * 100, top_three_counters + ) self._clock.looping_call(loop, 10000) @@ -139,6 +164,11 @@ class SQLBaseStore(object): self._current_txn_total_time += end - start + count, cum_time = self._txn_perf_counters.get(name, (0,0)) + count += 1 + cum_time += end - start + self._txn_perf_counters[name] = (count, cum_time) + with PreserveLoggingContext(): result = yield self._db_pool.runInteraction( inner_func, *args, **kwargs From 347b497db0355fe4e26ae3a51967aa91bec090d3 Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Mon, 9 Feb 2015 17:57:09 +0000 Subject: [PATCH 2/3] Formatting --- synapse/storage/_base.py | 1 - 1 file changed, 1 deletion(-) diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py index bcb03cbdcb..45f4b994eb 100644 --- a/synapse/storage/_base.py +++ b/synapse/storage/_base.py @@ -39,7 +39,6 @@ class LoggingTransaction(object): passed to the constructor. Adds logging to the .execute() method.""" __slots__ = ["txn", "name"] - def __init__(self, txn, name): object.__setattr__(self, "txn", txn) object.__setattr__(self, "name", name) From 0c4536da8fe75a207052fb558414b4408aa857ec Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Mon, 9 Feb 2015 18:06:31 +0000 Subject: [PATCH 3/3] Use the transaction 'desc' rather than 'name', increment the txn_ids in txn names --- synapse/storage/_base.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py index 45f4b994eb..5ddd410607 100644 --- a/synapse/storage/_base.py +++ b/synapse/storage/_base.py @@ -140,7 +140,7 @@ class SQLBaseStore(object): with LoggingContext("runInteraction") as context: current_context.copy_to(context) start = time.time() * 1000 - txn_id = SQLBaseStore._TXN_ID + txn_id = self._TXN_ID # We don't really need these to be unique, so lets stop it from # growing really large. @@ -163,10 +163,10 @@ class SQLBaseStore(object): self._current_txn_total_time += end - start - count, cum_time = self._txn_perf_counters.get(name, (0,0)) + count, cum_time = self._txn_perf_counters.get(desc, (0,0)) count += 1 cum_time += end - start - self._txn_perf_counters[name] = (count, cum_time) + self._txn_perf_counters[desc] = (count, cum_time) with PreserveLoggingContext(): result = yield self._db_pool.runInteraction(