From 24cc6979fb384ef383309b27d06985ba3a845b2b Mon Sep 17 00:00:00 2001
From: Erik Johnston <erik@matrix.org>
Date: Mon, 9 Feb 2015 13:46:22 +0000
Subject: Log when we receive a request, when we send a response and how long
 it took to process it.

---
 synapse/app/homeserver.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

(limited to 'synapse/app/homeserver.py')

diff --git a/synapse/app/homeserver.py b/synapse/app/homeserver.py
index f20ccfb5b6..0f175ec3f4 100755
--- a/synapse/app/homeserver.py
+++ b/synapse/app/homeserver.py
@@ -67,7 +67,7 @@ class SynapseHomeServer(HomeServer):
         return ClientV2AlphaRestResource(self)
 
     def build_resource_for_federation(self):
-        return JsonResource()
+        return JsonResource(self)
 
     def build_resource_for_web_client(self):
         syweb_path = os.path.dirname(syweb.__file__)
-- 
cgit 1.4.1


From 75656712e34694460ce7b12fc5a467667e04ea21 Mon Sep 17 00:00:00 2001
From: Erik Johnston <erik@matrix.org>
Date: Mon, 9 Feb 2015 14:22:52 +0000
Subject: Time how long we're spending on the database thread

---
 synapse/app/homeserver.py |  2 ++
 synapse/storage/_base.py  | 25 +++++++++++++++++++++++++
 2 files changed, 27 insertions(+)

(limited to 'synapse/app/homeserver.py')

diff --git a/synapse/app/homeserver.py b/synapse/app/homeserver.py
index 0f175ec3f4..8976ff2e82 100755
--- a/synapse/app/homeserver.py
+++ b/synapse/app/homeserver.py
@@ -274,6 +274,8 @@ def setup():
 
     hs.get_pusherpool().start()
 
+    hs.get_datastore().start_profiling()
+
     if config.daemonize:
         print config.pid_file
         daemon = Daemonize(
diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py
index b350fd61f1..0849c5f1b4 100644
--- a/synapse/storage/_base.py
+++ b/synapse/storage/_base.py
@@ -85,6 +85,28 @@ class SQLBaseStore(object):
         self._db_pool = hs.get_db_pool()
         self._clock = hs.get_clock()
 
+        self._previous_txn_total_time = 0
+        self._current_txn_total_time = 0
+        self._previous_loop_ts = 0
+
+    def start_profiling(self):
+        self._previous_loop_ts = self._clock.time_msec()
+
+        def loop():
+            curr = self._current_txn_total_time
+            prev = self._previous_txn_total_time
+            self._previous_txn_total_time = curr
+
+            time_now = self._clock.time_msec()
+            time_then = self._previous_loop_ts
+            self._previous_loop_ts = time_now
+
+            ratio = (curr - prev)/(time_now - time_then)
+
+            logger.info("Total database time: %.3f", ratio)
+
+        self._clock.looping_call(loop, 1000)
+
     @defer.inlineCallbacks
     def runInteraction(self, desc, func, *args, **kwargs):
         """Wraps the .runInteraction() method on the underlying db_pool."""
@@ -114,6 +136,9 @@ class SQLBaseStore(object):
                         "[TXN END] {%s} %f",
                         name, end - start
                     )
+
+                    self._current_txn_total_time += end - start
+
         with PreserveLoggingContext():
             result = yield self._db_pool.runInteraction(
                 inner_func, *args, **kwargs
-- 
cgit 1.4.1