Add metrics for event processing lag #3090

erikjohnston · 2018-04-11T13:35:33Z

Adds metrics for tracking how far behind the appservice and federation sending loops are. There are threee:

The stream positions of the last processed events, and stream position for last persisted event. This allows getting the lag in terms of delta of event stream positions.
The received_ts of the last processed event. This allows us to get an estimate of where the processing is up to time wise.
How long it took from being written to the db to being processed for the last event processed, i.e. its difference between the time the event was processed and its received_ts.

richvdh

generally looks good. a few minor comments.

richvdh · 2018-04-12T09:41:49Z

synapse/metrics/metric.py

+        # dict[list[str]]: value for each set of label values. the keys are the
+        # label values, in the same order as the labels in self.labels.
+        #
+        # (if the metric is a scalar, the (single) key is the empty list).


s/list/tuple/, fwiw

richvdh · 2018-04-12T09:42:03Z

synapse/metrics/metric.py

+
+        self.guages[values] = v
+
+    def render(self):


feels like a bit of a shame not to share this with CounterMetric with a baseclass

Yeah, though I think in this case its more hassle than its worth. Another option would be to make the counter and gauge class the same and have it support both set and inc, but then you lose the easy ability to see if a metric is meant to be a counter or gauge. WDYT?

I like them being separate. Happy for you to leave the code c&ped for now.

richvdh · 2018-04-12T09:59:30Z

synapse/storage/events_worker.py

+            event_id (str)
+
+        Returns:
+            Deferred[int|None]: Timstamp in milliseconds, or None for events


richvdh · 2018-04-12T10:03:12Z

synapse/federation/transaction_queue.py

+
+                if events:
+                    now = self.clock.time_msec()
+                    ts = yield self.store.get_received_ts(events[-1].event_id)


seems a shame to have to do a db hit for this, but I guess working around it is a faff.

richvdh · 2018-04-12T10:03:34Z

synapse/federation/transaction_queue.py

@@ -239,6 +239,21 @@ def handle_room_events(events):
                    "events", next_token
                )

+                synapse.metrics.event_processing_positions.set(


can we move the events_processed_counter update here so that all the metrics updates are collected together?

richvdh · 2018-04-12T10:03:51Z

synapse/handlers/appservice.py

@@ -111,6 +111,20 @@ def notify_interested_services(self, current_id):
                    events_processed_counter.inc_by(len(events))

                    yield self.store.set_appservice_last_pos(upper_bound)
+
+                    synapse.metrics.event_processing_positions.set(


again with events_processed_counter

richvdh · 2018-04-12T10:12:17Z

synapse/storage/events_worker.py

+        Returns:
+            Deferred[int|None]: Timstamp in milliseconds, or None for events
+            that were persisted before received_ts was implemented.
+        """


what happens if the event id is unknown? exception, presumably?

…ocessed_event_lag

richvdh · 2018-04-12T11:03:29Z

synapse/storage/events_worker.py

@@ -52,13 +52,14 @@

 class EventsWorkerStore(SQLBaseStore):
    def get_received_ts(self, event_id):
-        """Get received_ts (when it was persisted) for the event
+        """Get received_ts (when it was persisted) for the event. Raises an


could have done with being a separate paragraph, ftr, since the first line is slightly special (https://www.python.org/dev/peps/pep-0257/#multi-line-docstrings)

richvdh

lgtm

@Valodim

Changes in synapse v0.28.0-rc1 (2018-04-26) =========================================== Bug Fixes: * Fix quarantine media admin API and search reindex (PR #3130) * Fix media admin APIs (PR #3134) Changes in synapse v0.28.0-rc1 (2018-04-24) =========================================== Minor performance improvement to federation sending and bug fixes. (Note: This release does not include state resolutions discussed in matrix live) Features: * Add metrics for event processing lag (PR #3090) * Add metrics for ResponseCache (PR #3092) Changes: * Synapse on PyPy (PR #2760) Thanks to @Valodim! * move handling of auto_join_rooms to RegisterHandler (PR #2996) Thanks to @krombel! * Improve handling of SRV records for federation connections (PR #3016) Thanks to @silkeh! * Document the behaviour of ResponseCache (PR #3059) * Preparation for py3 (PR #3061, #3073, #3074, #3075, #3103, #3104, #3106, #3107, #3109, #3110) Thanks to @NotAFile! * update prometheus dashboard to use new metric names (PR #3069) Thanks to @krombel! * use python3-compatible prints (PR #3074) Thanks to @NotAFile! * Send federation events concurrently (PR #3078) * Limit concurrent event sends for a room (PR #3079) * Improve R30 stat definition (PR #3086) * Send events to ASes concurrently (PR #3088) * Refactor ResponseCache usage (PR #3093) * Clarify that SRV may not point to a CNAME (PR #3100) Thanks to @silkeh! * Use str(e) instead of e.message (PR #3103) Thanks to @NotAFile! * Use six.itervalues in some places (PR #3106) Thanks to @NotAFile! * Refactor store.have_events (PR #3117) Bug Fixes: * Return 401 for invalid access_token on logout (PR #2938) Thanks to @dklug! * Return a 404 rather than a 500 on rejoining empty rooms (PR #3080) * fix federation_domain_whitelist (PR #3099) * Avoid creating events with huge numbers of prev_events (PR #3113) * Reject events which have lots of prev_events (PR #3118)

erikjohnston added 3 commits April 11, 2018 12:13

Add GaugeMetric

ab825aa

Track where event stream processing have gotten up to

92e3461

Track last processed event received_ts

4dae4a9

erikjohnston assigned richvdh Apr 11, 2018

Fix tests

e939f3b

richvdh reviewed Apr 12, 2018

View reviewed changes

richvdh assigned erikjohnston and unassigned richvdh Apr 12, 2018

erikjohnston added 4 commits April 12, 2018 11:18

Set all metrics at the same time

f67e906

s/list/tuple

d7bf3a6

Doc we raise on unknown event

23a7f9d

Merge branch 'develop' of github.com:matrix-org/synapse into erikj/pr…

19ceb48

…ocessed_event_lag

erikjohnston assigned richvdh and unassigned erikjohnston Apr 12, 2018

richvdh reviewed Apr 12, 2018

View reviewed changes

richvdh approved these changes Apr 12, 2018

View reviewed changes

richvdh assigned erikjohnston and unassigned richvdh Apr 12, 2018

Format docstring

415aeef

erikjohnston merged commit 0f13f30 into develop Apr 12, 2018

erikjohnston deleted the erikj/processed_event_lag branch September 20, 2018 13:58

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add metrics for event processing lag #3090

Add metrics for event processing lag #3090

erikjohnston commented Apr 11, 2018

richvdh left a comment

richvdh Apr 12, 2018

richvdh Apr 12, 2018

erikjohnston Apr 12, 2018

richvdh Apr 12, 2018

richvdh Apr 12, 2018

richvdh Apr 12, 2018

richvdh Apr 12, 2018

richvdh Apr 12, 2018

richvdh Apr 12, 2018

richvdh Apr 12, 2018

richvdh left a comment

Add metrics for event processing lag #3090

Add metrics for event processing lag #3090

Conversation

erikjohnston commented Apr 11, 2018

richvdh left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

richvdh left a comment

Choose a reason for hiding this comment