Middleware: per-stage latency as a Server-Timing header

A response middleware that turns EDRI's built-in event._timing trace into a standard Server-Timing header. Open the browser DevTools → Timing tab and you see exactly where a request spent its time — broker queue, routing, the handler itself, a worker — per request, in the client, no log digging.

Why this is a natural process_response job:

  • In EDRI one request crosses several processes (Listener → Broker → Router → Manager → Worker → back). Each hop stamps event._timing. That breakdown is only meaningful once the response is on its way out — which is where response middleware runs.

  • EDRI already injects _timing into the response body, but only in development (EDRI_API_RESPONSE_TIMING). A header is the production-safe, tooling-native alternative: DevTools and APMs parse Server-Timing; they do not parse a custom body field.


The middleware

# middlewares/server_timing.py
from edri.api.middleware import Middleware, MiddlewareControl
from edri.dataclass.directive.http import HeaderResponseDirective
from edri.dataclass.event import Event


class ServerTimingMiddleware(Middleware):
    """Publishes event._timing as a Server-Timing header on every response."""

    def process_response(self, event: Event, info) -> MiddlewareControl:
        timing = getattr(event, "_timing", None)
        stamps = sorted(timing.events, key=lambda e: e.timestamp) if timing else []

        def label(stamp) -> str:
            return f"{stamp.name}:{stamp.description}" if stamp.description else stamp.name

        if len(stamps) >= 2:
            total = (stamps[-1].timestamp - stamps[0].timestamp).total_seconds() * 1000
            metrics = [f"total;dur={total:.1f}"]
            for i in range(1, len(stamps)):
                dur = (stamps[i].timestamp - stamps[i - 1].timestamp).total_seconds() * 1000
                metrics.append(f'seg{i};dur={dur:.1f};desc="{label(stamps[i - 1])}->{label(stamps[i])}"')
            event.response.add_directive(
                HeaderResponseDirective(name="Server-Timing", value=", ".join(metrics))
            )

        return MiddlewareControl.continue_processing()

Each consecutive pair of stamps becomes one Server-Timing metric whose dur is the gap between them in milliseconds; total is first-to-last. Returning continue_processing() leaves the response otherwise untouched.


Wiring it up

# main.py
import time
from http import HTTPMethod

from edri import EDRI
from edri.abstract import ManagerBase, request
from edri.api.dataclass.api_event import api, ApiType
from edri.dataclass.event import Event
from edri.dataclass.response import Response, response

from middlewares.server_timing import ServerTimingMiddleware


@response
class SlowResponse(Response):
    message: str


@api(url="/slow", method=HTTPMethod.GET, resource="slow", exclude={ApiType.HTML, ApiType.WS})
class SlowEvent(Event):
    response: SlowResponse


class DemoManager(ManagerBase):
    @request
    def slow(self, event: SlowEvent) -> None:
        time.sleep(0.05)            # pretend the handler does real work
        event.response.message = "ok"


if __name__ == "__main__":
    app = EDRI()
    app.add_component(DemoManager())
    app.start_api(middlewares=[ServerTimingMiddleware()])
    app.run()

What it produces

curl -D - -o /dev/null http://localhost:8080/slow -H "Accept: application/json"
Server-Timing: total;dur=54.6,
  seg1;dur=3.0;desc="RESTHandler:Created->Broker:Received",
  seg2;dur=0.3;desc="Broker:Received->Router:Received",
  seg3;dur=0.3;desc="Router:Received->DemoManager:Received",
  seg4;dur=50.2;desc="DemoManager:Received->DemoManager:Resolved",
  seg5;dur=0.4;desc="DemoManager:Resolved->Router:Received",
  seg6;dur=0.3;desc="Router:Received->Broker:Received",
  seg7;dur=0.0;desc="Broker:Received->ServerTimingMiddleware:Started"

(The header is a single line; wrapped here for readability.) seg4 — DemoManager:Received -> DemoManager:Resolved — is the handler's own 50 ms, clearly separated from the sub-millisecond broker/router hops. A growing Broker:Received -> Router:Received would instead point at router-queue backpressure.


Things to watch

  • Coverage ends at the broker. Response middleware runs inside the Broker, so the trace reaches up to ServerTimingMiddleware:Started; the final serialization in the Listener is not included. It captures essentially all of the server-side processing, which is what you want for spotting hot spots.

  • Worker time shows up too. If the handler offloads to a Worker, the worker's event_send adds stamps (...:Returned from worker), so a slow worker appears as its own segment.

  • Header size. With deep traces the header grows; emit only total plus a few key segments if you need to keep it small, or gate the middleware behind a debug flag / sampling in production.

  • Pairs well with a request id. Add a request-middleware that sets an X-Request-ID and echo it here, so a slow Server-Timing line and the matching cross-process logs share one identifier.