Add middleware for logging response times

Author: PGijsbers

src/core/logging.py

@@ -1,6 +1,7 @@
 """Utility functions for logging."""
 
 import sys
+import time
 import uuid
 from collections.abc import Awaitable, Callable
 from pathlib import Path
@@ -37,6 +38,33 @@ async def add_request_context_to_log(
         return await call_next(request)
 
 
+async def log_request_duration(
+    request: Request,
+    call_next: Callable[[Request], Awaitable[Response]],
+) -> Response:
+    """Log the process and wallclock time for each call.
+
+    Reported times cannot be attributed solely to processing the request.
+    As multiple requests can be handled concurrently in the same process,
+    process time may be spent on other requests as well. The same goes for
+    wallclock time, which is additionally influenced by e.g., context switches.
+    """
+    start_mono_ns = time.monotonic_ns()
+    start_process_ns = time.process_time_ns()
+    response: Response = await call_next(request)
+
+    duration_mono_ns = time.monotonic_ns() - start_mono_ns
+    duration_process_ns = time.process_time_ns() - start_process_ns
+    logger.info(
+        "Request took {mono_ms} ms wallclock time (process time {process_ms} ms)",
+        mono_ms=int(duration_mono_ns / 1_000_000),
+        process_ms=int(duration_process_ns / 1_000_000),
+        wallclock_time_ns=duration_mono_ns,
+        process_time_ns=duration_process_ns,
+    )
+    return response
+
+
 async def request_response_logger(
     request: Request,
     call_next: Callable[[Request], Awaitable[Response]],

src/main.py

@@ -10,7 +10,12 @@
 
 from config import load_configuration
 from core.errors import ProblemDetailError, problem_detail_exception_handler
-from core.logging import add_request_context_to_log, request_response_logger, setup_log_sinks
+from core.logging import (
+    add_request_context_to_log,
+    log_request_duration,
+    request_response_logger,
+    setup_log_sinks,
+)
 from database.setup import close_databases
 from routers.mldcat_ap.dataset import router as mldcat_ap_router
 from routers.openml.datasets import router as datasets_router
@@ -72,6 +77,7 @@ def create_api(configuration_file: Path | None = None) -> FastAPI:
     # Order matters! Each added middleware wraps the previous, creating a stack.
     # See also: https://fastapi.tiangolo.com/tutorial/middleware/#multiple-middleware-execution-order
     app.middleware("http")(request_response_logger)
+    app.middleware("http")(log_request_duration)
     app.middleware("http")(add_request_context_to_log)
 
     app.add_exception_handler(ProblemDetailError, problem_detail_exception_handler)  # type: ignore[arg-type]