Expose some initial Prometheus metrics (#1402)

The Prometheus client library for Python seems not great, but we really
need metrics to get a sense of some upcoming performance improvements.

containers/prometheus/Dockerfile

@@ -0,0 +1,2 @@
+FROM docker.io/prom/prometheus:v2.51.1
+COPY prometheus.yml /etc/prometheus/prometheus.yml

containers/prometheus/prometheus.yml

@@ -0,0 +1,8 @@
+global:
+  scrape_interval: 15s
+  evaluation_interval: 15s
+
+scrape_configs:
+  - job_name: web
+    static_configs:
+      - targets: ['web:8080']

docker-compose.yml

@@ -7,12 +7,14 @@ volumes:
   storage:
   logs:
   profile-stats:
+  prometheus:
   test-cache:
   test-coverage:
 
 networks:
   external-web:
   external-nginx:
+  external-prometheus:
   nginx-web:
     internal: true
   web-memcached:
@@ -21,6 +23,8 @@ networks:
     internal: true
   test-postgres:
     internal: true
+  prometheus-web:
+    internal: true
 
 services:
   nginx:
@@ -53,19 +57,23 @@ services:
       WEB_CONCURRENCY: 8
       PYTHONWARNINGS: d
       PYTHONUNBUFFERED: 1
+      PROMETHEUS_MULTIPROC_DIR: /weasyl/storage/prometheus
     volumes:
       - assets:/weasyl/build:ro
       - config:/run/config:ro
       - storage:/weasyl/storage/static
       - logs:/weasyl/storage/log
       - profile-stats:/weasyl/storage/profile-stats
+      - type: tmpfs
+        target: /weasyl/storage/prometheus
       - type: tmpfs
         target: /weasyl/storage/temp
       - type: tmpfs
         target: /tmp
     networks:
       - external-web
       - nginx-web
+      - prometheus-web
       - web-memcached
       - web-postgres
     read_only: false
@@ -95,6 +103,18 @@ services:
       - test-postgres
     read_only: true
 
+  prometheus:
+    profiles: [ prometheus ]
+    build: containers/prometheus
+    volumes:
+      - prometheus:/prometheus
+    networks:
+      - external-prometheus
+      - prometheus-web
+    ports:
+      - ${WEASYL_BIND:-127.0.0.1}:9090:9090/tcp
+    read_only: true
+
   configure:
     profiles: [ configure ]
     image: docker.io/library/alpine:3.16

gunicorn.conf.py

@@ -1,3 +1,6 @@
+from prometheus_client import multiprocess
+
+
 wsgi_app = "weasyl.wsgi:make_wsgi_app()"
 
 proc_name = "weasyl"
@@ -8,3 +11,7 @@
     'X-FORWARDED-PROTO': 'https',
 }
 forwarded_allow_ips = '*'
+
+
+def child_exit(server, worker):
+    multiprocess.mark_process_dead(worker.pid)

pyproject.toml

@@ -27,6 +27,7 @@ pillow = "10.3.0"
 psycopg2cffi = "2.9.0"
 sqlalchemy = "1.4.45"
 lxml = "4.9.2"
+prometheus-client = "^0.20.0"
 
 # https://github.com/Weasyl/misaka
 misaka = {url = "https://pypi.weasyl.dev/misaka/misaka-1.0.3%2Bweasyl.7.tar.gz"}

weasyl/index.py

@@ -3,6 +3,8 @@
 import operator
 import random
 
+from prometheus_client import Histogram
+
 from libweasyl import ratings
 from libweasyl.cache import region
 
@@ -16,10 +18,15 @@
 from weasyl import searchtag
 from weasyl import siteupdate
 from weasyl import submission
+from weasyl.metrics import CachedMetric
+
 
+recent_submissions_time = CachedMetric(Histogram("weasyl_recent_submissions_fetch_seconds", "recent submissions fetch time", ["cached"]))
 
+
+@recent_submissions_time.cached
 @region.cache_on_arguments(expiration_time=120)
-@d.record_timing
+@recent_submissions_time.uncached
 def recent_submissions():
     submissions = []
     for category in m.ALL_SUBMISSION_CATEGORIES:

weasyl/metrics.py

