Timing middleware: add support for alternate message formatters

Author: Conor Heine

CONTRIBUTING.md

@@ -100,7 +100,7 @@ This helps making sure that:
 During local development, there is a script that builds the site and checks for any changes, live-reloading:
 
 ```console
-$ bash scripts/docs-live.sh
+$ make docs-live
 ```
 
 It will serve the documentation on `http://0.0.0.0:8008`.

docs/contributing.md

@@ -100,7 +100,7 @@ This helps making sure that:
 During local development, there is a script that builds the site and checks for any changes, live-reloading:
 
 ```console
-$ bash scripts/docs-live.sh
+$ make docs-live
 ```
 
 It will serve the documentation on `http://0.0.0.0:8008`.

docs/src/timing2.py

@@ -0,0 +1,54 @@
+import asyncio
+import logging
+
+from fastapi import FastAPI
+from starlette.requests import Request
+from starlette.staticfiles import StaticFiles
+from starlette.testclient import TestClient
+
+from fastapi_utils import timing
+
+logging.basicConfig(level=logging.INFO)
+logger = logging.getLogger(__name__)
+
+app = FastAPI()
+timing.add_timing_middleware(
+    app,
+    record=logger.info,
+    prefix="app",
+    exclude="untimed",
+    format_message=timing.json_formatter,
+)
+static_files_app = StaticFiles(directory=".")
+app.mount(path="/static", app=static_files_app, name="static")
+
+
+@app.get("/json/timed")
+async def get_json_timed() -> None:
+    await asyncio.sleep(0.05)
+
+
+@app.get("/json/untimed")
+async def get_json_untimed() -> None:
+    await asyncio.sleep(0.1)
+
+
+@app.get("/json/timed-intermediate")
+async def get_json_with_intermediate_timing(request: Request) -> None:
+    await asyncio.sleep(0.1)
+    timing.record_timing(request, note="halfway")
+    await asyncio.sleep(0.1)
+
+
+TestClient(app).get("/json/timed")
+# INFO:__main__:TIMING: {"wall_ms":53.0,"cpu_ms":1.2,"name":"app.__main__.get_json_timed","note":null}
+
+TestClient(app).get("/json/untimed")
+# <nothing logged>
+
+TestClient(app).get("/json/timed-intermediate")
+# INFO:__main__:TIMING: {"wall_ms":105.3,"cpu_ms":0.4,"name":"app.__main__.get_json_with_intermediate_timing","note":"halfway"}
+# INFO:__main__:TIMING: {"wall_ms":206.7,"cpu_ms":1.1,"name":"app.__main__.get_json_timed","note":null}
+
+TestClient(app).get("/static/test")
+# INFO:__main__:TIMING: {"wall_ms":1.6,"cpu_ms":1.6,"name":"StaticFiles<'static'>","note":null}

docs/user-guide/timing-middleware.md

@@ -1,4 +1,4 @@
-#### Source module: [`fastapi_utils.timing`](https://github.com/dmontagu/fastapi-utils/blob/master/fastapi_utils/timing.py){.internal-link target=_blank}
+#### Source module: [`fastapi_utils.timing`](https://github.com/dmontagu/fastapi-utils/blob/master/fastapi_utils/timing.py){.internal-link target=\_blank}
 
 ---
 
@@ -7,39 +7,39 @@ used to find performance bottlenecks, monitor for regressions, etc.
 
 There are currently two public functions provided by this module:
 
-* `add_timing_middleware`, which can be used to add a middleware to a `FastAPI` app that will
-log very basic profiling information for each request (with low overhead).
+- `add_timing_middleware`, which can be used to add a middleware to a `FastAPI` app that will
+  log very basic profiling information for each request (with low overhead).
 
-* `record_timing`, which can be called on a `starlette.requests.Request` instance for a `FastAPI`
-app with the timing middleware installed (via `add_timing_middleware`), and will emit performance
-information for the request at the point at which it is called.
+- `record_timing`, which can be called on a `starlette.requests.Request` instance for a `FastAPI`
+  app with the timing middleware installed (via `add_timing_middleware`), and will emit performance
+  information for the request at the point at which it is called.
 
 !!! tip
