From e3bc4617fcd5c858ff02cf2d443b898db87ae8a5 Mon Sep 17 00:00:00 2001
From: Erik Johnston <erik@matrix.org>
Date: Tue, 4 May 2021 15:14:22 +0100
Subject: [PATCH] Time external cache response time (#9904)

---
 changelog.d/9904.misc                     |  1 +
 synapse/replication/tcp/external_cache.py | 36 ++++++++++++++++-------
 2 files changed, 27 insertions(+), 10 deletions(-)
 create mode 100644 changelog.d/9904.misc

diff --git a/changelog.d/9904.misc b/changelog.d/9904.misc
new file mode 100644
index 000000000..3db1e625a
--- /dev/null
+++ b/changelog.d/9904.misc
@@ -0,0 +1 @@
+Time response time for external cache requests.
diff --git a/synapse/replication/tcp/external_cache.py b/synapse/replication/tcp/external_cache.py
index 1a3b051e3..b402f8281 100644
--- a/synapse/replication/tcp/external_cache.py
+++ b/synapse/replication/tcp/external_cache.py
@@ -15,7 +15,7 @@
 import logging
 from typing import TYPE_CHECKING, Any, Optional
 
-from prometheus_client import Counter
+from prometheus_client import Counter, Histogram
 
 from synapse.logging.context import make_deferred_yieldable
 from synapse.util import json_decoder, json_encoder
@@ -35,6 +35,20 @@ get_counter = Counter(
     labelnames=["cache_name", "hit"],
 )
 
+response_timer = Histogram(
+    "synapse_external_cache_response_time_seconds",
+    "Time taken to get a response from Redis for a cache get/set request",
+    labelnames=["method"],
+    buckets=(
+        0.001,
+        0.002,
+        0.005,
+        0.01,
+        0.02,
+        0.05,
+    ),
+)
+
 
 logger = logging.getLogger(__name__)
 
@@ -72,13 +86,14 @@ class ExternalCache:
 
         logger.debug("Caching %s %s: %r", cache_name, key, encoded_value)
 
-        return await make_deferred_yieldable(
-            self._redis_connection.set(
-                self._get_redis_key(cache_name, key),
-                encoded_value,
-                pexpire=expiry_ms,
+        with response_timer.labels("set").time():
+            return await make_deferred_yieldable(
+                self._redis_connection.set(
+                    self._get_redis_key(cache_name, key),
+                    encoded_value,
+                    pexpire=expiry_ms,
+                )
             )
-        )
 
     async def get(self, cache_name: str, key: str) -> Optional[Any]:
         """Look up a key/value in the named cache."""
@@ -86,9 +101,10 @@ class ExternalCache:
         if self._redis_connection is None:
             return None
 
-        result = await make_deferred_yieldable(
-            self._redis_connection.get(self._get_redis_key(cache_name, key))
-        )
+        with response_timer.labels("get").time():
+            result = await make_deferred_yieldable(
+                self._redis_connection.get(self._get_redis_key(cache_name, key))
+            )
 
         logger.debug("Got cache result %s %s: %r", cache_name, key, result)