mirror of
https://mau.dev/maunium/synapse.git
synced 2024-08-23 18:56:10 +00:00
Merge pull request #429 from matrix-org/markjh/db_counters
Track the time spent in the database per request.
This commit is contained in:
commit
219027f580
@ -503,12 +503,15 @@ class SynapseRequest(Request):
|
|||||||
try:
|
try:
|
||||||
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_duration = context.db_txn_duration
|
||||||
except:
|
except:
|
||||||
ru_utime, ru_stime = (0, 0)
|
ru_utime, ru_stime = (0, 0)
|
||||||
|
db_txn_count, db_txn_duration = (0, 0)
|
||||||
|
|
||||||
self.site.access_logger.info(
|
self.site.access_logger.info(
|
||||||
"%s - %s - {%s}"
|
"%s - %s - {%s}"
|
||||||
" Processed request: %dms (%dms, %dms)"
|
" Processed request: %dms (%dms, %dms) (%dms/%d)"
|
||||||
" %sB %s \"%s %s %s\" \"%s\"",
|
" %sB %s \"%s %s %s\" \"%s\"",
|
||||||
self.getClientIP(),
|
self.getClientIP(),
|
||||||
self.site.site_tag,
|
self.site.site_tag,
|
||||||
@ -516,6 +519,8 @@ 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),
|
||||||
|
int(db_txn_count),
|
||||||
self.sentLength,
|
self.sentLength,
|
||||||
self.code,
|
self.code,
|
||||||
self.method,
|
self.method,
|
||||||
|
@ -61,6 +61,15 @@ response_ru_stime = metrics.register_distribution(
|
|||||||
"response_ru_stime", labels=["method", "servlet"]
|
"response_ru_stime", labels=["method", "servlet"]
|
||||||
)
|
)
|
||||||
|
|
||||||
|
response_db_txn_count = metrics.register_distribution(
|
||||||
|
"response_db_txn_count", labels=["method", "servlet"]
|
||||||
|
)
|
||||||
|
|
||||||
|
response_db_txn_duration = metrics.register_distribution(
|
||||||
|
"response_db_txn_duration", labels=["method", "servlet"]
|
||||||
|
)
|
||||||
|
|
||||||
|
|
||||||
_next_request_id = 0
|
_next_request_id = 0
|
||||||
|
|
||||||
|
|
||||||
@ -235,6 +244,12 @@ class JsonResource(HttpServer, resource.Resource):
|
|||||||
|
|
||||||
response_ru_utime.inc_by(ru_utime, request.method, servlet_classname)
|
response_ru_utime.inc_by(ru_utime, request.method, servlet_classname)
|
||||||
response_ru_stime.inc_by(ru_stime, request.method, servlet_classname)
|
response_ru_stime.inc_by(ru_stime, request.method, servlet_classname)
|
||||||
|
response_db_txn_count.inc_by(
|
||||||
|
context.db_txn_count, request.method, servlet_classname
|
||||||
|
)
|
||||||
|
response_db_txn_duration.inc_by(
|
||||||
|
context.db_txn_duration, request.method, servlet_classname
|
||||||
|
)
|
||||||
except:
|
except:
|
||||||
pass
|
pass
|
||||||
|
|
||||||
|
@ -214,7 +214,8 @@ class SQLBaseStore(object):
|
|||||||
|
|
||||||
self._clock.looping_call(loop, 10000)
|
self._clock.looping_call(loop, 10000)
|
||||||
|
|
||||||
def _new_transaction(self, conn, desc, after_callbacks, func, *args, **kwargs):
|
def _new_transaction(self, conn, desc, after_callbacks, logging_context,
|
||||||
|
func, *args, **kwargs):
|
||||||
start = time.time() * 1000
|
start = time.time() * 1000
|
||||||
txn_id = self._TXN_ID
|
txn_id = self._TXN_ID
|
||||||
|
|
||||||
@ -277,6 +278,9 @@ class SQLBaseStore(object):
|
|||||||
end = time.time() * 1000
|
end = time.time() * 1000
|
||||||
duration = end - start
|
duration = end - start
|
||||||
|
|
||||||
|
if logging_context is not None:
|
||||||
|
logging_context.add_database_transaction(duration)
|
||||||
|
|
||||||
transaction_logger.debug("[TXN END] {%s} %f", name, duration)
|
transaction_logger.debug("[TXN END] {%s} %f", name, duration)
|
||||||
|
|
||||||
self._current_txn_total_time += duration
|
self._current_txn_total_time += duration
|
||||||
@ -302,7 +306,8 @@ class SQLBaseStore(object):
|
|||||||
|
|
||||||
current_context.copy_to(context)
|
current_context.copy_to(context)
|
||||||
return self._new_transaction(
|
return self._new_transaction(
|
||||||
conn, desc, after_callbacks, func, *args, **kwargs
|
conn, desc, after_callbacks, current_context,
|
||||||
|
func, *args, **kwargs
|
||||||
)
|
)
|
||||||
|
|
||||||
result = yield preserve_context_over_fn(
|
result = yield preserve_context_over_fn(
|
||||||
|
@ -649,7 +649,7 @@ class EventsStore(SQLBaseStore):
|
|||||||
]
|
]
|
||||||
|
|
||||||
rows = self._new_transaction(
|
rows = self._new_transaction(
|
||||||
conn, "do_fetch", [], self._fetch_event_rows, event_ids
|
conn, "do_fetch", [], None, self._fetch_event_rows, event_ids
|
||||||
)
|
)
|
||||||
|
|
||||||
row_dict = {
|
row_dict = {
|
||||||
|
@ -69,6 +69,9 @@ class LoggingContext(object):
|
|||||||
def stop(self):
|
def stop(self):
|
||||||
pass
|
pass
|
||||||
|
|
||||||
|
def add_database_transaction(self, duration_ms):
|
||||||
|
pass
|
||||||
|
|
||||||
sentinel = Sentinel()
|
sentinel = Sentinel()
|
||||||
|
|
||||||
def __init__(self, name=None):
|
def __init__(self, name=None):
|
||||||
@ -76,6 +79,8 @@ class LoggingContext(object):
|
|||||||
self.name = name
|
self.name = name
|
||||||
self.ru_stime = 0.
|
self.ru_stime = 0.
|
||||||
self.ru_utime = 0.
|
self.ru_utime = 0.
|
||||||
|
self.db_txn_count = 0
|
||||||
|
self.db_txn_duration = 0.
|
||||||
self.usage_start = None
|
self.usage_start = None
|
||||||
self.main_thread = threading.current_thread()
|
self.main_thread = threading.current_thread()
|
||||||
|
|
||||||
@ -171,6 +176,10 @@ class LoggingContext(object):
|
|||||||
|
|
||||||
return ru_utime, ru_stime
|
return ru_utime, ru_stime
|
||||||
|
|
||||||
|
def add_database_transaction(self, duration_ms):
|
||||||
|
self.db_txn_count += 1
|
||||||
|
self.db_txn_duration += duration_ms / 1000.
|
||||||
|
|
||||||
|
|
||||||
class LoggingContextFilter(logging.Filter):
|
class LoggingContextFilter(logging.Filter):
|
||||||
"""Logging filter that adds values from the current logging context to each
|
"""Logging filter that adds values from the current logging context to each
|
||||||
|
Loading…
Reference in New Issue
Block a user