From 6324b65f08b3f8dbfee6fef0079e2a87cb1c2c85 Mon Sep 17 00:00:00 2001
From: Richard van der Hoff <richard@matrix.org>
Date: Thu, 11 Jan 2018 18:17:54 +0000
Subject: [PATCH] Track db txn time in millisecs

... to reduce the amount of floating-point foo we do.
---
 synapse/http/server.py     | 4 +++-
 synapse/http/site.py       | 6 +++---
 synapse/util/logcontext.py | 9 ++++++---
 synapse/util/metrics.py    | 8 +++++---
 4 files changed, 17 insertions(+), 10 deletions(-)

diff --git a/synapse/http/server.py b/synapse/http/server.py
index 269b65ca413b..0f30e6fd560f 100644
--- a/synapse/http/server.py
+++ b/synapse/http/server.py
@@ -93,6 +93,8 @@
     ),
 )
 
+# seconds spent waiting for db txns, excluding scheduling time, when processing
+# this request
 response_db_txn_duration = metrics.register_counter(
     "response_db_txn_duration_seconds", labels=["method", "servlet", "tag"],
     alternative_names=(
@@ -377,7 +379,7 @@ def stop(self, clock, request):
             context.db_txn_count, request.method, self.name, tag
         )
         response_db_txn_duration.inc_by(
-            context.db_txn_duration, request.method, self.name, tag
+            context.db_txn_duration_ms / 1000., request.method, self.name, tag
         )
 
 
diff --git a/synapse/http/site.py b/synapse/http/site.py
index cd1492b1c3f3..dc64f0f6f50b 100644
--- a/synapse/http/site.py
+++ b/synapse/http/site.py
@@ -66,10 +66,10 @@ def finished_processing(self):
             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
+            db_txn_duration_ms = context.db_txn_duration_ms
         except Exception:
             ru_utime, ru_stime = (0, 0)
-            db_txn_count, db_txn_duration = (0, 0)
+            db_txn_count, db_txn_duration_ms = (0, 0)
 
         self.site.access_logger.info(
             "%s - %s - {%s}"
@@ -81,7 +81,7 @@ def finished_processing(self):
             int(time.time() * 1000) - self.start_time,
             int(ru_utime * 1000),
             int(ru_stime * 1000),
-            int(db_txn_duration * 1000),
+            db_txn_duration_ms,
             int(db_txn_count),
             self.sentLength,
             self.code,
diff --git a/synapse/util/logcontext.py b/synapse/util/logcontext.py
index ca71a1fc2752..a78e53812fb7 100644
--- a/synapse/util/logcontext.py
+++ b/synapse/util/logcontext.py
@@ -59,7 +59,7 @@ class LoggingContext(object):
 
     __slots__ = [
         "previous_context", "name", "ru_stime", "ru_utime",
-        "db_txn_count", "db_txn_duration", "usage_start", "usage_end",
+        "db_txn_count", "db_txn_duration_ms", "usage_start", "usage_end",
         "main_thread", "alive",
         "request", "tag",
     ]
@@ -97,7 +97,10 @@ def __init__(self, name=None):
         self.ru_stime = 0.
         self.ru_utime = 0.
         self.db_txn_count = 0
-        self.db_txn_duration = 0.
+
+        # ms spent waiting for db txns, excluding scheduling time
+        self.db_txn_duration_ms = 0
+
         self.usage_start = None
         self.usage_end = None
         self.main_thread = threading.current_thread()
@@ -205,7 +208,7 @@ def get_resource_usage(self):
 
     def add_database_transaction(self, duration_ms):
         self.db_txn_count += 1
-        self.db_txn_duration += duration_ms / 1000.
+        self.db_txn_duration_ms += duration_ms
 
 
 class LoggingContextFilter(logging.Filter):
diff --git a/synapse/util/metrics.py b/synapse/util/metrics.py
index 8d22ff306825..d25629cc5042 100644
--- a/synapse/util/metrics.py
+++ b/synapse/util/metrics.py
@@ -72,6 +72,7 @@
     ),
 )
 
+# seconds spent waiting for db txns, excluding scheduling time, in this block
 block_db_txn_duration = metrics.register_counter(
     "block_db_txn_duration_seconds", labels=["block_name"],
     alternative_names=(
@@ -95,7 +96,7 @@ def measured_func(self, *args, **kwargs):
 class Measure(object):
     __slots__ = [
         "clock", "name", "start_context", "start", "new_context", "ru_utime",
-        "ru_stime", "db_txn_count", "db_txn_duration", "created_context"
+        "ru_stime", "db_txn_count", "db_txn_duration_ms", "created_context"
     ]
 
     def __init__(self, clock, name):
@@ -115,7 +116,7 @@ def __enter__(self):
 
         self.ru_utime, self.ru_stime = self.start_context.get_resource_usage()
         self.db_txn_count = self.start_context.db_txn_count
-        self.db_txn_duration = self.start_context.db_txn_duration
+        self.db_txn_duration_ms = self.start_context.db_txn_duration_ms
 
     def __exit__(self, exc_type, exc_val, exc_tb):
         if isinstance(exc_type, Exception) or not self.start_context:
@@ -145,7 +146,8 @@ def __exit__(self, exc_type, exc_val, exc_tb):
             context.db_txn_count - self.db_txn_count, self.name
         )
         block_db_txn_duration.inc_by(
-            context.db_txn_duration - self.db_txn_duration, self.name
+            (context.db_txn_duration_ms - self.db_txn_duration_ms) / 1000.,
+            self.name
         )
 
         if self.created_context: