Track DB scheduling delay per-request

For each request, track the amount of time spent waiting for a db
connection. This entails adding it to the LoggingContext and we may as well add
metrics for it while we are passing.

2 files changed, 10 insertions, 1 deletions

diff --git a/synapse/http/server.py b/synapse/http/server.py
index 0f30e6fd56..7b6418bc2c 100644
--- a/synapse/http/server.py
+++ b/synapse/http/server.py
@@ -102,6 +102,10 @@ response_db_txn_duration = metrics.register_counter(
     ),
 )
 
+# seconds spent waiting for a db connection, when processing this request
+response_db_sched_duration = metrics.register_counter(
+    "response_db_sched_duration_seconds", labels=["method", "servlet", "tag"]
+)
 
 _next_request_id = 0
 
@@ -381,6 +385,9 @@ class RequestMetrics(object):
         response_db_txn_duration.inc_by(
             context.db_txn_duration_ms / 1000., request.method, self.name, tag
         )
+        response_db_sched_duration.inc_by(
+            context.db_sched_duration_ms / 1000., request.method, self.name, tag
+        )
 
 
 class RootRedirect(resource.Resource):
diff --git a/synapse/http/site.py b/synapse/http/site.py
index dc64f0f6f5..e422c8dfae 100644
--- a/synapse/http/site.py
+++ b/synapse/http/site.py
@@ -67,13 +67,14 @@ class SynapseRequest(Request):
             ru_utime, ru_stime = context.get_resource_usage()
             db_txn_count = context.db_txn_count
             db_txn_duration_ms = context.db_txn_duration_ms
+            db_sched_duration_ms = context.db_sched_duration_ms
         except Exception:
             ru_utime, ru_stime = (0, 0)
             db_txn_count, db_txn_duration_ms = (0, 0)
 
         self.site.access_logger.info(
             "%s - %s - {%s}"
-            " Processed request: %dms (%dms, %dms) (%dms/%d)"
+            " Processed request: %dms (%dms, %dms) (%dms/%dms/%d)"
             " %sB %s \"%s %s %s\" \"%s\"",
             self.getClientIP(),
             self.site.site_tag,
@@ -81,6 +82,7 @@ class SynapseRequest(Request):
             int(time.time() * 1000) - self.start_time,
             int(ru_utime * 1000),
             int(ru_stime * 1000),
+            db_sched_duration_ms,
             db_txn_duration_ms,
             int(db_txn_count),
             self.sentLength,