tileradotorg/synapse
1
0
Fork 0
forked from MirrorHub/synapse
Code Pull requests Activity

Log number of events fetched from DB

Browse source 
When we finish processing a request, log the number of events we fetched from
the database to handle it.

[I'm trying to figure out which requests are responsible for large amounts of
event cache churn. It may turn out to be more helpful to add counts to the
prometheus per-request/block metrics, but that is an extension to this code
anyway.]
This commit is contained in:
Richard van der Hoff 2018-06-21 06:15:03 +01:00
parent aff3d76920
commit b088aafcae
3 changed files with 12 additions and 1 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

5
synapse/http/site.py
View file

@ -99,16 +99,18 @@ class SynapseRequest(Request):
db_txn_count = context.db_txn_count db_txn_count = context.db_txn_count
db_txn_duration_sec = context.db_txn_duration_sec db_txn_duration_sec = context.db_txn_duration_sec
db_sched_duration_sec = context.db_sched_duration_sec db_sched_duration_sec = context.db_sched_duration_sec
evt_db_fetch_count = context.evt_db_fetch_count
except Exception: except Exception:
ru_utime, ru_stime = (0, 0) ru_utime, ru_stime = (0, 0)
db_txn_count, db_txn_duration_sec = (0, 0) db_txn_count, db_txn_duration_sec = (0, 0)
evt_db_fetch_count = 0
end_time = time.time() end_time = time.time()
self.site.access_logger.info( self.site.access_logger.info(
"%s - %s - {%s}" "%s - %s - {%s}"
" Processed request: %.3fsec (%.3fsec, %.3fsec) (%.3fsec/%.3fsec/%d)" " Processed request: %.3fsec (%.3fsec, %.3fsec) (%.3fsec/%.3fsec/%d)"
" %sB %s \"%s %s %s\" \"%s\"", " %sB %s \"%s %s %s\" \"%s\" [%d dbevts]",
self.getClientIP(), self.getClientIP(),
self.site.site_tag, self.site.site_tag,
self.authenticated_entity, self.authenticated_entity,
@ -124,6 +126,7 @@ class SynapseRequest(Request):
self.get_redacted_uri(), self.get_redacted_uri(),
self.clientproto, self.clientproto,
self.get_user_agent(), self.get_user_agent(),
evt_db_fetch_count,
) )
try: try:

4
synapse/storage/events_worker.py
View file

@ -21,6 +21,7 @@ from synapse.events.utils import prune_event
from synapse.util.logcontext import ( from synapse.util.logcontext import (
PreserveLoggingContext, make_deferred_yieldable, run_in_background, PreserveLoggingContext, make_deferred_yieldable, run_in_background,
LoggingContext,
) )
from synapse.util.metrics import Measure from synapse.util.metrics import Measure
from synapse.api.errors import SynapseError from synapse.api.errors import SynapseError
@ -145,6 +146,9 @@ class EventsWorkerStore(SQLBaseStore):
missing_events_ids = [e for e in event_ids if e not in event_entry_map] missing_events_ids = [e for e in event_ids if e not in event_entry_map]
if missing_events_ids: if missing_events_ids:
log_ctx = LoggingContext.current_context()
log_ctx.evt_db_fetch_count += len(missing_events_ids)
missing_events = yield self._enqueue_events( missing_events = yield self._enqueue_events(
missing_events_ids, missing_events_ids,
check_redacted=check_redacted, check_redacted=check_redacted,

4
synapse/util/logcontext.py
View file

@ -60,6 +60,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_sec", "db_sched_duration_sec", "db_txn_count", "db_txn_duration_sec", "db_sched_duration_sec",
"evt_db_fetch_count",
"usage_start", "usage_start",
"main_thread", "alive", "main_thread", "alive",
"request", "tag", "request", "tag",
@ -109,6 +110,9 @@ class LoggingContext(object):
# sec spent waiting for db txns to be scheduled # sec spent waiting for db txns to be scheduled
self.db_sched_duration_sec = 0 self.db_sched_duration_sec = 0
# number of events this thread has fetched from the db
self.evt_db_fetch_count = 0
# If alive has the thread resource usage when the logcontext last # If alive has the thread resource usage when the logcontext last
# became active. # became active.
self.usage_start = None self.usage_start = None