Add timing docs, clarify public timing API, and update deps

docs/release-notes.md

@@ -1,6 +1,10 @@
 ## Latest changes
 
-* Fix bug with ordering of routes in a CBV router
+## 0.2.0
+
+* Make some of the functions/classes in `fastapi_utils.timing` private to clarify the intended public API
+* Add documentation for `fastapi_utils.timing` module 
+* Fix bug with ordering of routes in a CBV router 
 
 ## 0.1.1
 

docs/src/timing1.py

@@ -0,0 +1,56 @@
+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.timing import add_timing_middleware, record_timing
+
+logging.basicConfig(level=logging.INFO)
+logger = logging.getLogger(__name__)
+
+app = FastAPI()
+add_timing_middleware(app, record=logger.info, prefix="app", exclude="untimed")
+static_files_app = StaticFiles(directory=".")
+app.mount(path="/static", app=static_files_app, name="static")
+
+
+@app.get("/timed")
+async def get_timed() -> None:
+    await asyncio.sleep(0.05)
+
+
+@app.get("/untimed")
+async def get_untimed() -> None:
+    await asyncio.sleep(0.1)
+
+
+@app.get("/timed-intermediate")
+async def get_with_intermediate_timing(request: Request) -> None:
+    await asyncio.sleep(0.1)
+    record_timing(request, note="halfway")
+    await asyncio.sleep(0.1)
+
+
+TestClient(app).get("/timed")
+# INFO:__main__:TIMING: Wall:   53.0ms
+#   | CPU:    1.2ms
+#   | app.__main__.get_timed
+
+TestClient(app).get("/untimed")
+# <nothing logged>
+
+TestClient(app).get("/timed-intermediate")
+# INFO:__main__:TIMING: Wall:  105.3ms
+#   | CPU:    0.4ms
+#   | app.__main__.get_with_intermediate_timing (halfway)
+# INFO:__main__:TIMING: Wall:  206.7ms
+#   | CPU:    1.1ms
+#   | app.__main__.get_with_intermediate_timing
+
+TestClient(app).get("/static/test")
+# INFO:__main__:TIMING: Wall:    1.6ms
+#   | CPU:    1.6ms
+#   | StaticFiles<'static'>

docs/user-guide/timing-middleware.md

@@ -2,4 +2,60 @@
 
 ---
 
