diff options
author | Richard van der Hoff <1389908+richvdh@users.noreply.github.com> | 2019-06-24 17:12:54 +0100 |
---|---|---|
committer | GitHub <noreply@github.com> | 2019-06-24 17:12:54 +0100 |
commit | e59a8cd2e54e5e91dac4e1747849a683757dbc0d (patch) | |
tree | bc916952d19771c175c3b8d43e49316310172056 /synapse/util | |
parent | Merge pull request #5534 from matrix-org/babolivier/federation-publicrooms (diff) | |
parent | black (diff) | |
download | synapse-e59a8cd2e54e5e91dac4e1747849a683757dbc0d.tar.xz |
Merge pull request #5499 from matrix-org/rav/cleanup_metrics
Cleanups and sanity-checking in cpu and db metrics
Diffstat (limited to 'synapse/util')
-rw-r--r-- | synapse/util/logcontext.py | 46 |
1 files changed, 39 insertions, 7 deletions
diff --git a/synapse/util/logcontext.py b/synapse/util/logcontext.py index a9885cb507..6b0d2deea0 100644 --- a/synapse/util/logcontext.py +++ b/synapse/util/logcontext.py @@ -336,10 +336,9 @@ class LoggingContext(object): logger.warning("Called stop on logcontext %s without calling start", self) return - usage_end = get_thread_resource_usage() - - self._resource_usage.ru_utime += usage_end.ru_utime - self.usage_start.ru_utime - self._resource_usage.ru_stime += usage_end.ru_stime - self.usage_start.ru_stime + utime_delta, stime_delta = self._get_cputime() + self._resource_usage.ru_utime += utime_delta + self._resource_usage.ru_stime += stime_delta self.usage_start = None @@ -357,13 +356,44 @@ class LoggingContext(object): # can include resource usage so far. is_main_thread = threading.current_thread() is self.main_thread if self.alive and self.usage_start and is_main_thread: - current = get_thread_resource_usage() - res.ru_utime += current.ru_utime - self.usage_start.ru_utime - res.ru_stime += current.ru_stime - self.usage_start.ru_stime + utime_delta, stime_delta = self._get_cputime() + res.ru_utime += utime_delta + res.ru_stime += stime_delta return res + def _get_cputime(self): + """Get the cpu usage time so far + + Returns: Tuple[float, float]: seconds in user mode, seconds in system mode + """ + current = get_thread_resource_usage() + + utime_delta = current.ru_utime - self.usage_start.ru_utime + stime_delta = current.ru_stime - self.usage_start.ru_stime + + # sanity check + if utime_delta < 0: + logger.error( + "utime went backwards! %f < %f", + current.ru_utime, + self.usage_start.ru_utime, + ) + utime_delta = 0 + + if stime_delta < 0: + logger.error( + "stime went backwards! %f < %f", + current.ru_stime, + self.usage_start.ru_stime, + ) + stime_delta = 0 + + return utime_delta, stime_delta + def add_database_transaction(self, duration_sec): + 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 @@ -374,6 +404,8 @@ class LoggingContext(object): sched_sec (float): 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 def record_event_fetch(self, event_count): |