@@ -0,0 +1,43 @@
+import functools
+import threading
+import time
+
+
+class CachedMetric:
+    """
+    A metric for a cached operation. Adds a `cached` label.
+    """
+
+    def __init__(self, metric):
+        self._state = threading.local()
+        self._metric = metric
+        metric.labels(cached="no")
+        metric.labels(cached="yes")
+
+    def cached(self, func):
+        state = self._state
+        metric = self._metric
+
+        @functools.wraps(func)
+        def wrapped(*args, **kwargs):
+            state.cached = True
+
+            start = time.perf_counter()
+            ret = func(*args, **kwargs)
+            duration = time.perf_counter() - start
+
+            metric.labels(cached="yes" if state.cached else "no").observe(duration)
+
+            return ret
+
+        return wrapped
+
+    def uncached(self, func):
+        state = self._state
+
+        @functools.wraps(func)
+        def wrapped(*args, **kwargs):
+            state.cached = False
+            return func(*args, **kwargs)
+
+        return wrapped

weasyl/middleware.py

@@ -7,6 +7,7 @@
 from datetime import datetime, timedelta, timezone
 
 import multipart
+from prometheus_client import Histogram
 from pyramid.decorator import reify
 from pyramid.httpexceptions import (
     HTTPBadRequest,
@@ -154,24 +155,35 @@ def cache_clear_tween(request):
     return cache_clear_tween
 
 
+request_duration = Histogram(
+    "weasyl_request_duration_seconds",
+    "total request time",
+    ["route"],
+    # `Histogram.DEFAULT_BUCKETS`, extended up to the Gunicorn worker timeout
+    buckets=(.005, .01, .025, .05, .075, .1, .25, .5, .75, 1.0, 2.5, 5.0, 7.5, 10.0, 15.0, 20.0, 30.0, float("inf")),
+)
+
+
 def db_timer_tween_factory(handler, registry):
     """
     A tween that records timing information in the headers of a response.
     """
+    # register all labels for the `weasyl_request_duration_seconds` metric in advance
+    for route in registry.introspector.get_category("routes"):
+        request_duration.labels(route=route["introspectable"].discriminator)
+
     def db_timer_tween(request):
         started_at = time.perf_counter()
         request.sql_times = []
         request.memcached_times = []
         resp = handler(request)
-        ended_at = time.perf_counter()
-        time_in_sql = sum(request.sql_times)
-        time_in_memcached = sum(request.memcached_times)
-        time_in_python = ended_at - started_at - time_in_sql - time_in_memcached
-        resp.headers['X-SQL-Time-Spent'] = '%0.1fms' % (time_in_sql * 1000,)
-        resp.headers['X-Memcached-Time-Spent'] = '%0.1fms' % (time_in_memcached * 1000,)
-        resp.headers['X-Python-Time-Spent'] = '%0.1fms' % (time_in_python * 1000,)
-        resp.headers['X-SQL-Queries'] = str(len(request.sql_times))
-        resp.headers['X-Memcached-Queries'] = str(len(request.memcached_times))
+        time_total = time.perf_counter() - started_at
+        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),),
+            "memcached_queries": "%d" % (len(request.memcached_times),),
+            "memcached_seconds": "%.3f" % (sum(request.memcached_times),),
+        })
         return resp
     return db_timer_tween
 

weasyl/wsgi.py

@@ -1,3 +1,8 @@
+from prometheus_client import (
+    CollectorRegistry,
+    multiprocess,
+)
+from prometheus_client.openmetrics import exposition as openmetrics
 from pyramid.config import Configurator
 from pyramid.response import Response
 
@@ -80,4 +85,22 @@ def make_wsgi_app(*, configure_cache=True):
             replace_existing_backend=True
         )
 
-    return wsgi_app
+    def app_with_metrics(environ, start_response):
+        if environ["PATH_INFO"] == "/metrics":
+            if "HTTP_X_FORWARDED_FOR" in environ:
+                start_response("403 Forbidden", [])
+                return []
+
+            registry = CollectorRegistry()
+            multiprocess.MultiProcessCollector(registry)
+            data = openmetrics.generate_latest(registry)
+
+            start_response("200 OK", [
+                ("Content-Type", openmetrics.CONTENT_TYPE_LATEST),
+                ("Content-Length", str(len(data))),
+            ])
+            return [data]
+
+        return wsgi_app(environ, start_response)
+
+    return app_with_metrics