diff --git a/synapse/http/request_metrics.py b/synapse/http/request_metrics.py
index af3067b4bb..dc06f6c443 100644
--- a/synapse/http/request_metrics.py
+++ b/synapse/http/request_metrics.py
@@ -139,8 +139,8 @@ LaterGauge(
class RequestMetrics(object):
- def start(self, time_msec, name, method):
- self.start = time_msec
+ def start(self, time_sec, name, method):
+ self.start = time_sec
self.start_context = LoggingContext.current_context()
self.name = name
self.method = method
@@ -149,7 +149,7 @@ class RequestMetrics(object):
_in_flight_requests.add(self)
- def stop(self, time_msec, request):
+ def stop(self, time_sec, request):
_in_flight_requests.discard(self)
context = LoggingContext.current_context()
@@ -170,7 +170,7 @@ class RequestMetrics(object):
response_count.labels(request.method, self.name, tag).inc()
response_timer.labels(request.method, self.name, tag).observe(
- time_msec - self.start
+ time_sec - self.start
)
ru_utime, ru_stime = context.get_resource_usage()
@@ -181,10 +181,10 @@ class RequestMetrics(object):
context.db_txn_count
)
response_db_txn_duration.labels(request.method, self.name, tag).inc(
- context.db_txn_duration_ms / 1000.
+ context.db_txn_duration_sec
)
response_db_sched_duration.labels(request.method, self.name, tag).inc(
- context.db_sched_duration_ms / 1000.
+ context.db_sched_duration_sec
)
response_size.labels(request.method, self.name, tag).inc(request.sentLength)
@@ -207,11 +207,11 @@ class RequestMetrics(object):
)
in_flight_requests_db_txn_duration.labels(self.method, self.name).inc(
- diff.db_txn_duration_ms / 1000.
+ diff.db_txn_duration_sec
)
in_flight_requests_db_sched_duration.labels(self.method, self.name).inc(
- diff.db_sched_duration_ms / 1000.
+ diff.db_sched_duration_sec
)
@@ -223,18 +223,18 @@ class _RequestStats(object):
"ru_utime",
"ru_stime",
"db_txn_count",
- "db_txn_duration_ms",
- "db_sched_duration_ms",
+ "db_txn_duration_sec",
+ "db_sched_duration_sec",
]
def __init__(
- self, ru_utime, ru_stime, db_txn_count, db_txn_duration_ms, db_sched_duration_ms
+ self, ru_utime, ru_stime, db_txn_count, db_txn_duration_sec, db_sched_duration_sec
):
self.ru_utime = ru_utime
self.ru_stime = ru_stime
self.db_txn_count = db_txn_count
- self.db_txn_duration_ms = db_txn_duration_ms
- self.db_sched_duration_ms = db_sched_duration_ms
+ self.db_txn_duration_sec = db_txn_duration_sec
+ self.db_sched_duration_sec = db_sched_duration_sec
@staticmethod
def from_context(context):
@@ -243,8 +243,8 @@ class _RequestStats(object):
return _RequestStats(
ru_utime, ru_stime,
context.db_txn_count,
- context.db_txn_duration_ms,
- context.db_sched_duration_ms,
+ context.db_txn_duration_sec,
+ context.db_sched_duration_sec,
)
def update(self, context):
@@ -260,14 +260,14 @@ class _RequestStats(object):
new.ru_utime - self.ru_utime,
new.ru_stime - self.ru_stime,
new.db_txn_count - self.db_txn_count,
- new.db_txn_duration_ms - self.db_txn_duration_ms,
- new.db_sched_duration_ms - self.db_sched_duration_ms,
+ new.db_txn_duration_sec - self.db_txn_duration_sec,
+ new.db_sched_duration_sec - self.db_sched_duration_sec,
)
self.ru_utime = new.ru_utime
self.ru_stime = new.ru_stime
self.db_txn_count = new.db_txn_count
- self.db_txn_duration_ms = new.db_txn_duration_ms
- self.db_sched_duration_ms = new.db_sched_duration_ms
+ self.db_txn_duration_sec = new.db_txn_duration_sec
+ self.db_sched_duration_sec = new.db_sched_duration_sec
return diff
diff --git a/synapse/util/logcontext.py b/synapse/util/logcontext.py
index 914f616312..a58c723403 100644
--- a/synapse/util/logcontext.py
+++ b/synapse/util/logcontext.py
@@ -59,7 +59,7 @@ class LoggingContext(object):
__slots__ = [
"previous_context", "name", "ru_stime", "ru_utime",
- "db_txn_count", "db_txn_duration_ms", "db_sched_duration_ms",
+ "db_txn_count", "db_txn_duration_sec", "db_sched_duration_sec",
"usage_start",
"main_thread", "alive",
"request", "tag",
@@ -84,10 +84,10 @@ class LoggingContext(object):
def stop(self):
pass
- def add_database_transaction(self, duration_ms):
+ def add_database_transaction(self, duration_sec):
pass
- def add_database_scheduled(self, sched_ms):
+ def add_database_scheduled(self, sched_sec):
pass
def __nonzero__(self):
@@ -103,11 +103,11 @@ class LoggingContext(object):
self.ru_utime = 0.
self.db_txn_count = 0
- # ms spent waiting for db txns, excluding scheduling time
- self.db_txn_duration_ms = 0
+ # sec spent waiting for db txns, excluding scheduling time
+ self.db_txn_duration_sec = 0
- # ms spent waiting for db txns to be scheduled
- self.db_sched_duration_ms = 0
+ # sec spent waiting for db txns to be scheduled
+ self.db_sched_duration_sec = 0
# If alive has the thread resource usage when the logcontext last
# became active.
@@ -230,18 +230,18 @@ class LoggingContext(object):
return ru_utime, ru_stime
- def add_database_transaction(self, duration_ms):
+ def add_database_transaction(self, duration_sec):
self.db_txn_count += 1
- self.db_txn_duration_ms += duration_ms
+ self.db_txn_duration_sec += duration_sec
- def add_database_scheduled(self, sched_ms):
+ def add_database_scheduled(self, sched_sec):
"""Record a use of the database pool
Args:
- sched_ms (int): number of milliseconds it took us to get a
+ sched_sec (float): number of seconds it took us to get a
connection
"""
- self.db_sched_duration_ms += sched_ms
+ self.db_sched_duration_sec += sched_sec
class LoggingContextFilter(logging.Filter):
diff --git a/synapse/util/logutils.py b/synapse/util/logutils.py
index 3a83828d25..03249c5dc8 100644
--- a/synapse/util/logutils.py
+++ b/synapse/util/logutils.py
@@ -96,7 +96,7 @@ def time_function(f):
id = _TIME_FUNC_ID
_TIME_FUNC_ID += 1
- start = time.clock() * 1000
+ start = time.clock()
try:
_log_debug_as_f(
@@ -107,10 +107,10 @@ def time_function(f):
r = f(*args, **kwargs)
finally:
- end = time.clock() * 1000
+ end = time.clock()
_log_debug_as_f(
f,
- "[FUNC END] {%s-%d} %f",
+ "[FUNC END] {%s-%d} %.3f sec",
(func_name, id, end - start,),
)
diff --git a/synapse/util/metrics.py b/synapse/util/metrics.py
index 424fdcb036..23fc0ca20d 100644
--- a/synapse/util/metrics.py
+++ b/synapse/util/metrics.py
@@ -74,7 +74,7 @@ class Measure(object):
self.created_context = False
def __enter__(self):
- self.start = self.clock.time_msec()
+ self.start = self.clock.time()
self.start_context = LoggingContext.current_context()
if not self.start_context:
self.start_context = LoggingContext("Measure")
@@ -90,7 +90,7 @@ class Measure(object):
if isinstance(exc_type, Exception) or not self.start_context:
return
- duration = self.clock.time_msec() - self.start
+ duration = self.clock.time() - self.start
block_counter.labels(self.name).inc()
block_timer.labels(self.name).inc(duration)
@@ -114,9 +114,9 @@ class Measure(object):
block_ru_stime.labels(self.name).inc(ru_stime - self.ru_stime)
block_db_txn_count.labels(self.name).inc(context.db_txn_count - self.db_txn_count)
block_db_txn_duration.labels(self.name).inc(
- (context.db_txn_duration_ms - self.db_txn_duration_ms) / 1000.)
+ context.db_txn_duration_sec - self.db_txn_duration_sec)
block_db_sched_duration.labels(self.name).inc(
- (context.db_sched_duration_ms - self.db_sched_duration_ms) / 1000.)
+ context.db_sched_duration_sec - self.db_sched_duration_sec)
if self.created_context:
self.start_context.__exit__(exc_type, exc_val, exc_tb)
|
