From 24cc6979fb384ef383309b27d06985ba3a845b2b Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Mon, 9 Feb 2015 13:46:22 +0000 Subject: [PATCH 1/5] Log when we receive a request, when we send a response and how long it took to process it. --- synapse/app/homeserver.py | 2 +- synapse/http/server.py | 23 +++++++++++++++++++++-- synapse/rest/client/v1/__init__.py | 2 +- synapse/rest/client/v2_alpha/__init__.py | 2 +- 4 files changed, 24 insertions(+), 5 deletions(-) diff --git a/synapse/app/homeserver.py b/synapse/app/homeserver.py index f20ccfb5b..0f175ec3f 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__) diff --git a/synapse/http/server.py b/synapse/http/server.py index 0f6539e1b..6d084fa33 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 d8d01cdd1..21876b348 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 8f611de3a..bca65f2a6 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 From 75656712e34694460ce7b12fc5a467667e04ea21 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Mon, 9 Feb 2015 14:22:52 +0000 Subject: [PATCH 2/5] 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(+) diff --git a/synapse/app/homeserver.py b/synapse/app/homeserver.py index 0f175ec3f..8976ff2e8 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 b350fd61f..0849c5f1b 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 From 66fde49f071d75ea8bfdfac02fd4fa6fab5a9bf4 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Mon, 9 Feb 2015 14:45:15 +0000 Subject: [PATCH 3/5] Log database time every 10s and log as percentage --- synapse/storage/_base.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py index 0849c5f1b..f1df5d39f 100644 --- a/synapse/storage/_base.py +++ b/synapse/storage/_base.py @@ -103,9 +103,9 @@ class SQLBaseStore(object): ratio = (curr - prev)/(time_now - time_then) - logger.info("Total database time: %.3f", ratio) + logger.info("Total database time: %.3f%", ratio * 100) - self._clock.looping_call(loop, 1000) + self._clock.looping_call(loop, 10000) @defer.inlineCallbacks def runInteraction(self, desc, func, *args, **kwargs): From ef995e69460a117e78a72bcef285f9a0c7438487 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Mon, 9 Feb 2015 14:47:59 +0000 Subject: [PATCH 4/5] Add looping_call to Clock --- synapse/util/__init__.py | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/synapse/util/__init__.py b/synapse/util/__init__.py index 4e837a918..fee76b0a9 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() From c4ee4ce93ec6075bc076b12520fd72769079f37c Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Mon, 9 Feb 2015 15:00:37 +0000 Subject: [PATCH 5/5] Fix typo --- synapse/storage/_base.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py index f1df5d39f..310ee0104 100644 --- a/synapse/storage/_base.py +++ b/synapse/storage/_base.py @@ -103,7 +103,7 @@ class SQLBaseStore(object): ratio = (curr - prev)/(time_now - time_then) - logger.info("Total database time: %.3f%", ratio * 100) + logger.info("Total database time: %.3f%%", ratio * 100) self._clock.looping_call(loop, 10000)