feat(robot-server,system-server): Return server timing metrics in HTTP responses

robot-server/robot_server/app_setup.py

@@ -6,6 +6,8 @@
 from fastapi import FastAPI
 from fastapi.middleware.cors import CORSMiddleware
 
+from server_utils.fastapi_utils.server_timing_middleware import server_timing_middleware
+
 from opentrons import __version__
 
 from .errors.exception_handlers import exception_handlers
@@ -104,7 +106,6 @@ async def _lifespan(app: FastAPI) -> AsyncGenerator[None, None]:
     lifespan=_lifespan,
 )
 
-# cors
 app.add_middleware(
     CORSMiddleware,
     allow_origins=("*"),
@@ -113,6 +114,8 @@ async def _lifespan(app: FastAPI) -> AsyncGenerator[None, None]:
     allow_headers=["*"],
 )
 
+app.middleware("http")(server_timing_middleware())
+
 # main router
 router.install_on_app(app)
 

server-utils/Pipfile

@@ -25,7 +25,7 @@ flake8-annotations = "==3.0.1"
 flake8-docstrings = "~=1.7.0"
 flake8-noqa = "~=1.4.0"
 decoy = "==2.1.1"
-httpx = "==0.18.*"
+httpx = "==0.26.0"
 black = "==22.3.0"
 types-requests = "~=2.31.0"
 types-mock = "~=5.1.0"

server-utils/server_utils/fastapi_utils/server_timing_middleware.py

@@ -0,0 +1,76 @@
+"""Add server performance metrics to HTTP responses.
+
+This uses the standard Server-Timing response header, so the metrics will show up in
+browser dev tools.
+https://developer.mozilla.org/en-US/docs/Web/HTTP/Reference/Headers/Server-Timing
+"""
+
+
+import logging
+import time
+from typing import Awaitable, Callable
+
+from fastapi import Request, Response
+
+
+# These are inserted into the HTTP response header raw, so they should be short and
+# avoid special characters.
+#
+# Chrome devtools uses the description as a label in the timing bar graph,
+# adjacent to things like "Waiting for server response" and "Content download".
+_METRIC_NAME = "opentrons-asgi"
+_METRIC_DESC = "Time in Python (roughly)"
+
+
+_log = logging.getLogger(__name__)
+
+
+_CallNextType = Callable[[Request], Awaitable[Response]]
+
+
+def server_timing_middleware(
+    clock: Callable[[], float] = time.perf_counter
+) -> Callable[[Request, _CallNextType], Awaitable[Response]]:
+    """Return a function that can be used as a FastAPI middleware.
+
+    Usage example:
+
+        app = fastapi.FastAPI()
+        ...
+
+        app.middleware("http")(server_timing_middleware())
+
+
+    The `clock` param should return the current time in seconds.
+    """
+
+    async def middleware_function(
+        request: Request, call_next: _CallNextType
+    ) -> Response:
+        time_before = clock()
+        response = await call_next(request)
+        time_after = clock()
+        duration_ms = round((time_after - time_before) * 1000)
+
+        _log.debug(f"{request.url}: {duration_ms} ms")
+
+        response.headers["Server-Timing"] = _update_server_timing_header(
+            preexisting_header_value=response.headers.get("Server-Timing", None),
+            name=_METRIC_NAME,
+            desc=_METRIC_DESC,
+            dur=duration_ms,
+        )
+
+        return response
+
+    return middleware_function
+
+
+def _update_server_timing_header(
+    preexisting_header_value: str | None, name: str, dur: float, desc: str
+) -> str:
+    new_metric = f'{name};dur={dur};desc="{desc}"'
+    if preexisting_header_value is None:
+        return new_metric
+    else:
+        return f"{preexisting_header_value},{new_metric}"

server-utils/tests/fastapi_utils/__init__.py

@@ -0,0 +1 @@
+# noqa: D104

server-utils/tests/fastapi_utils/test_server_timing_middleware.py

@@ -0,0 +1,53 @@
+# noqa: D100
+
+
+from fastapi import FastAPI, Response
+from starlette.testclient import TestClient
+
+from server_utils.fastapi_utils.server_timing_middleware import server_timing_middleware
+
+
+def test_server_timing_middleware() -> None:
+    """Test server timing middleware.
+
+    It should add, or update, a Server-Timing header with the elapsed milliseconds.
+    """
+    app = FastAPI()
+
+    class TestClock:
+        """Start at t=100 seconds and increment by 1 second each call."""
+
+        def __init__(self) -> None:
+            self._time = 100.0
+
+        def __call__(self) -> float:
+            initial_time = self._time
+            self._time += 1
+            return initial_time
+
+    app.middleware("http")(server_timing_middleware(TestClock()))
+
+    @app.get("/testEndpoint")
+    def get_test_endpoint() -> str:
+        return "Test response body"
+
+    @app.get("/testEndpointWithPreexistingHeader")
+    def get_test_endpoint_with_preexisting_header(response: Response) -> str:
+        response.headers["Server-Timing"] = "something-preexisting"
+        return "Test response body"
+
+    test_client = TestClient(app)
+
+    response = test_client.get("/testEndpoint")
+    assert response.status_code == 200
+    assert (
+        response.headers["Server-Timing"]
+        == 'opentrons-asgi;dur=1000;desc="Time in Python (roughly)"'
+    )
+
+    response = test_client.get("/testEndpointWithPreexistingHeader")
+    assert response.status_code == 200
+    assert (
+        response.headers["Server-Timing"]
+        == 'something-preexisting,opentrons-asgi;dur=1000;desc="Time in Python (roughly)"'
+    )

system-server/system_server/app_setup.py

@@ -1,8 +1,11 @@
 """Main FastAPI application."""
 import logging
+from typing import List, Any
+
 from fastapi import FastAPI
 from fastapi.middleware.cors import CORSMiddleware
-from typing import List, Any
+
+from server_utils.fastapi_utils.server_timing_middleware import server_timing_middleware
 
 from system_server._version import version
 from system_server.settings import get_settings
@@ -22,7 +25,6 @@
     redoc_url="/system/redoc",
 )
 
-# cors
 app.add_middleware(
     CORSMiddleware,
     allow_origins=("*"),
@@ -31,6 +33,8 @@
     allow_headers=["*"],
 )
 
+app.middleware("http")(server_timing_middleware())
+
 # main router
 app.include_router(router=router)