summary refs log tree commit diff
diff options
context:
space:
mode:
authorErik Johnston <erik@matrix.org>2015-02-09 18:08:08 +0000
committerErik Johnston <erik@matrix.org>2015-02-09 18:08:08 +0000
commit375eba6a1885dfe23fb6623a788f6f608124cc91 (patch)
treeba4e0fa27bc39a6e022aece5536b6cd5a2e6d115
parentNeed to use re.search if looking for matches not at the start of the string. ... (diff)
parentUse the transaction 'desc' rather than 'name', increment the txn_ids in (diff)
downloadsynapse-375eba6a1885dfe23fb6623a788f6f608124cc91.tar.xz
Merge pull request #57 from matrix-org/transaction_counters
Transaction counters
Diffstat (limited to '')
-rw-r--r--synapse/storage/_base.py33
1 files changed, 31 insertions, 2 deletions
diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py
index 310ee0104c..5ddd410607 100644
--- a/synapse/storage/_base.py
+++ b/synapse/storage/_base.py
@@ -88,6 +88,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 +105,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)
 
@@ -116,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.
@@ -139,6 +163,11 @@ class SQLBaseStore(object):
 
                     self._current_txn_total_time += end - start
 
+                    count, cum_time = self._txn_perf_counters.get(desc, (0,0))
+                    count += 1
+                    cum_time += end - start
+                    self._txn_perf_counters[desc] = (count, cum_time)
+
         with PreserveLoggingContext():
             result = yield self._db_pool.runInteraction(
                 inner_func, *args, **kwargs