-    If you are look for more fine-grained performance profiling data, consider 
-    <a href="https://github.com/sumerc/yappi" target="_blank">`yappi`</a>,
-    a python profiling library that was recently updated with coroutine support to enable
-    better coroutine-aware profiling.
-    
+If you are look for more fine-grained performance profiling data, consider
+<a href="https://github.com/sumerc/yappi" target="_blank">`yappi`</a>,
+a python profiling library that was recently updated with coroutine support to enable
+better coroutine-aware profiling.
+
     Note however that `yappi` adds considerable runtime overhead, and should typically be used during
     development rather than production.
-    
+
     The middleware provided in this package is intended to be sufficiently performant for production use.
-    
 
 ## Adding timing middleware
 
 The `add_timing_middleware` function takes the following arguments:
 
-* `app: FastAPI` : The app to which to add the timing middleware
-* `record: Optional[Callable[[str], None]] = None` : The callable to call on the generated timing messages.
-If not provided, defaults to `print`; a good choice is the `info` method of a `logging.Logger` instance 
-* `prefix: str = ""` : A prefix to prepend to the generated route names. This can be useful for, e.g., 
-distinguishing between mounted ASGI apps.
-* `exclude: Optional[str] = None` : If provided, any route whose generated name includes this value will not have its
-timing stats recorded.
- 
+- `app: FastAPI` : The app to which to add the timing middleware
+- `record: Optional[Callable[[str], None]] = None` : The callable to call on the generated timing messages.
+  If not provided, defaults to `print`; a good choice is the `info` method of a `logging.Logger` instance
+- `prefix: str = ""` : A prefix to prepend to the generated route names. This can be useful for, e.g.,
+  distinguishing between mounted ASGI apps.
+- `exclude: Optional[str] = None` : If provided, any route whose generated name includes this value will not have its
+  timing stats recorded.
+- `format_message: Optional[Callable[[TimingInfo], Any]] = None` : Override the default message formatter. For example, to output structured JSON logs.
+
 Here's an example demonstrating what the logged output looks like (note that the commented output has been
