From 48a2526d629fc33207cf864de36f3cff706a1c4c Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Thu, 3 Dec 2015 21:03:01 +0000 Subject: [PATCH 1/3] Track the cpu used in the main thread by each logging context --- synapse/util/__init__.py | 3 +- synapse/util/debug.py | 3 +- synapse/util/logcontext.py | 76 +++++++++++++++++++++++++++++++++++--- 3 files changed, 72 insertions(+), 10 deletions(-) diff --git a/synapse/util/__init__.py b/synapse/util/__init__.py index d69c7cb991..2170746025 100644 --- a/synapse/util/__init__.py +++ b/synapse/util/__init__.py @@ -64,8 +64,7 @@ class Clock(object): current_context = LoggingContext.current_context() def wrapped_callback(*args, **kwargs): - with PreserveLoggingContext(): - LoggingContext.thread_local.current_context = current_context + with PreserveLoggingContext(current_context): callback(*args, **kwargs) with PreserveLoggingContext(): diff --git a/synapse/util/debug.py b/synapse/util/debug.py index f6a5a841a4..b2bee7958f 100644 --- a/synapse/util/debug.py +++ b/synapse/util/debug.py @@ -30,8 +30,7 @@ def debug_deferreds(): context = LoggingContext.current_context() def restore_context_callback(x): - with PreserveLoggingContext(): - LoggingContext.thread_local.current_context = context + with PreserveLoggingContext(context): return fn(x) return restore_context_callback 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 From d6059bdd2ade632b3778d1f475a35ffd4a7242e9 Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Fri, 4 Dec 2015 11:34:05 +0000 Subject: [PATCH 2/3] Fix warnings --- synapse/app/homeserver.py | 12 +++++++++++- synapse/util/logcontext.py | 4 ++-- 2 files changed, 13 insertions(+), 3 deletions(-) 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 From 5231737369c6c5488cdfdcb76af8008fc8a2db07 Mon Sep 17 00:00:00 2001 From: Mark Haines Date: Fri, 4 Dec 2015 11:53:38 +0000 Subject: [PATCH 3/3] Add comments to explain why we are hardcoding RUSAGE_THREAD --- synapse/util/logcontext.py | 8 ++++++++ 1 file changed, 8 insertions(+) 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