61 lines
2.5 KiB
Python
61 lines
2.5 KiB
Python
"""Content-free phase timing for diagnosing slow Gateway operations."""
|
|
|
|
from __future__ import annotations
|
|
|
|
import logging
|
|
from collections.abc import Iterator
|
|
from contextlib import contextmanager
|
|
from time import perf_counter
|
|
|
|
from starlette.exceptions import HTTPException
|
|
from starlette.responses import Response
|
|
|
|
|
|
class OperationTiming:
|
|
"""Measure handler work, not proxy/network or pre-handler/auth queue time.
|
|
|
|
Phase names and context must be server-owned labels, never request content,
|
|
database URLs or credentials. The response header also helps deployments
|
|
where operators do not yet have application logs available.
|
|
"""
|
|
|
|
def __init__(self, response: Response | None, logger: logging.Logger, operation: str, **context: str) -> None:
|
|
self.response = response if response is not None else Response()
|
|
self.logger = logger
|
|
self.operation = operation
|
|
self.context = context
|
|
self.started = perf_counter()
|
|
self.phases: dict[str, float] = {}
|
|
|
|
def __enter__(self) -> OperationTiming:
|
|
return self
|
|
|
|
def __exit__(self, exc_type, exc, traceback) -> None:
|
|
total_ms = (perf_counter() - self.started) * 1000
|
|
metrics = {**self.phases, "handler_total": total_ms}
|
|
self.response.headers["Server-Timing"] = ", ".join(f"{name};dur={duration:.2f}" for name, duration in metrics.items())
|
|
if isinstance(exc, HTTPException):
|
|
# FastAPI discards the injected response on HTTPException.
|
|
exc.headers = {**(exc.headers or {}), "Server-Timing": self.response.headers["Server-Timing"]}
|
|
log = self.logger.warning if exc_type is not None or total_ms >= 1000 else self.logger.info
|
|
try:
|
|
log(
|
|
"GATEWAY_OPERATION_TIMING operation=%s outcome=%s %s %s",
|
|
self.operation,
|
|
"error" if exc_type is not None else "ok",
|
|
" ".join(f"{name}={value}" for name, value in self.context.items()),
|
|
" ".join(f"{name}_ms={duration:.2f}" for name, duration in metrics.items()),
|
|
)
|
|
except Exception:
|
|
# Diagnostics must not hide the actual request error (or fail a
|
|
# successful write) if a custom logging handler/disk is unavailable.
|
|
pass
|
|
|
|
@contextmanager
|
|
def phase(self, name: str) -> Iterator[None]:
|
|
started = perf_counter()
|
|
try:
|
|
yield
|
|
finally:
|
|
self.phases[name] = self.phases.get(name, 0.0) + (perf_counter() - started) * 1000
|