mirror of
https://github.com/element-hq/synapse
synced 2024-09-01 12:10:21 +00:00
Merge pull request #2793 from matrix-org/rav/db_txn_time_in_millis
Track db txn time in millisecs
This commit is contained in:
commit
fb6563b4be
4 changed files with 17 additions and 10 deletions
|
@ -93,6 +93,8 @@ response_db_txn_count = metrics.register_counter(
|
||||||
),
|
),
|
||||||
)
|
)
|
||||||
|
|
||||||
|
# seconds spent waiting for db txns, excluding scheduling time, when processing
|
||||||
|
# this request
|
||||||
response_db_txn_duration = metrics.register_counter(
|
response_db_txn_duration = metrics.register_counter(
|
||||||
"response_db_txn_duration_seconds", labels=["method", "servlet", "tag"],
|
"response_db_txn_duration_seconds", labels=["method", "servlet", "tag"],
|
||||||
alternative_names=(
|
alternative_names=(
|
||||||
|
@ -368,7 +370,7 @@ class RequestMetrics(object):
|
||||||
context.db_txn_count, request.method, self.name, tag
|
context.db_txn_count, request.method, self.name, tag
|
||||||
)
|
)
|
||||||
response_db_txn_duration.inc_by(
|
response_db_txn_duration.inc_by(
|
||||||
context.db_txn_duration, request.method, self.name, tag
|
context.db_txn_duration_ms / 1000., request.method, self.name, tag
|
||||||
)
|
)
|
||||||
|
|
||||||
|
|
||||||
|
|
|
@ -66,10 +66,10 @@ class SynapseRequest(Request):
|
||||||
context = LoggingContext.current_context()
|
context = LoggingContext.current_context()
|
||||||
ru_utime, ru_stime = context.get_resource_usage()
|
ru_utime, ru_stime = context.get_resource_usage()
|
||||||
db_txn_count = context.db_txn_count
|
db_txn_count = context.db_txn_count
|
||||||
db_txn_duration = context.db_txn_duration
|
db_txn_duration_ms = context.db_txn_duration_ms
|
||||||
except Exception:
|
except Exception:
|
||||||
ru_utime, ru_stime = (0, 0)
|
ru_utime, ru_stime = (0, 0)
|
||||||
db_txn_count, db_txn_duration = (0, 0)
|
db_txn_count, db_txn_duration_ms = (0, 0)
|
||||||
|
|
||||||
self.site.access_logger.info(
|
self.site.access_logger.info(
|
||||||
"%s - %s - {%s}"
|
"%s - %s - {%s}"
|
||||||
|
@ -81,7 +81,7 @@ class SynapseRequest(Request):
|
||||||
int(time.time() * 1000) - self.start_time,
|
int(time.time() * 1000) - self.start_time,
|
||||||
int(ru_utime * 1000),
|
int(ru_utime * 1000),
|
||||||
int(ru_stime * 1000),
|
int(ru_stime * 1000),
|
||||||
int(db_txn_duration * 1000),
|
db_txn_duration_ms,
|
||||||
int(db_txn_count),
|
int(db_txn_count),
|
||||||
self.sentLength,
|
self.sentLength,
|
||||||
self.code,
|
self.code,
|
||||||
|
|
|
@ -59,7 +59,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", "usage_start", "usage_end",
|
"db_txn_count", "db_txn_duration_ms", "usage_start", "usage_end",
|
||||||
"main_thread", "alive",
|
"main_thread", "alive",
|
||||||
"request", "tag",
|
"request", "tag",
|
||||||
]
|
]
|
||||||
|
@ -97,7 +97,10 @@ class LoggingContext(object):
|
||||||
self.ru_stime = 0.
|
self.ru_stime = 0.
|
||||||
self.ru_utime = 0.
|
self.ru_utime = 0.
|
||||||
self.db_txn_count = 0
|
self.db_txn_count = 0
|
||||||
self.db_txn_duration = 0.
|
|
||||||
|
# ms spent waiting for db txns, excluding scheduling time
|
||||||
|
self.db_txn_duration_ms = 0
|
||||||
|
|
||||||
self.usage_start = None
|
self.usage_start = None
|
||||||
self.usage_end = None
|
self.usage_end = None
|
||||||
self.main_thread = threading.current_thread()
|
self.main_thread = threading.current_thread()
|
||||||
|
@ -205,7 +208,7 @@ class LoggingContext(object):
|
||||||
|
|
||||||
def add_database_transaction(self, duration_ms):
|
def add_database_transaction(self, duration_ms):
|
||||||
self.db_txn_count += 1
|
self.db_txn_count += 1
|
||||||
self.db_txn_duration += duration_ms / 1000.
|
self.db_txn_duration_ms += duration_ms
|
||||||
|
|
||||||
|
|
||||||
class LoggingContextFilter(logging.Filter):
|
class LoggingContextFilter(logging.Filter):
|
||||||
|
|
|
@ -72,6 +72,7 @@ block_db_txn_count = metrics.register_counter(
|
||||||
),
|
),
|
||||||
)
|
)
|
||||||
|
|
||||||
|
# seconds spent waiting for db txns, excluding scheduling time, in this block
|
||||||
block_db_txn_duration = metrics.register_counter(
|
block_db_txn_duration = metrics.register_counter(
|
||||||
"block_db_txn_duration_seconds", labels=["block_name"],
|
"block_db_txn_duration_seconds", labels=["block_name"],
|
||||||
alternative_names=(
|
alternative_names=(
|
||||||
|
@ -95,7 +96,7 @@ def measure_func(name):
|
||||||
class Measure(object):
|
class Measure(object):
|
||||||
__slots__ = [
|
__slots__ = [
|
||||||
"clock", "name", "start_context", "start", "new_context", "ru_utime",
|
"clock", "name", "start_context", "start", "new_context", "ru_utime",
|
||||||
"ru_stime", "db_txn_count", "db_txn_duration", "created_context"
|
"ru_stime", "db_txn_count", "db_txn_duration_ms", "created_context"
|
||||||
]
|
]
|
||||||
|
|
||||||
def __init__(self, clock, name):
|
def __init__(self, clock, name):
|
||||||
|
@ -115,7 +116,7 @@ class Measure(object):
|
||||||
|
|
||||||
self.ru_utime, self.ru_stime = self.start_context.get_resource_usage()
|
self.ru_utime, self.ru_stime = self.start_context.get_resource_usage()
|
||||||
self.db_txn_count = self.start_context.db_txn_count
|
self.db_txn_count = self.start_context.db_txn_count
|
||||||
self.db_txn_duration = self.start_context.db_txn_duration
|
self.db_txn_duration_ms = self.start_context.db_txn_duration_ms
|
||||||
|
|
||||||
def __exit__(self, exc_type, exc_val, exc_tb):
|
def __exit__(self, exc_type, exc_val, exc_tb):
|
||||||
if isinstance(exc_type, Exception) or not self.start_context:
|
if isinstance(exc_type, Exception) or not self.start_context:
|
||||||
|
@ -145,7 +146,8 @@ class Measure(object):
|
||||||
context.db_txn_count - self.db_txn_count, self.name
|
context.db_txn_count - self.db_txn_count, self.name
|
||||||
)
|
)
|
||||||
block_db_txn_duration.inc_by(
|
block_db_txn_duration.inc_by(
|
||||||
context.db_txn_duration - self.db_txn_duration, self.name
|
(context.db_txn_duration_ms - self.db_txn_duration_ms) / 1000.,
|
||||||
|
self.name
|
||||||
)
|
)
|
||||||
|
|
||||||
if self.created_context:
|
if self.created_context:
|
||||||
|
|
Loading…
Reference in a new issue