From b088aafcae71fa61433f92ce0b139802a9cbd304 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Thu, 21 Jun 2018 06:15:03 +0100 Subject: Log number of events fetched from DB 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.] --- synapse/storage/events_worker.py | 4 ++++ 1 file changed, 4 insertions(+) (limited to 'synapse/storage') diff --git a/synapse/storage/events_worker.py b/synapse/storage/events_worker.py index 32d9d00ffb..cf4efa9d12 100644 --- a/synapse/storage/events_worker.py +++ b/synapse/storage/events_worker.py @@ -21,6 +21,7 @@ from synapse.events.utils import prune_event from synapse.util.logcontext import ( PreserveLoggingContext, make_deferred_yieldable, run_in_background, + LoggingContext, ) from synapse.util.metrics import Measure 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] 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_ids, check_redacted=check_redacted, -- cgit 1.4.1 From 0495fe00350a3610cbfd9b0097ff1a8a1c31f5f4 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Fri, 22 Jun 2018 10:42:28 +0100 Subject: Indirect evt_count updates via method call so that we can stub it for the sentinel and not have a billion failing UTs --- synapse/storage/events_worker.py | 2 +- synapse/util/logcontext.py | 11 +++++++++++ 2 files changed, 12 insertions(+), 1 deletion(-) (limited to 'synapse/storage') diff --git a/synapse/storage/events_worker.py b/synapse/storage/events_worker.py index cf4efa9d12..3a634842ca 100644 --- a/synapse/storage/events_worker.py +++ b/synapse/storage/events_worker.py @@ -147,7 +147,7 @@ class EventsWorkerStore(SQLBaseStore): if missing_events_ids: log_ctx = LoggingContext.current_context() - log_ctx.evt_db_fetch_count += len(missing_events_ids) + log_ctx.record_event_fetch(len(missing_events_ids)) missing_events = yield self._enqueue_events( missing_events_ids, diff --git a/synapse/util/logcontext.py b/synapse/util/logcontext.py index 2bfd4bee96..df2b71b791 100644 --- a/synapse/util/logcontext.py +++ b/synapse/util/logcontext.py @@ -91,6 +91,9 @@ class LoggingContext(object): def add_database_scheduled(self, sched_sec): pass + def record_event_fetch(self, event_count): + pass + def __nonzero__(self): return False __bool__ = __nonzero__ # python3 @@ -247,6 +250,14 @@ class LoggingContext(object): """ self.db_sched_duration_sec += sched_sec + def record_event_fetch(self, event_count): + """Record a number of events being fetched from the db + + Args: + event_count (int): number of events being fetched + """ + self.evt_db_fetch_count += event_count + class LoggingContextFilter(logging.Filter): """Logging filter that adds values from the current logging context to each -- cgit 1.4.1