From ce315cd8a799884d90b1b9489a3a9729f5456e4b Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Tue, 5 May 2020 10:45:15 -0400 Subject: [PATCH 1/3] Improve usage deltas reported to parents. --- synapse/logging/context.py | 18 +++++++++++++----- 1 file changed, 13 insertions(+), 5 deletions(-) diff --git a/synapse/logging/context.py b/synapse/logging/context.py index 856534e91a75..527e6a5cc418 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -245,6 +245,7 @@ class LoggingContext(object): "name", "parent_context", "_resource_usage", + "_prev_resource_usage", "usage_start", "main_thread", "finished", @@ -259,6 +260,7 @@ def __init__(self, name=None, parent_context=None, request=None) -> None: # track the resources used by this context so far self._resource_usage = ContextResourceUsage() + self._prev_resource_usage = None # type: Optional[ContextResourceUsage] # The thread resource usage when the logcontext became active. None # if the context is not currently active. @@ -434,12 +436,18 @@ def stop(self, rusage: "Optional[resource._RUsage]") -> None: self._resource_usage.ru_utime += utime_delta self._resource_usage.ru_stime += stime_delta - # if we have a parent, pass our CPU usage stats on + # if we have a parent, pass the change in our usage stats on. if self.parent_context: - self.parent_context._resource_usage += self._resource_usage - - # reset them in case we get entered again - self._resource_usage.reset() + if self._prev_resource_usage: + delta_resource_usage = ( + self._resource_usage - self._prev_resource_usage + ) + else: + delta_resource_usage = self._resource_usage + self.parent_context._resource_usage += delta_resource_usage + + # Store the current usage for future deltas. + self._prev_resource_usage = self._resource_usage.copy() finally: self.usage_start = None From 2b6c851160762dacba62135222e91f30fa886533 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Wed, 6 May 2020 11:22:37 -0400 Subject: [PATCH 2/3] Recursively pass metrics up contexts. --- synapse/logging/context.py | 46 +++++++++++++++++++++----------------- 1 file changed, 26 insertions(+), 20 deletions(-) diff --git a/synapse/logging/context.py b/synapse/logging/context.py index 527e6a5cc418..8b9c4e38bd9f 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -245,7 +245,6 @@ class LoggingContext(object): "name", "parent_context", "_resource_usage", - "_prev_resource_usage", "usage_start", "main_thread", "finished", @@ -260,7 +259,6 @@ def __init__(self, name=None, parent_context=None, request=None) -> None: # track the resources used by this context so far self._resource_usage = ContextResourceUsage() - self._prev_resource_usage = None # type: Optional[ContextResourceUsage] # The thread resource usage when the logcontext became active. None # if the context is not currently active. @@ -433,21 +431,7 @@ def stop(self, rusage: "Optional[resource._RUsage]") -> None: return utime_delta, stime_delta = self._get_cputime(rusage) - self._resource_usage.ru_utime += utime_delta - self._resource_usage.ru_stime += stime_delta - - # if we have a parent, pass the change in our usage stats on. - if self.parent_context: - if self._prev_resource_usage: - delta_resource_usage = ( - self._resource_usage - self._prev_resource_usage - ) - else: - delta_resource_usage = self._resource_usage - self.parent_context._resource_usage += delta_resource_usage - - # Store the current usage for future deltas. - self._prev_resource_usage = self._resource_usage.copy() + self.add_cputime(utime_delta, stime_delta) finally: self.usage_start = None @@ -505,30 +489,52 @@ def _get_cputime(self, current: "resource._RUsage") -> Tuple[float, float]: return utime_delta, stime_delta + def add_cputime(self, utime_delta: float, stime_delta: float) -> None: + """Update the CPU time usage of this context (and any parents, recursively). + + Args: + utime_delta: additional user time, in seconds, spent in this context. + stime_delta: additional system time, in seconds, spent in this context. + """ + self._resource_usage.ru_utime += utime_delta + self._resource_usage.ru_stime += stime_delta + if self.parent_context: + self.parent_context.add_cputime(utime_delta, stime_delta) + def add_database_transaction(self, duration_sec: float) -> None: + """Record the use of a database transaction and the length of time it took. + + Args: + duration_sec: The number of seconds the database transaction took. + """ if duration_sec < 0: raise ValueError("DB txn time can only be non-negative") self._resource_usage.db_txn_count += 1 self._resource_usage.db_txn_duration_sec += duration_sec + if self.parent_context: + self.parent_context.add_database_transaction(duration_sec) def add_database_scheduled(self, sched_sec: float) -> None: """Record a use of the database pool Args: - sched_sec (float): number of seconds it took us to get a - connection + sched_sec: number of seconds it took us to get a connection """ if sched_sec < 0: raise ValueError("DB scheduling time can only be non-negative") self._resource_usage.db_sched_duration_sec += sched_sec + if self.parent_context: + self.parent_context.add_database_scheduled(sched_sec) def record_event_fetch(self, event_count: int) -> None: """Record a number of events being fetched from the db Args: - event_count (int): number of events being fetched + event_count: number of events being fetched """ self._resource_usage.evt_db_fetch_count += event_count + if self.parent_context: + self.parent_context.record_event_fetch(event_count) class LoggingContextFilter(logging.Filter): From 8b3f635c372455c5a9ecfdf2c63c0864db0ae259 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Wed, 6 May 2020 11:46:10 -0400 Subject: [PATCH 3/3] Add newsfragment. --- changelog.d/7426.misc | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/7426.misc diff --git a/changelog.d/7426.misc b/changelog.d/7426.misc new file mode 100644 index 000000000000..731f4dcb52e4 --- /dev/null +++ b/changelog.d/7426.misc @@ -0,0 +1 @@ +Clean up some LoggingContext code.