Merge pull request #429 from matrix-org/markjh/db_counters

Track the time spent in the database per request.

synapse/app/homeserver.py

@@ -503,19 +503,24 @@ def finished_processing(self):
         try:
             context = LoggingContext.current_context()
             ru_utime, ru_stime = context.get_resource_usage()
+            db_txn_count = context.db_txn_count
+            db_txn_duration = context.db_txn_duration
         except:
             ru_utime, ru_stime = (0, 0)
+            db_txn_count, db_txn_duration = (0, 0)
 
         self.site.access_logger.info(
             "%s - %s - {%s}"
-            " Processed request: %dms (%dms, %dms)"
+            " Processed request: %dms (%dms, %dms) (%dms/%d)"
             " %sB %s \"%s %s %s\" \"%s\"",
             self.getClientIP(),
             self.site.site_tag,
             self.authenticated_entity,
             int(time.time() * 1000) - self.start_time,
             int(ru_utime * 1000),
             int(ru_stime * 1000),
+            int(db_txn_duration * 1000),
+            int(db_txn_count),
             self.sentLength,
             self.code,
             self.method,

synapse/http/server.py

@@ -61,6 +61,15 @@
     "response_ru_stime", labels=["method", "servlet"]
 )
 
+response_db_txn_count = metrics.register_distribution(
+    "response_db_txn_count", labels=["method", "servlet"]
+)
+
+response_db_txn_duration = metrics.register_distribution(
+    "response_db_txn_duration", labels=["method", "servlet"]
+)
+
+
 _next_request_id = 0
 
 
@@ -235,6 +244,12 @@ def _async_render(self, request):
 
                 response_ru_utime.inc_by(ru_utime, request.method, servlet_classname)
                 response_ru_stime.inc_by(ru_stime, request.method, servlet_classname)
+                response_db_txn_count.inc_by(
+                    context.db_txn_count, request.method, servlet_classname
+                )
+                response_db_txn_duration.inc_by(
+                    context.db_txn_duration, request.method, servlet_classname
+                )
             except:
                 pass
 

synapse/storage/_base.py

@@ -214,7 +214,8 @@ def loop():
 
         self._clock.looping_call(loop, 10000)
 
-    def _new_transaction(self, conn, desc, after_callbacks, func, *args, **kwargs):
+    def _new_transaction(self, conn, desc, after_callbacks, logging_context,
+                         func, *args, **kwargs):
         start = time.time() * 1000
         txn_id = self._TXN_ID
 
@@ -277,6 +278,9 @@ def _new_transaction(self, conn, desc, after_callbacks, func, *args, **kwargs):
             end = time.time() * 1000
             duration = end - start
 
+            if logging_context is not None:
+                logging_context.add_database_transaction(duration)
+
             transaction_logger.debug("[TXN END] {%s} %f", name, duration)
 
             self._current_txn_total_time += duration
@@ -302,7 +306,8 @@ def inner_func(conn, *args, **kwargs):
 
                 current_context.copy_to(context)
                 return self._new_transaction(
-                    conn, desc, after_callbacks, func, *args, **kwargs
+                    conn, desc, after_callbacks, current_context,
+                    func, *args, **kwargs
                 )
 
         result = yield preserve_context_over_fn(

synapse/storage/events.py

@@ -649,7 +649,7 @@ def _do_fetch(self, conn):
                 ]
 
                 rows = self._new_transaction(
-                    conn, "do_fetch", [], self._fetch_event_rows, event_ids
+                    conn, "do_fetch", [], None, self._fetch_event_rows, event_ids
                 )
 
                 row_dict = {

synapse/util/logcontext.py

@@ -69,13 +69,18 @@ def start(self):
         def stop(self):
             pass
 
+        def add_database_transaction(self, duration_ms):
+            pass
+
     sentinel = Sentinel()
 
     def __init__(self, name=None):
         self.parent_context = None
         self.name = name
         self.ru_stime = 0.
         self.ru_utime = 0.
+        self.db_txn_count = 0
+        self.db_txn_duration = 0.
         self.usage_start = None
         self.main_thread = threading.current_thread()
 
@@ -171,6 +176,10 @@ def get_resource_usage(self):
 
         return ru_utime, ru_stime
 
+    def add_database_transaction(self, duration_ms):
+        self.db_txn_count += 1
+        self.db_txn_duration += duration_ms / 1000.
+
 
 class LoggingContextFilter(logging.Filter):
     """Logging filter that adds values from the current logging context to each