-Documentation coming soon!
+The `fastapi_utils.timing` module provides basic profiling functionality that could be
+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).
+
+* `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.
+
+    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.
+
+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): 
+
+```python hl_lines="15 37 42 45 53"
+{!./src/timing1.py!}
+```
+
+## Recording intermediate timings
+
+In the above example, you can see the `get_with_intermediate_timing` function used in
+the `/timed-intermediate` endpoint to record an intermediate execution duration:
+
+```python hl_lines="33 46 47 48"
+{!./src/timing1.py!}
+```
+
+Note that this requires the app that generated the `Request` instance to have had the timing middleware
+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.

fastapi_utils/timing.py

@@ -16,9 +16,70 @@
 from starlette.requests import Request
 from starlette.responses import Response
 from starlette.routing import Match, Mount
+from starlette.types import Scope
 
+TIMER_ATTRIBUTE = "__fastapi_utils_timer__"
+
+
+def add_timing_middleware(
+    app: FastAPI, record: Optional[Callable[[str], None]] = None, prefix: str = "", exclude: Optional[str] = None
+) -> None:
+    """
+    Adds a middleware to the provided `app` that records timing metrics using the provided `record` callable.
+
+    Typically `record` would be something like `logger.info` for a `logging.Logger` instance.
+
+    The provided `prefix` is used when generating route names.
+
+    If `exclude` is provided, timings for any routes containing `exclude`
+    as an exact substring of the generated metric name will not be logged.
+    This provides an easy way to disable logging for routes
+
+    The `exclude` will probably be replaced by a regex match at some point in the future. (PR welcome!)
+    """
+    metric_namer = _MetricNamer(prefix=prefix, app=app)
+
+    @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:
+            setattr(request.state, TIMER_ATTRIBUTE, timer)
+            response = await call_next(request)
+        return response
+
+
+def record_timing(request: Request, note: Optional[str] = None) -> None:
+    """
+    Call this function at any point that you want to display elapsed time during the handling of a single request
+
+    This can help profile which piece of a request is causing a performance bottleneck.
+
+    Note that for this function to succeed, the request should have been generated by a FastAPI app
+    that has had timing middleware added using the `fastapi_utils.timing.add_timing_middleware` function.
+    """
+    timer = getattr(request.state, TIMER_ATTRIBUTE, None)
+    if timer is not None:
+        assert isinstance(timer, _TimingStats)
+        timer.emit(note)
+    else:
+        raise ValueError("No timer present on request")
+
+
+class _TimingStats:
+    """
+    This class tracks and records endpoint timing data.
+
+    Should be used as a context manager; on exit, timing stats will be emitted.
+
+    name:
+        The name to include with the recorded timing data
+    record:
+        The callable to call on generated messages. Defaults to `print`, but typically
+        something like `logger.info` for a `logging.Logger` instance would be preferable.
+    exclude:
+        An optional string; if it is not None and occurs inside `name`, no stats will be emitted
+    """
 
-class TimingStats:
     def __init__(
         self, name: Optional[str] = None, record: Callable[[str], None] = None, exclude: Optional[str] = None
     ) -> None:
@@ -31,16 +92,16 @@ def __init__(
         self.end_time: float = 0
         self.silent: bool = False
 
-        if self.name and exclude and (exclude in self.name):
+        if self.name is not None and exclude is not None and (exclude in self.name):
             self.silent = True
 
     def start(self) -> None:
         self.start_time = time.time()
-        self.start_cpu_time = get_cpu_time()
+        self.start_cpu_time = _get_cpu_time()
 
     def take_split(self) -> None:
         self.end_time = time.time()
-        self.end_cpu_time = get_cpu_time()
+        self.end_cpu_time = _get_cpu_time()
 
     @property
     def time(self) -> float:
@@ -50,14 +111,17 @@ def time(self) -> float:
     def cpu_time(self) -> float:
         return self.end_cpu_time - self.start_cpu_time
 
-    def __enter__(self) -> "TimingStats":
+    def __enter__(self) -> "_TimingStats":
         self.start()
         return self
 
     def __exit__(self, exc_type: Any, exc_value: Any, traceback: Any) -> None:
         self.emit()
 
     def emit(self, note: Optional[str] = None) -> None:
+        """
+        Emit timing information, optionally including a specified note
+        """
         if not self.silent:
             self.take_split()
             cpu_ms = 1000 * self.cpu_time
@@ -68,14 +132,35 @@ def emit(self, note: Optional[str] = None) -> None:
             self.record(message)
 
 
-class MetricNamer:
+class _MetricNamer:
+    """
+    This class generates the route "name" used when logging timing records.
+
+    If the route has `endpoint` and `name` attributes, the endpoint's module and route's name will be used
+    (along with an optional prefix that can be used, e.g., to distinguish between multiple mounted ASGI apps).
+
+    By default, in FastAPI the route name is the `__name__` of the route's function (or type if it is a callable class
+    instance).
+
+    For example, with prefix == "custom", a function defined in the module `app.crud` with name `read_item`
+    would get name `custom.app.crud.read_item`. If the empty string were used as the prefix, the result would be
+    just "app.crud.read_item".
+
+    For starlette.routing.Mount instances, the name of the type of `route.app` is used in a slightly different format.
+
+    For other routes missing either an endpoint or name, the raw route path is included in the generated name.
+    """
+
     def __init__(self, prefix: str, app: FastAPI):
         if prefix:
             prefix += "."
         self.prefix = prefix
         self.app = app
 
-    def __call__(self, scope: Any) -> str:
+    def __call__(self, scope: Scope) -> str:
+        """
+        Generates the actual name to use when logging timing metrics for a specified ASGI Scope
+        """
         route = None
         for r in self.app.router.routes:
             if r.matches(scope)[0] == Match.FULL:
@@ -90,36 +175,10 @@ def __call__(self, scope: Any) -> str:
         return name
 
 
-def get_cpu_time() -> float:
-    # taken from timing-asgi
+def _get_cpu_time() -> float:
+    """
+    Generates the cpu time to report. Adds the user and system time, following the implementation from timing-asgi
+    """
     resources = resource.getrusage(resource.RUSAGE_SELF)
     # add up user time (ru_utime) and system time (ru_stime)
     return resources[0] + resources[1]
-
-
-def add_timing_middleware(
-    app: FastAPI, record: Callable[[str], None] = None, prefix: str = "", exclude: Optional[str] = None
-) -> None:
-    """
-    Don't print timings if exclude occurs as an exact substring of the generated metric name
-    """
-    metric_namer = MetricNamer(prefix=prefix, app=app)
-
-    @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:
-            request.state.timer = timer
-            response = await call_next(request)
-        return response
-
-
-def record_timing(request: Request, note: Optional[str] = None) -> None:
-    """
-    Call this function anywhere you want to display performance information while handling a single request
-    """
-    if hasattr(request.state, "timer"):
-        assert isinstance(request.state.timer, TimingStats)
-        request.state.timer.emit(note)
-    else:
-        print("TIMING ERROR: No timer present on request")