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
|
