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
|
