Track the time spent in the database per request.

and track the number of transactions that request started.
This commit is contained in:
Mark Haines 2015-12-07 17:56:11 +00:00
parent f7a1cdbbc6
commit 6a5ff5f223
5 changed files with 38 additions and 4 deletions

View File

@ -503,12 +503,15 @@ class SynapseRequest(Request):
try:
context = LoggingContext.current_context()
ru_utime, ru_stime = context.get_resource_usage()
db_txn_count = context.db_txn_count
db_txn_duration = context.db_txn_duration
except:
ru_utime, ru_stime = (0, 0)
db_txn_count, db_txn_duration = (0, 0)
self.site.access_logger.info(
"%s - %s - {%s}"
" Processed request: %dms (%dms, %dms)"
" Processed request: %dms (%dms, %dms) (%dms/%d)"
" %sB %s \"%s %s %s\" \"%s\"",
self.getClientIP(),
self.site.site_tag,
@ -516,6 +519,8 @@ class SynapseRequest(Request):
int(time.time() * 1000) - self.start_time,
int(ru_utime * 1000),
int(ru_stime * 1000),
int(db_txn_duration * 1000),
int(db_txn_count),
self.sentLength,
self.code,
self.method,

View File

@ -61,6 +61,15 @@ response_ru_stime = metrics.register_distribution(
"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
@ -235,6 +244,12 @@ class JsonResource(HttpServer, resource.Resource):
response_ru_utime.inc_by(ru_utime, 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:
pass

View File

@ -214,7 +214,8 @@ class SQLBaseStore(object):
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
txn_id = self._TXN_ID
@ -277,6 +278,9 @@ class SQLBaseStore(object):
end = time.time() * 1000
duration = end - start
if logging_context is not None:
logging_context.add_database_transaction(duration)
transaction_logger.debug("[TXN END] {%s} %f", name, duration)
self._current_txn_total_time += duration
@ -302,7 +306,8 @@ class SQLBaseStore(object):
current_context.copy_to(context)
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(

View File

@ -649,7 +649,7 @@ class EventsStore(SQLBaseStore):
]
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 = {

View File

@ -69,6 +69,9 @@ class LoggingContext(object):
def stop(self):
pass
def add_database_transaction(self, duration_ms):
pass
sentinel = Sentinel()
def __init__(self, name=None):
@ -76,6 +79,8 @@ class LoggingContext(object):
self.name = name
self.ru_stime = 0.
self.ru_utime = 0.
self.db_txn_count = 0
self.db_txn_duration = 0.
self.usage_start = None
self.main_thread = threading.current_thread()
@ -171,6 +176,10 @@ class LoggingContext(object):
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):
"""Logging filter that adds values from the current logging context to each