From 9385c41ba4fd9cbc86d074ff8fa69e2ae437eb88 Mon Sep 17 00:00:00 2001
From: Eric Eastwood <erice@element.io>
Date: Tue, 23 Aug 2022 02:47:30 -0500
Subject: [PATCH] Fix Prometheus metrics being negative (mixed up start/end)
 (#13584)

Fix:

 - https://github.com/matrix-org/synapse/pull/13535#discussion_r949582508
 - https://github.com/matrix-org/synapse/pull/13533#discussion_r949577244
---
 changelog.d/13584.misc               |  1 +
 synapse/handlers/federation.py       |  7 ++++++-
 synapse/handlers/federation_event.py | 10 ++++++++++
 synapse/rest/client/room.py          |  6 +++++-
 4 files changed, 22 insertions(+), 2 deletions(-)
 create mode 100644 changelog.d/13584.misc

diff --git a/changelog.d/13584.misc b/changelog.d/13584.misc
new file mode 100644
index 000000000..6b190181c
--- /dev/null
+++ b/changelog.d/13584.misc
@@ -0,0 +1 @@
+Add metrics to time how long it takes us to do backfill processing (`synapse_federation_backfill_processing_before_time_seconds`, `synapse_federation_backfill_processing_after_time_seconds`).
diff --git a/synapse/handlers/federation.py b/synapse/handlers/federation.py
index a09eaa437..e15196205 100644
--- a/synapse/handlers/federation.py
+++ b/synapse/handlers/federation.py
@@ -86,9 +86,14 @@ backfill_processing_before_timer = Histogram(
     "sec",
     [],
     buckets=(
+        0.1,
+        0.5,
         1.0,
+        2.5,
         5.0,
+        7.5,
         10.0,
+        15.0,
         20.0,
         30.0,
         40.0,
@@ -482,7 +487,7 @@ class FederationHandler:
 
         processing_end_time = self.clock.time_msec()
         backfill_processing_before_timer.observe(
-            (processing_start_time - processing_end_time) / 1000
+            (processing_end_time - processing_start_time) / 1000
         )
 
         success = await try_backfill(likely_domains)
diff --git a/synapse/handlers/federation_event.py b/synapse/handlers/federation_event.py
index 32326975a..048c4111f 100644
--- a/synapse/handlers/federation_event.py
+++ b/synapse/handlers/federation_event.py
@@ -104,15 +104,25 @@ backfill_processing_after_timer = Histogram(
     "sec",
     [],
     buckets=(
+        0.1,
+        0.25,
+        0.5,
         1.0,
+        2.5,
         5.0,
+        7.5,
         10.0,
+        15.0,
         20.0,
+        25.0,
         30.0,
         40.0,
+        50.0,
         60.0,
         80.0,
+        100.0,
         120.0,
+        150.0,
         180.0,
         "+Inf",
     ),
diff --git a/synapse/rest/client/room.py b/synapse/rest/client/room.py
index 0eafbae45..3259de480 100644
--- a/synapse/rest/client/room.py
+++ b/synapse/rest/client/room.py
@@ -116,9 +116,13 @@ messsages_response_timer = Histogram(
         2.5,
         5.0,
         10.0,
+        20.0,
         30.0,
         60.0,
+        80.0,
+        100.0,
         120.0,
+        150.0,
         180.0,
         "+Inf",
     ),
@@ -674,7 +678,7 @@ class RoomMessageListRestServlet(RestServlet):
         room_member_count = await make_deferred_yieldable(room_member_count_deferred)
         messsages_response_timer.labels(
             room_size=_RoomSize.from_member_count(room_member_count)
-        ).observe((processing_start_time - processing_end_time) / 1000)
+        ).observe((processing_end_time - processing_start_time) / 1000)
 
         return 200, msgs