From 7aa3372807dab5faec696c806c92be236d984bec Mon Sep 17 00:00:00 2001 From: Conor Heine Date: Wed, 9 Dec 2020 11:14:17 -0800 Subject: [PATCH] Timing middleware: add support for alternate message formatters --- CONTRIBUTING.md | 2 +- docs/contributing.md | 2 +- docs/src/timing2.py | 54 ++++++++++++++++++++++++++++ docs/user-guide/timing-middleware.md | 54 ++++++++++++++++------------ fastapi_utils/timing.py | 49 ++++++++++++++++++++----- pyproject.toml | 2 +- tests/test_timing.py | 53 ++++++++++++++++++++++++++- 7 files changed, 181 insertions(+), 35 deletions(-) create mode 100644 docs/src/timing2.py diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index 864830c7..93d18954 100644 --- a/CONTRIBUTING.md +++ b/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`. diff --git a/docs/contributing.md b/docs/contributing.md index 864830c7..93d18954 100644 --- a/docs/contributing.md +++ b/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`. diff --git a/docs/src/timing2.py b/docs/src/timing2.py new file mode 100644 index 00000000..a661c54e --- /dev/null +++ b/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") +# + +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} diff --git a/docs/user-guide/timing-middleware.md b/docs/user-guide/timing-middleware.md index c8ac2f1c..81c9d3ba 100644 --- a/docs/user-guide/timing-middleware.md +++ b/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 - `yappi`, - 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 +`yappi`, +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. \ No newline at end of file +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!} +``` diff --git a/fastapi_utils/timing.py b/fastapi_utils/timing.py index 676ba1b8..ab5a81cf 100644 --- a/fastapi_utils/timing.py +++ b/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) diff --git a/pyproject.toml b/pyproject.toml index 750a4ceb..2865c31a 100644 --- a/pyproject.toml +++ b/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 diff --git a/tests/test_timing.py b/tests/test_timing.py index 494462ce..fed30863 100644 --- a/tests/test_timing.py +++ b/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