MirrorHub/synapse
0
0
Fork 1
mirror of https://mau.dev/maunium/synapse.git synced 2024-12-18 19:24:24 +01:00
Code Issues Projects Releases Wiki Activity

Merge pull request #3258 from matrix-org/erikj/fixup_logcontext_rusage

Browse source 
Fix logcontext resource usage tracking
This commit is contained in:
Erik Johnston 2018-05-22 11:39:56 +01:00 committed by GitHub
commit 7cfa8a87a1
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
1 changed files with 27 additions and 11 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

38
synapse/util/logcontext.py
View file

@ -60,7 +60,7 @@ class LoggingContext(object):
__slots__ = [ __slots__ = [
"previous_context", "name", "ru_stime", "ru_utime", "previous_context", "name", "ru_stime", "ru_utime",
"db_txn_count", "db_txn_duration_ms", "db_sched_duration_ms", "db_txn_count", "db_txn_duration_ms", "db_sched_duration_ms",
"usage_start", "usage_end", "usage_start",
"main_thread", "alive", "main_thread", "alive",
"request", "tag", "request", "tag",
] ]
@ -109,8 +109,10 @@ class LoggingContext(object):
# ms spent waiting for db txns to be scheduled # ms spent waiting for db txns to be scheduled
self.db_sched_duration_ms = 0 self.db_sched_duration_ms = 0
# If alive has the thread resource usage when the logcontext last
# became active.
self.usage_start = None self.usage_start = None
self.usage_end = None
self.main_thread = threading.current_thread() self.main_thread = threading.current_thread()
self.request = None self.request = None
self.tag = "" self.tag = ""
@ -159,7 +161,7 @@ class LoggingContext(object):
"""Restore the logging context in thread local storage to the state it """Restore the logging context in thread local storage to the state it
was before this context was entered. was before this context was entered.
Returns: Returns:
None to avoid suppressing any exeptions that were thrown. None to avoid suppressing any exceptions that were thrown.
""" """
current = self.set_current_context(self.previous_context) current = self.set_current_context(self.previous_context)
if current is not self: if current is not self:
@ -185,29 +187,43 @@ class LoggingContext(object):
def start(self): def start(self):
if threading.current_thread() is not self.main_thread: if threading.current_thread() is not self.main_thread:
logger.warning("Started logcontext %s on different thread", self)
return return
if self.usage_start and self.usage_end: # If we haven't already started record the thread resource usage so
self.ru_utime += self.usage_end.ru_utime - self.usage_start.ru_utime # far
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: if not self.usage_start:
self.usage_start = get_thread_resource_usage() self.usage_start = get_thread_resource_usage()
def stop(self): def stop(self):
if threading.current_thread() is not self.main_thread: if threading.current_thread() is not self.main_thread:
logger.warning("Stopped logcontext %s on different thread", self)
return return
# When we stop, let's record the resource used since we started
if self.usage_start: if self.usage_start:
self.usage_end = get_thread_resource_usage() usage_end = get_thread_resource_usage()
self.ru_utime += usage_end.ru_utime - self.usage_start.ru_utime
self.ru_stime += usage_end.ru_stime - self.usage_start.ru_stime
self.usage_start = None
else:
logger.warning("Called stop on logcontext %s without calling start", self)
def get_resource_usage(self): def get_resource_usage(self):
"""Get CPU time used by this logcontext so far.
Returns:
tuple[float, float]: The user and system CPU usage in seconds
"""
ru_utime = self.ru_utime ru_utime = self.ru_utime
ru_stime = self.ru_stime ru_stime = self.ru_stime
if self.usage_start and threading.current_thread() is self.main_thread: # If we are on the correct thread and we're currently running then we
# 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() current = get_thread_resource_usage()
ru_utime += current.ru_utime - self.usage_start.ru_utime ru_utime += current.ru_utime - self.usage_start.ru_utime
ru_stime += current.ru_stime - self.usage_start.ru_stime ru_stime += current.ru_stime - self.usage_start.ru_stime