From 6a5ff5f223c1b4311aa63574663c0335d0c6bd79 Mon Sep 17 00:00:00 2001
From: Mark Haines <mark.haines@matrix.org>
Date: Mon, 7 Dec 2015 17:56:11 +0000
Subject: [PATCH] Track the time spent in the database per request.

and track the number of transactions that request started.
---
 synapse/app/homeserver.py  |  7 ++++++-
 synapse/http/server.py     | 15 +++++++++++++++
 synapse/storage/_base.py   |  9 +++++++--
 synapse/storage/events.py  |  2 +-
 synapse/util/logcontext.py |  9 +++++++++
 5 files changed, 38 insertions(+), 4 deletions(-)

diff --git a/synapse/app/homeserver.py b/synapse/app/homeserver.py
index 58c679bbfd..56bc52e9ca 100755
--- a/synapse/app/homeserver.py
+++ b/synapse/app/homeserver.py
@@ -503,12 +503,15 @@ class SynapseRequest(Request):
         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,
@@ -516,6 +519,8 @@ class SynapseRequest(Request):
             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,
diff --git a/synapse/http/server.py b/synapse/http/server.py
index 06fb53707b..c44bdfc888 100644
--- a/synapse/http/server.py
+++ b/synapse/http/server.py
@@ -61,6 +61,15 @@ response_ru_stime = metrics.register_distribution(
     "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 @@ class JsonResource(HttpServer, resource.Resource):
 
                 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
 
diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py
index 218e708054..17a14e001c 100644
--- a/synapse/storage/_base.py
+++ b/synapse/storage/_base.py
@@ -214,7 +214,8 @@ class SQLBaseStore(object):
 
         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 @@ class SQLBaseStore(object):
             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 @@ class SQLBaseStore(object):
 
                 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(
diff --git a/synapse/storage/events.py b/synapse/storage/events.py
index 7088f2709b..fc5725097c 100644
--- a/synapse/storage/events.py
+++ b/synapse/storage/events.py
@@ -649,7 +649,7 @@ class EventsStore(SQLBaseStore):
                 ]
 
                 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 = {
diff --git a/synapse/util/logcontext.py b/synapse/util/logcontext.py
index c20c89aa8f..d528ced55a 100644
--- a/synapse/util/logcontext.py
+++ b/synapse/util/logcontext.py
@@ -69,6 +69,9 @@ class LoggingContext(object):
         def stop(self):
             pass
 
+        def add_database_transaction(self, duration_ms):
+            pass
+
     sentinel = Sentinel()
 
     def __init__(self, name=None):
@@ -76,6 +79,8 @@ class LoggingContext(object):
         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 @@ class LoggingContext(object):
 
         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