waterfall-log 0.1.7

Request waterfall tracing for Starlette-compatible ASGI applications

waterfall-log

waterfall-log is a small Python library for Starlette-compatible applications that prints a request waterfall to the console after every HTTP request.

It is designed for FastAPI and other ASGI apps built on Starlette, and it focuses on two things:

• capturing the Python call tree for one request
• making the slowest parts obvious in the console output

What it does

For each HTTP request, the middleware:

• profiles Python function calls in the active request task
• builds a nested call tree with timestamps
• prints a waterfall-style timeline to the configured output stream
• reports the hottest frames by inclusive and self time
• focuses on frames from your application code by default, not FastAPI, Starlette, or other helper libraries
• collapses repeated low-impact calls below 0.1% of total request time so the output stays readable
• compresses linear wrapper chains when each frame spends less than 0.1% of total request time in its own body
• shows an ASCII tree prefix next to each function so nested call paths are easier to read

Install

pip install waterfall-log

Quick start

from fastapi import FastAPI

from waterfall_log import WaterfallMiddleware

app = FastAPI()
app.add_middleware(WaterfallMiddleware)


@app.get("/hello")
async def hello() -> dict[str, str]:
    return {"message": "hello"}

By default, the middleware captures frames from the current working directory and skips framework and dependency code. Additional optional parameters are available to configure the waterfall-log to your needs.

Signature:

app.add_middleware(
  WaterfallMiddleware,
  stream=None,
  width=60,
  hotspot_count=5,
  max_nodes=5000,
  collapse_below_percent=0.1,
  collapse_chain_self_below_percent=0.1,
  include_paths=None,
  exclude_paths=None,
)

Optional parameters:

• stream: Output stream used for the rendered waterfall. Defaults to standard output.
• width: Width of the waterfall timeline in characters.
• hotspot_count: Number of hottest frames to show in the Hotspots section.
• max_nodes: Maximum number of profiled call nodes captured for a single request.
• collapse_below_percent: Collapses repeated low-impact calls when their total share of request time is below this percentage.
• collapse_chain_self_below_percent: Compresses linear wrapper chains when each frame spends less than this percentage in its own body.
• include_paths: List of filesystem roots to include in the profile. Defaults to the current working directory.
• exclude_paths: Additional filesystem roots to exclude from profiling on top of the built-in library and virtual environment exclusions.

Run the sample app:

poetry run python sample_app.py

It prints a small startup banner with the request URL and a ready-to-run curl command.

Then call:

curl http://127.0.0.1:8000/report/42

Example output:

Request 200 GET /report/42 took 86.54 ms
Hotspots
  38.12 ms total | 36.89 ms self  sample_app.py:24 load_line_items
  21.07 ms total | 20.81 ms self  sample_app.py:36 render_summary
Waterfall
    0.00 ms |############################################################|   86.54 ms 100.0% GET /report/42
    1.14 ms | ###                                                        |    4.93 ms   5.7% sample_app.py:51 compute_discount
    7.03 ms |     ##########################                             |   38.12 ms  44.0% sample_app.py:24 load_line_items  <<< hottest
   49.82 ms |                                  ###############          |   21.07 ms  24.3% sample_app.py:36 render_summary

Optional environment variables for the demo app

WATERFALL_DEMO_HOST=0.0.0.0   
WATERFALL_DEMO_PORT=9000   
WATERFALL_DEMO_RELOAD=1   

Notes

• The profiler automatically isolates the active asyncio task, so overlapping requests handled on the same event loop do not share one trace.
• Work executed in background threads or native extensions is not profiled directly. Time spent there is still visible in the waiting parent frame.
• The middleware only traces HTTP requests. WebSocket and lifespan scopes pass through unchanged.

Poetry workflow

Install dependencies for local work:

poetry install --with dev,demo

Run tests:

poetry run pytest

Build publishable artifacts:

poetry build

Check package metadata:

poetry check

Publish to PyPI:

poetry config pypi-token.pypi <token>
poetry publish --build

Publish to TestPyPI:

poetry config repositories.testpypi https://test.pypi.org/legacy/
poetry publish --build --repository testpypi