-split to multiple lines for ease of reading here, but each timing record is actually a single line): 
+split to multiple lines for ease of reading here, but each timing record is actually a single line):
 
 ```python hl_lines="15 37 42 45 53"
 {!./src/timing1.py!}
@@ -58,4 +58,12 @@ Note that this requires the app that generated the `Request` instance to have ha
 added using the `add_timing_middleware` function.
 
 This can be used to output multiple records at distinct times in order to introspect the relative
-contributions of different execution steps in a single endpoint.
+contributions of different execution steps in a single endpoint.
+
+## Custom message formatter
+
+It may be useful to provide an alternate format for the timing output. For example, some log management solutions prefer ingesting structured logs. A `json_formatter` function is included, but any custom formatter may be provided:
+
+```python hl_lines="9 15 37 40 43 47"
+{!./src/timing2.py!}
+```

fastapi_utils/timing.py

@@ -7,8 +7,10 @@
 For more detailed performance investigations (during development only, due to added overhead),
 consider using the coroutine-aware profiling library `yappi`.
 """
+import json
 import resource
 import time
+from dataclasses import asdict, dataclass
 from typing import Any, Callable, Optional
 
 from fastapi import FastAPI
@@ -21,8 +23,20 @@
 TIMER_ATTRIBUTE = "__fastapi_utils_timer__"
 
 
+@dataclass
+class TimingInfo:
+    cpu_ms: float
+    wall_ms: float
+    name: Optional[str] = None
+    note: Optional[str] = None
+
+
 def add_timing_middleware(
-    app: FastAPI, record: Optional[Callable[[str], None]] = None, prefix: str = "", exclude: Optional[str] = None
+    app: FastAPI,
+    record: Optional[Callable[[str], None]] = None,
+    prefix: str = "",
+    exclude: Optional[str] = None,
+    format_message: Optional[Callable[[TimingInfo], Any]] = None,
 ) -> None:
     """
     Adds a middleware to the provided `app` that records timing metrics using the provided `record` callable.
@@ -42,7 +56,7 @@ def add_timing_middleware(
     @app.middleware("http")
     async def timing_middleware(request: Request, call_next: RequestResponseEndpoint) -> Response:
         metric_name = metric_namer(request.scope)
-        with _TimingStats(metric_name, record=record, exclude=exclude) as timer:
+        with _TimingStats(metric_name, record=record, exclude=exclude, format_message=format_message) as timer:
             setattr(request.state, TIMER_ATTRIBUTE, timer)
             response = await call_next(request)
         return response
@@ -65,6 +79,23 @@ def record_timing(request: Request, note: Optional[str] = None) -> None:
         raise ValueError("No timer present on request")
 
 
+def default_formatter(info: TimingInfo) -> str:
+    """
+    Default message formatter
+    """
+    message = f"TIMING: Wall: {info.wall_ms:6.1f}ms | CPU: {info.cpu_ms:6.1f}ms | {info.name}"
+    if info.note is not None:
+        message += f" ({info.note})"
+    return message
+
+
+def json_formatter(info: TimingInfo) -> str:
+    """
+    Format logged messages as JSON
+    """
+    return json.dumps(asdict(info))
+
+
 class _TimingStats:
     """
     This class tracks and records endpoint timing data.
@@ -81,9 +112,14 @@ class _TimingStats:
     """
 
     def __init__(
-        self, name: Optional[str] = None, record: Callable[[str], None] = None, exclude: Optional[str] = None
+        self,
+        name: Optional[str] = None,
+        record: Callable[[str], None] = None,
+        exclude: Optional[str] = None,
+        format_message: Optional[Callable[[TimingInfo], Any]] = None,
     ) -> None:
         self.name = name
+        self.format_message = format_message or default_formatter
         self.record = record or print
 
         self.start_time: float = 0
@@ -124,11 +160,8 @@ def emit(self, note: Optional[str] = None) -> None:
         """
         if not self.silent:
             self.take_split()
-            cpu_ms = 1000 * self.cpu_time
-            wall_ms = 1000 * self.time
-            message = f"TIMING: Wall: {wall_ms:6.1f}ms | CPU: {cpu_ms:6.1f}ms | {self.name}"
-            if note is not None:
-                message += f" ({note})"
+            info = TimingInfo(name=self.name, wall_ms=1000 * self.time, cpu_ms=1000 * self.cpu_time, note=note)
+            message = self.format_message(info)
             self.record(message)
 
 

pyproject.toml

@@ -91,7 +91,7 @@ exclude = '''
 [tool.isort]
 line_length = 120
 known_first_party = ["fastapi-utils", "tests"]
-multi_line_output = 3
+# multi_line_output = 3
 include_trailing_comma = true
 force_grid_wrap = 0
 combine_as_imports = true

tests/test_timing.py

@@ -1,3 +1,4 @@
+import json
 from pathlib import Path
 
 import pytest
@@ -7,7 +8,7 @@
 from starlette.staticfiles import StaticFiles
 from starlette.testclient import TestClient
 
-from fastapi_utils.timing import add_timing_middleware, record_timing
+from fastapi_utils.timing import TimingInfo, add_timing_middleware, json_formatter, record_timing
 
 app = FastAPI()
 add_timing_middleware(app, exclude="untimed")
@@ -100,3 +101,53 @@ def test_recording_fails_without_middleware() -> None:
     with pytest.raises(ValueError) as exc_info:
         client3.get("/")
     assert str(exc_info.value) == "No timer present on request"
+
+
+app4 = FastAPI()
+add_timing_middleware(app4, format_message=json_formatter)
+
+
+@app4.get("/json-timed")
+def get_json_timed() -> None:
+    pass
+
+
+client4 = TestClient(app4)
+
+
+def test_timing_json_formatter(capsys: CaptureFixture) -> None:
+    client4.get("/json-timed")
+    out, err = capsys.readouterr()
+    assert err == ""
+    assert out.startswith("{")
+    json_out = json.loads(out)
+    assert json_out["name"]
+    assert json_out["cpu_ms"] > 0.0
+    assert json_out["wall_ms"] > 0.0
+    assert json_out["note"] is None
+
+
+app5 = FastAPI()
+
+
+def custom_formatter(info: TimingInfo) -> str:
+    return f"CPU({info.cpu_ms}), WALL({info.wall_ms})"
+
+
+add_timing_middleware(app5, format_message=custom_formatter)
+
+
+@app5.get("/custom-timed")
+def get_alt_timed() -> None:
+    pass
+
+
+client5 = TestClient(app5)
+
+
+def test_timing_custom_formatter(capsys: CaptureFixture) -> None:
+    client5.get("/custom-timed")
+    out, err = capsys.readouterr()
+    assert err == ""
+    assert out.startswith("CPU(")
+    assert "WALL(" in out