Findings¶
The profiler records what happened. The detectors say what is wrong with it.
duplicate_count = 11 is a number you have to interpret. "The same statement
ran twelve times from repository.py:20, and the query before it returned
twelve rows" is a finding you can act on. Every recorded request is run
through the detectors once, after the response has gone out, and what they
conclude appears as Findings at the top of the request detail page, as a
badge in the request list, and under problems in the JSON.
What is detected¶
N+1 query¶
The same statement, repeated from the same line.
Three conditions have to hold, and the third is the one nothing else can do:
- at least
n_plus_one_countexecutions (five by default), - occupying at least
n_plus_one_msof non-overlapping time (zero by default — see below), - all issued through one shared application frame.
That last test is why the finding can name a line rather than a query. The deepest frame every execution passed through is the loop, and the finding is fingerprinted on it. The statement that ran immediately before the repeats is reported as well: those twelve queries exist because that one returned twelve rows, and seeing both together is usually the whole diagnosis.
Repetition that fails the shared-frame test is not reported. A serialiser and
a permission check that happen to ask the same question are not a loop, and
sending someone to look for one wastes their afternoon. Transaction
bookkeeping — SAVEPOINT, COMMIT, BEGIN — is excluded for the same
reason: it repeats by nature.
Blocking database call¶
A synchronous driver call made on the event loop.
This is the quiet one. A sync Session inside an async def endpoint raises
nothing, passes its tests, and looks fine in isolation — because in isolation
it is fine. Under concurrency it freezes every other request in flight for
the duration of every query, and the latency lands on endpoints that have
nothing to do with it. A production tracer sees the symptom on the wrong
endpoint and the cause on none.
The profiler can tell the three cases apart because it sees the thread and the greenlet at the moment the query runs:
| How the query ran | Blocking? |
|---|---|
def endpoint (Starlette's worker thread) |
No |
async def + async engine (SQLAlchemy's greenlet yields) |
No |
async def + sync Session |
Yes |
The fix is an async engine with AsyncSession, or
starlette.concurrency.run_in_threadpool, or simply making the endpoint def
instead of async def.
Slow query¶
One statement at or over slow_query_issue_ms (100 ms by default), reported
once per distinct statement however many times it ran.
Why two thresholds default to zero¶
Sentry requires 50 ms of database time before it calls repetition an N+1. That is right for a service watching production, and exactly wrong here.
The value of finding an N+1 in development is that it has not reached production yet — and in development the table has twelve rows, so five hundred repeated queries come back in four milliseconds. A duration floor tuned for production data filters out precisely the findings you still have time to act on. The count and the shared call site are the signal; duration is there to be raised when you profile against a production-sized database.
The same reasoning applies to blocking_query_ms. A synchronous call on the
event loop is the wrong shape whether your development database answers in one
millisecond or the production one takes a hundred.
Fingerprints¶
Every finding carries one:
It is the identity of the problem, not of the request. The same N+1 seen on four hundred requests has one fingerprint — built from the route, the shared frame, and the normalised text of both the repeated statement and the one before it. That is what will let a later release group findings across requests, and what lets CI tell a new problem from a known one today:
known = {"1-n_plus_one_db-20837a7b58c1f5cd"}
found = {p["fingerprint"] for r in requests for p in r["problems"]}
assert not (found - known), "new performance problem"
The leading 1- is the scheme version. It changes if the grouping rule ever
changes, so old and new findings separate visibly instead of merging quietly.
Configuring them¶
install(
app,
detectors=["n_plus_one_db"], # only this one; () for none, None for all
n_plus_one_count=10, # stricter
n_plus_one_ms=100.0, # profiling against production-sized data
slow_query_issue_ms=250.0,
)
Names are in asgi_profiler.DETECTOR_TYPES. An unknown name is ignored rather
than raising — a detector removed in a later release cannot break your
configuration — and ProfilerConfig.unknown_detectors() will tell you which
names went unrecognised.
A detector that raises is logged and skipped, and the rest still run. A profiler that turns a served request into a 500 because it could not decide whether the request was slow has failed at the only thing it must not do.
Running them yourself¶
They are ordinary functions over a recorded profile, with no dependency on configuration, storage or the request:
from asgi_profiler import detect, DetectorSettings
for problem in detect(profile, DetectorSettings(n_plus_one_count=3)):
print(problem.type, problem.title, problem.evidence["frame"])
Which is also how you would use them over a capture file, without the application running at all — see Storage.