From 48a2526d629fc33207cf864de36f3cff706a1c4c Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Thu, 3 Dec 2015 21:03:01 +0000 Subject: Track the cpu used in the main thread by each logging context --- synapse/util/logcontext.py | 76 ++++++++++++++++++++++++++++++++++++++++++---- 1 file changed, 70 insertions(+), 6 deletions(-) (limited to 'synapse/util/logcontext.py') diff --git a/synapse/util/logcontext.py b/synapse/util/logcontext.py index 7e6062c1b8..6d7a6c3e2b 100644 --- a/synapse/util/logcontext.py +++ b/synapse/util/logcontext.py @@ -19,6 +19,16 @@ import logging logger = logging.getLogger(__name__) +try: + import resource + RUSAGE_THREAD = 1 + resource.getrusage(RUSAGE_THREAD) + def get_thread_resource_usage(): + return resource.getrusage(RUSAGE_THREAD) +except: + def get_thread_resource_usage(): + return None + class LoggingContext(object): """Additional context for log formatting. Contexts are scoped within a @@ -27,7 +37,9 @@ class LoggingContext(object): name (str): Name for the context for debugging. """ - __slots__ = ["parent_context", "name", "__dict__"] + __slots__ = [ + "parent_context", "name", "usage_start", "usage_end", "main_thread", "__dict__" + ] thread_local = threading.local() @@ -42,11 +54,21 @@ class LoggingContext(object): def copy_to(self, record): pass + def start(self): + pass + + def stop(self): + pass + sentinel = Sentinel() def __init__(self, name=None): self.parent_context = None self.name = name + self.ru_stime = 0. + self.ru_utime = 0. + self.usage_start = None + self.main_thread = threading.current_thread() def __str__(self): return "%s@%x" % (self.name, id(self)) @@ -62,6 +84,7 @@ class LoggingContext(object): raise Exception("Attempt to enter logging context multiple times") self.parent_context = self.current_context() self.thread_local.current_context = self + self.start() return self def __exit__(self, type, value, traceback): @@ -80,6 +103,7 @@ class LoggingContext(object): self ) self.thread_local.current_context = self.parent_context + self.stop() self.parent_context = None def __getattr__(self, name): @@ -93,6 +117,40 @@ class LoggingContext(object): for key, value in self.__dict__.items(): setattr(record, key, value) + record.ru_utime, record.ru_stime = self.get_resource_usage() + + def start(self): + if threading.current_thread() is not self.main_thread: + return + + if self.usage_start and self.usage_end: + self.ru_utime += self.usage_end.ru_utime - self.usage_start.ru_utime + self.ru_stime += self.usage_end.ru_stime - self.usage_start.ru_stime + self.usage_start = None + self.usage_end = None + + if not self.usage_start: + self.usage_start = get_thread_resource_usage() + + def stop(self): + if threading.current_thread() is not self.main_thread: + return + + if self.usage_start: + self.usage_end = get_thread_resource_usage() + + def get_resource_usage(self): + ru_utime = self.ru_utime + ru_stime = self.ru_stime + + start = self.usage_start + if self.usage_start and threading.current_thread() is self.main_thread: + current = get_thread_resource_usage() + ru_utime += current.ru_utime - self.usage_start.ru_utime + ru_stime += current.ru_stime - self.usage_start.ru_stime + + return ru_utime, ru_stime + class LoggingContextFilter(logging.Filter): """Logging filter that adds values from the current logging context to each @@ -121,17 +179,24 @@ class PreserveLoggingContext(object): exited. Used to restore the context after a function using @defer.inlineCallbacks is resumed by a callback from the reactor.""" - __slots__ = ["current_context"] + __slots__ = ["current_context", "new_context"] + + def __init__(self, new_context=LoggingContext.sentinel): + self.new_context = new_context def __enter__(self): """Captures the current logging context""" self.current_context = LoggingContext.current_context() - LoggingContext.thread_local.current_context = LoggingContext.sentinel + if self.new_context is not self.current_context: + self.current_context.stop() + LoggingContext.thread_local.current_context = self.new_context def __exit__(self, type, value, traceback): """Restores the current logging context""" + context = LoggingContext.thread_local.current_context LoggingContext.thread_local.current_context = self.current_context - + if context is not self.current_context: + self.current_context.start() if self.current_context is not LoggingContext.sentinel: if self.current_context.parent_context is None: logger.warn( @@ -164,8 +229,7 @@ class _PreservingContextDeferred(defer.Deferred): def _wrap_callback(self, f): def g(res, *args, **kwargs): - with PreserveLoggingContext(): - LoggingContext.thread_local.current_context = self._log_context + with PreserveLoggingContext(self._log_context): res = f(res, *args, **kwargs) return res return g -- cgit 1.5.1 From d6059bdd2ade632b3778d1f475a35ffd4a7242e9 Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Fri, 4 Dec 2015 11:34:05 +0000 Subject: Fix warnings --- synapse/app/homeserver.py | 12 +++++++++++- synapse/util/logcontext.py | 4 ++-- 2 files changed, 13 insertions(+), 3 deletions(-) (limited to 'synapse/util/logcontext.py') diff --git a/synapse/app/homeserver.py b/synapse/app/homeserver.py index cd7a52ec07..58c679bbfd 100755 --- a/synapse/app/homeserver.py +++ b/synapse/app/homeserver.py @@ -499,13 +499,23 @@ class SynapseRequest(Request): self.start_time = int(time.time() * 1000) def finished_processing(self): + + try: + context = LoggingContext.current_context() + ru_utime, ru_stime = context.get_resource_usage() + except: + ru_utime, ru_stime = (0, 0) + self.site.access_logger.info( "%s - %s - {%s}" - " Processed request: %dms %sB %s \"%s %s %s\" \"%s\"", + " Processed request: %dms (%dms, %dms)" + " %sB %s \"%s %s %s\" \"%s\"", self.getClientIP(), self.site.site_tag, self.authenticated_entity, int(time.time() * 1000) - self.start_time, + int(ru_utime * 1000), + int(ru_stime * 1000), self.sentLength, self.code, self.method, diff --git a/synapse/util/logcontext.py b/synapse/util/logcontext.py index 6d7a6c3e2b..2633201528 100644 --- a/synapse/util/logcontext.py +++ b/synapse/util/logcontext.py @@ -23,6 +23,7 @@ try: import resource RUSAGE_THREAD = 1 resource.getrusage(RUSAGE_THREAD) + def get_thread_resource_usage(): return resource.getrusage(RUSAGE_THREAD) except: @@ -137,13 +138,12 @@ class LoggingContext(object): return if self.usage_start: - self.usage_end = get_thread_resource_usage() + self.usage_end = get_thread_resource_usage() def get_resource_usage(self): ru_utime = self.ru_utime ru_stime = self.ru_stime - start = self.usage_start if self.usage_start and threading.current_thread() is self.main_thread: current = get_thread_resource_usage() ru_utime += current.ru_utime - self.usage_start.ru_utime -- cgit 1.5.1 From 5231737369c6c5488cdfdcb76af8008fc8a2db07 Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Fri, 4 Dec 2015 11:53:38 +0000 Subject: Add comments to explain why we are hardcoding RUSAGE_THREAD --- synapse/util/logcontext.py | 8 ++++++++ 1 file changed, 8 insertions(+) (limited to 'synapse/util/logcontext.py') diff --git a/synapse/util/logcontext.py b/synapse/util/logcontext.py index 2633201528..e4ce087afe 100644 --- a/synapse/util/logcontext.py +++ b/synapse/util/logcontext.py @@ -21,12 +21,20 @@ logger = logging.getLogger(__name__) try: import resource + + # Python doesn't ship with a definition of RUSAGE_THREAD but it's defined + # to be 1 on linux so we hard code it. RUSAGE_THREAD = 1 + + # If the system doesn't support RUSAGE_THREAD then this should throw an + # exception. resource.getrusage(RUSAGE_THREAD) def get_thread_resource_usage(): return resource.getrusage(RUSAGE_THREAD) except: + # If the system doesn't support resource.getrusage(RUSAGE_THREAD) then we + # won't track resource usage by returning None. def get_thread_resource_usage(): return None -- cgit 1.5.1 From 3dd16308487d4b5f76d8b3f3e0bf5ce2a72aff22 Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Mon, 7 Dec 2015 10:51:18 +0000 Subject: Add a setter for the current log context. Move the resource tracking inside that setter so that it is easier to make sure that the resource tracking isn't double counting the resource usage. --- synapse/util/logcontext.py | 40 ++++++++++++++++++++++++---------------- 1 file changed, 24 insertions(+), 16 deletions(-) (limited to 'synapse/util/logcontext.py') diff --git a/synapse/util/logcontext.py b/synapse/util/logcontext.py index e4ce087afe..c20c89aa8f 100644 --- a/synapse/util/logcontext.py +++ b/synapse/util/logcontext.py @@ -87,13 +87,26 @@ class LoggingContext(object): """Get the current logging context from thread local storage""" return getattr(cls.thread_local, "current_context", cls.sentinel) + @classmethod + def set_current_context(cls, context): + """Set the current logging context in thread local storage + Args: + context(LoggingContext): The context to activate. + Returns: + The context that was previously active + """ + current = cls.current_context() + if current is not context: + current.stop() + cls.thread_local.current_context = context + context.start() + return current + def __enter__(self): """Enters this logging context into thread local storage""" if self.parent_context is not None: raise Exception("Attempt to enter logging context multiple times") - self.parent_context = self.current_context() - self.thread_local.current_context = self - self.start() + self.parent_context = self.set_current_context(self) return self def __exit__(self, type, value, traceback): @@ -102,17 +115,16 @@ class LoggingContext(object): Returns: None to avoid suppressing any exeptions that were thrown. """ - if self.thread_local.current_context is not self: - if self.thread_local.current_context is self.sentinel: + current = self.set_current_context(self.parent_context) + if current is not self: + if current is self.sentinel: logger.debug("Expected logging context %s has been lost", self) else: logger.warn( "Current logging context %s is not expected context %s", - self.thread_local.current_context, + current, self ) - self.thread_local.current_context = self.parent_context - self.stop() self.parent_context = None def __getattr__(self, name): @@ -194,17 +206,13 @@ class PreserveLoggingContext(object): def __enter__(self): """Captures the current logging context""" - self.current_context = LoggingContext.current_context() - if self.new_context is not self.current_context: - self.current_context.stop() - LoggingContext.thread_local.current_context = self.new_context + self.current_context = LoggingContext.set_current_context( + self.new_context + ) def __exit__(self, type, value, traceback): """Restores the current logging context""" - context = LoggingContext.thread_local.current_context - LoggingContext.thread_local.current_context = self.current_context - if context is not self.current_context: - self.current_context.start() + LoggingContext.set_current_context(self.current_context) if self.current_context is not LoggingContext.sentinel: if self.current_context.parent_context is None: logger.warn( -- cgit 1.5.1 From 6a5ff5f223c1b4311aa63574663c0335d0c6bd79 Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Mon, 7 Dec 2015 17:56:11 +0000 Subject: Track the time spent in the database per request. and track the number of transactions that request started. --- synapse/app/homeserver.py | 7 ++++++- synapse/http/server.py | 15 +++++++++++++++ synapse/storage/_base.py | 9 +++++++-- synapse/storage/events.py | 2 +- synapse/util/logcontext.py | 9 +++++++++ 5 files changed, 38 insertions(+), 4 deletions(-) (limited to 'synapse/util/logcontext.py') 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 -- cgit 1.5.1