diff --git a/synapse/app/homeserver.py b/synapse/app/homeserver.py
index f20ccfb5b6..8976ff2e82 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__)
@@ -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/http/server.py b/synapse/http/server.py
index 0f6539e1be..6d084fa33c 100644
--- a/synapse/http/server.py
+++ b/synapse/http/server.py
@@ -69,9 +69,10 @@ class JsonResource(HttpServer, resource.Resource):
_PathEntry = collections.namedtuple("_PathEntry", ["pattern", "callback"])
- def __init__(self):
+ def __init__(self, hs):
resource.Resource.__init__(self)
+ self.clock = hs.get_clock()
self.path_regexs = {}
def register_path(self, method, path_pattern, callback):
@@ -111,6 +112,7 @@ class JsonResource(HttpServer, resource.Resource):
This checks if anyone has registered a callback for that method and
path.
"""
+ code = None
try:
# Just say yes to OPTIONS.
if request.method == "OPTIONS":
@@ -130,6 +132,13 @@ class JsonResource(HttpServer, resource.Resource):
urllib.unquote(u).decode("UTF-8") for u in m.groups()
]
+ logger.info(
+ "Received request: %s %s",
+ request.method, request.path
+ )
+
+ start = self.clock.time_msec()
+
code, response = yield path_entry.callback(
request,
*args
@@ -145,9 +154,11 @@ class JsonResource(HttpServer, resource.Resource):
logger.info("%s SynapseError: %s - %s", request, e.code, e.msg)
else:
logger.exception(e)
+
+ code = e.code
self._send_response(
request,
- e.code,
+ code,
cs_exception(e),
response_code_message=e.response_code_message
)
@@ -158,6 +169,14 @@ class JsonResource(HttpServer, resource.Resource):
500,
{"error": "Internal server error"}
)
+ finally:
+ code = str(code) if code else "-"
+
+ end = self.clock.time_msec()
+ logger.info(
+ "Processed request: %dms %s %s %s",
+ end-start, code, request.method, request.path
+ )
def _send_response(self, request, code, response_json_object,
response_code_message=None):
diff --git a/synapse/rest/client/v1/__init__.py b/synapse/rest/client/v1/__init__.py
index d8d01cdd16..21876b3487 100644
--- a/synapse/rest/client/v1/__init__.py
+++ b/synapse/rest/client/v1/__init__.py
@@ -25,7 +25,7 @@ class ClientV1RestResource(JsonResource):
"""A resource for version 1 of the matrix client API."""
def __init__(self, hs):
- JsonResource.__init__(self)
+ JsonResource.__init__(self, hs)
self.register_servlets(self, hs)
@staticmethod
diff --git a/synapse/rest/client/v2_alpha/__init__.py b/synapse/rest/client/v2_alpha/__init__.py
index 8f611de3a8..bca65f2a6a 100644
--- a/synapse/rest/client/v2_alpha/__init__.py
+++ b/synapse/rest/client/v2_alpha/__init__.py
@@ -25,7 +25,7 @@ class ClientV2AlphaRestResource(JsonResource):
"""A resource for version 2 alpha of the matrix client API."""
def __init__(self, hs):
- JsonResource.__init__(self)
+ JsonResource.__init__(self, hs)
self.register_servlets(self, hs)
@staticmethod
diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py
index b350fd61f1..310ee0104c 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 * 100)
+
+ self._clock.looping_call(loop, 10000)
+
@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
diff --git a/synapse/util/__init__.py b/synapse/util/__init__.py
index 4e837a918e..fee76b0a9b 100644
--- a/synapse/util/__init__.py
+++ b/synapse/util/__init__.py
@@ -15,7 +15,7 @@
from synapse.util.logcontext import LoggingContext
-from twisted.internet import reactor
+from twisted.internet import reactor, task
import time
@@ -35,6 +35,14 @@ class Clock(object):
"""Returns the current system time in miliseconds since epoch."""
return self.time() * 1000
+ def looping_call(self, f, msec):
+ l = task.LoopingCall(f)
+ l.start(msec/1000.0, now=False)
+ return l
+
+ def stop_looping_call(self, loop):
+ loop.stop()
+
def call_later(self, delay, callback):
current_context = LoggingContext.current_context()
|
