Separate metrics for retrieving notification counts from overall requ…

…est metrics (#1424)

I deployed this ahead of time, and it didn’t have as much of a clear impact on most of the graphs as I had hoped, but it did at least achieve the main goal of eliminating the peaks on the order of 7 seconds caused by notification counting from non-notification-related routes (mostly `index`).

weasyl/define.py

@@ -16,6 +16,7 @@
 import requests
 import sqlalchemy as sa
 import sqlalchemy.orm
+from prometheus_client import Histogram
 from pyramid.response import Response
 from sqlalchemy.exc import OperationalError
 from web.template import Template
@@ -29,6 +30,7 @@
 from weasyl import config
 from weasyl import errorcode
 from weasyl import macro
+from weasyl import metrics
 from weasyl.config import config_obj, config_read_setting
 from weasyl.error import WeasylError
 
@@ -622,8 +624,13 @@ def posts_count(userid, *, friends: bool):
     return result
 
 
+notification_count_time = metrics.CachedMetric(Histogram("weasyl_notification_count_fetch_seconds", "notification counts fetch time", ["cached"]))
+
+
+@metrics.separate_timing
+@notification_count_time.cached
 @region.cache_on_arguments(expiration_time=180)
-@record_timing
+@notification_count_time.uncached
 def _page_header_info(userid):
     messages = engine.scalar(
         "SELECT COUNT(*) FROM message WHERE otherid = %(user)s AND settings ~ 'u'", user=userid)

weasyl/metrics.py

@@ -2,6 +2,8 @@
 import threading
 import time
 
+from pyramid.threadlocal import get_current_request
+
 
 class CachedMetric:
     """
@@ -41,3 +43,29 @@ def wrapped(*args, **kwargs):
             return func(*args, **kwargs)
 
         return wrapped
+
+
+def separate_timing(func):
+    """
+    Exclude the timing information for a function that runs during request processing from the overall request’s metrics, allowing them to be recorded separately.
+    """
+    @functools.wraps(func)
+    def wrapped(*args, **kwargs):
+        request = get_current_request()
+
+        outer_sql_times = request.sql_times
+        outer_memcached_times = request.memcached_times
+        request.sql_times = []
+        request.memcached_times = []
+
+        start = time.perf_counter()
+        ret = func(*args, **kwargs)
+        duration = time.perf_counter() - start
+
+        request.sql_times = outer_sql_times
+        request.memcached_times = outer_memcached_times
+        request.excluded_time += duration
+
+        return ret
+
+    return wrapped

weasyl/middleware.py

@@ -174,10 +174,11 @@ def db_timer_tween_factory(handler, registry):
 
     def db_timer_tween(request):
         started_at = time.perf_counter()
+        request.excluded_time = 0.0
         request.sql_times = []
         request.memcached_times = []
         resp = handler(request)
-        time_total = time.perf_counter() - started_at
+        time_total = time.perf_counter() - started_at - request.excluded_time
         request_duration.labels(route=request.matched_route.name if request.matched_route is not None else "none").observe(time_total, exemplar={
             "sql_queries": "%d" % (len(request.sql_times),),
             "sql_seconds": "%.3f" % (sum(request.sql_times),),