Zero-config SQL flight recorder for slow Python/SQLAlchemy jobs: exact call site, count, and fix.
io.github.habibafaisal/wherewent β Model Context Protocol (MCP) Server
The io.github.habibafaisal/wherewent MCP server is described as a zero-config SQL flight recorder for slow Python/SQLAlchemy jobs. It records exact call site information and provides a count, along with a fix, focused on identifying and addressing slow database interactions.
π οΈ Key Features
Zero-config operation
SQL βflight recorderβ for slow Python/SQLAlchemy jobs
Captures exact call site
Provides count
Includes fix information
π Use Cases
Debugging slow Python/SQLAlchemy operations
Locating the exact call site responsible for slow SQL behavior
Using recorded counts to assess frequency
β‘ Developer Benefits
No setup required (βzero-configβ)
Actionable output: call site + count + fix to guide remediation
β οΈ Limitations
Description only references Python/SQLAlchemy and slow jobs; other environments are not specified.
A zero-config recorder that answers "why did this Python batch job take so long?"
Run it from your shell β or as an MCP server an AI agent invokes directly.
bash
wherewent run python your_job.py
The 0.4ms query that costs you 5 minutes
A query can be individually fast β 0.4ms β and still sink your job, because it's
called 500,000 times from a single line of code. Your app burns 300 seconds on
round-trips while Postgres itself only worked for 80. Every profiler you've tried shows
you "time spent in psycopg" and stops there.
wherewent shows you the calling pattern. It groups queries by shape, counts how
often each shape ran, sums the wall time, and points at the exact file:line in your
code that fired it β then tells you, in plain English with the arithmetic shown, what to
do about it.
code
====================================================================================================
wherewent β SQL flight recorder
----------------------------------------------------------------------------------------------------
wall: 26.15s cpu: 25.41s (97% CPU busy) queries: 20,004 commits: 20,001 rollbacks: 1
in-DB time: 5.46s (20.9% of wall; app-observed: includes network+driver+server)
commit time: 9.06s total rows: 20,000
recording added ~1.81s (~6.9% of wall)
====================================================================================================
QUERY GROUP CALLS TOTAL MEDIAN CALL SITE
----------------------------------------------------------------------------------------------------
INSERT INTO events (name, value) VALUES (?, ?) 20,000 5.46s 0.24ms demo/naive_job.py:65 in main
SELECT count(*) AS count_1 FROM events 1 0.00s 0.16ms demo/naive_job.py:71 in main
====================================================================================================
FINDINGS
----------------------------------------------------------------------------------------------------
1. [R1+R2] commit-per-row loop
20,000 calls x 0.24ms median ~= 5.5s = 21% of 26.1s wall, at demo/naive_job.py:65. Batch it.
20,001 commits for 20,000 rows (1.0 rows/commit), 9.1s in commit = 35% of wall. Batch to 1,000+ rows/txn.
~= 14.5s attributable
====================================================================================================
Why it's different
Sampling profilers
APM / tracing
wherewent
Zero code changes
β
β
β
Groups queries by shape
β
β οΈ
β
Blames your call site
β οΈ
β οΈ
β
Tells you the fix
β
β
β
Runs anywhere, no server
β
β
β
Works on a Ctrl-C'd partial run
β
β οΈ
β
Install
bash
pip install wherewent
That's it β the recorder is pure standard library. You only need SQLAlchemy
because your job already uses it.
Use it
Wrap any command. Your script runs completely unmodified β no imports, no decorators,
no config:
bash
wherewent run python your_job.py --some arg
wherewent run python -m your_package
wherewent run --save run.json python your_job.py # also dump machine-readable JSON
The report prints to stderr at exit; your job's own stdout/stderr pass through untouched.
Ctrl-C still produces a report. Sampling the first 5 minutes of a 14-hour job is the
main use case β partial data is the point.
Peek without stopping. Send SIGUSR1 (kill -USR1 <pid>) for a partial snapshot mid-run,
or run with WHEREWENT_INTERVAL=30 to print one every 30s. The job keeps going.
Works on async SQLAlchemy. Queries run inside a greenlet with no user frames on the
stack, so naive stack-walking blames nothing; wherewent attributes them to your real call
site anyway (AsyncSession / AsyncConnection).
It can never crash or corrupt your job. Every hook body is wrapped so the recorder
fails silent rather than taking your run down with it.
It never records your data. Only query shapes and counts are kept β literal
values and bind parameters are stripped before anything is stored.
Try the built-in demo
bash
git clone https://github.com/habibafaisal/wherewent && cd wherewent
pip install -e ".[dev]"
wherewent run python demo/naive_job.py # watch the R1+R2 finding fire
python demo/benchmark.py # naive vs fixed, with the overhead gate
Use it as an MCP server (agent-native)
wherewent ships a Model Context Protocol (MCP) server, so
an AI agent can invoke it directly the moment a job is slow and get back machine-readable findings
β instead of reading raw query logs and reasoning its way to the same conclusion. It is listed in
the official MCP Registry as
io.github.habibafaisal/wherewent.
Install with the [mcp] extra (this pulls in the MCP SDK; the core recorder stays pure-stdlib)
and run the stdio server:
Run a Python/SQLAlchemy job under wherewent and return why it was slow β exact call site, query count, and fix as structured fields. On timeout, partial results are returned (timed_out: true).
explain_run(path)
Return the enriched findings from a JSON file already produced by wherewent run --save β no re-run.
Each finding carries fix, call_site, calls, wall_fraction, and an evidence object an
agent can act on and cite. Wire it into any MCP client (e.g. Claude Desktop) via config:
A Dockerfile at the repo root builds this same stdio server for container-based MCP hosts.
Name your unit of work
"81,749 queries" is hard to judge. "135 queries per receivable" tells an engineer
instantly that the architecture is chatty. Name the unit your job processes and wherewent
reports the economics of one β median duration, queries/commits/rows per unit, and how
the cost trends as the run progresses:
bash
# Zero-config: name a function; every top-level call is one unit
wherewent run --unit-function myapp.jobs:process_receivable python run.py
python
# Or mark the unit in code (same machinery, same report)import wherewent
for receivable in book:
with wherewent.unit("receivable"):
process(receivable)
code
UNIT: myapp.jobs:process_receivable (1,203 units)
----------------------------------------------------------------------------------------------------
median duration 341 ms queries/unit 135 (median)
commits/unit 1.0 rows/unit 46.0
GROWTH
units 1β100 220 ms/unit
units (last 100) 379 ms/unit
queries 1β100 98 queries/unit
queries (last 100) 171 queries/unit
trend +72% slower over the run
query trend +74% more queries/unit over the run β R6 fires
R6 fires on either slope. That matters for a compute-bound job: if the clock stays flat but
queries/unit climbs, the duration trend reads flat and only the query trend exposes the problem β
so wherewent reports both and says plainly that the pattern is a scalability risk rather than the
current wall-clock bottleneck.
The growth trend is why a sampled run is honest: it shows cost-per-unit rising, so you
know the full run will be worse than a linear extrapolation β the thing a totals-only profiler
can never tell you. Per-unit counts are exact even under concurrent async units; nothing but
shapes and counts is ever recorded.
How it works
Injects itself into the target process via a PYTHONPATH sitecustomize shim β no
changes to your code, no wrapper imports.
Listens at the class level β event.listen(sqlalchemy.engine.Engine, ...) β so
every engine your app creates is captured automatically, config-free.
Normalizes each statement into a query group: literals, bind params, IN-lists
and multi-row VALUES collapse, so a million distinct inserts become one honest row.
Resolves the call site by walking the stack past library frames to the first line
of your code β cheaply: cached by filename, full stacks only for the first 5 samples
per group, so the hot path stays cheap enough to hit its overhead budget.
Fires deterministic findings from three rules, each showing its arithmetic.
The findings engine
Rule
Fires when
Tells you
R1 β chatty group
> 1,000 calls, > 10% of wall, median < 5ms
A fast query is called too many times β batch it (executemany / IN-list / JOIN).
R2 β commit-per-row
> 100 commits, < 10 rows/commit, > 5% of wall in commit
You're committing per row β batch to 1,000+ rows per transaction.
R3 β DB-wait bound
in-DB time > 60% of wall, CPU busy < 30%
The job is round-trip bound, not compute bound.
R4 β co-occurring pattern
β₯ 2 query groups fire from the same function AND the pattern scales β many queries/iteration across many iterations, or > 10% of wall once one-time setup is excluded
Several queries fire together every iteration (SELECT + UPDATE + INSERT) β collapse them into one round-trip. Clusters by function, not by line, so a helper that issues its statements on three different lines is still seen as one operation. One-shot (calls == 1) statements are excluded β they're fixed cost, and R5's job. Reports estimated queries-per-iteration, and flags patterns that scale even when a bounded run's clock hides them.
R5 β one-shot heavyweight
a single calls==1 statement > 15% of wall or > 10s absolute
One statement is a huge fixed cost. R1/R3/R4 all look for chattiness and miss it β R5 catches the single most fixable line. The absolute floor matters: 20s is worth cutting whether it's 24% of a sampled run or 1% of the full one.
R6 β rising per-unit cost
per-unit timeorqueries/unit climbs β₯ 1.5Γ from the first 100 units to the last 100 (needs --unit-function/wherewent.unit())
Cost per item grows as the run progresses β accumulating state, unbatched history reads, or a list that grows each loop. Reports the slope (queries/unit early vs late), so a compute-bound job whose query cost is growing still gets caught.
Findings that share a root cause merge (e.g. R1+R2), everything under 5% of wall is
suppressed, and at most the top 3 are shown β ranked by seconds attributable. R4 catches
the case a per-group threshold can't: an N+1 pattern spread across a SELECT + UPDATE + INSERT
that individually look innocent but fire as one unit each loop β and, since v0.3, it fires on
patterns that scale even when one-time setup costs make them look small on a short sample run.
Every number is honest. Query times are labelled app-observed (they include network,
driver, and server time β not just Postgres). Anything that can't be measured prints β,
never a guess. wherewent even times its own hooks and reports the overhead it added.
Roadmap β help wanted π
wherewent is built to grow beyond SQLAlchemy. Seven of its eight modules β
normalization, call-site resolution, the stats model, the rules engine, the report, the
CLI, and the injection shim β are already framework-agnostic. They operate on a plain
RunSnapshot of query events. Only recorder.py, which binds SQLAlchemy's event system,
is framework-specific.
That means a new backend is a well-contained contribution: capture query
start/end/rowcount/txn events from another driver, feed the same RunSnapshot, and the
entire findings-and-report pipeline works for free. Good first backends:
Async SQLAlchemy β call-site attribution through the greenlet boundary (v0.2.0)
Execution-pattern findings(the next big one β help wanted) β today wherewent
clusters the queries that fire together each iteration (R4). Next: reconstruct the ordered,
possibly nested workflow behind them and name it, e.g.
code
For each receivable:
For each audit event Γ23:
SELECT chain_state β SELECT payload β INSERT payload β INSERT audit_event β UPDATE chain_state
Finding: serialized audit-append loop β 23 repetitions/receivable, β115 statements/receivable,
58% of DB activity, at process_receivable β emit_firing β append_event.
This is a real step past ordinary N+1 detection (Sentry/Scout find repeated single-shape
queries; this would find multi-operation workflows spanning several SQL shapes and functions):
readβmodifyβwrite loops, serializeβinsertβcommit per item, whole-state snapshots after every
mutation, growing-history scans, and CPU rising with item position. Needs an ordered per-unit
event log + repeated-subsequence mining, kept under the overhead gate.
Raw psycopg / psycopg2 β cursor subclass or connection factory hook
Raw asyncpg (outside SQLAlchemy) β the async execution path
Django ORM β via connection.execute_wrapper
Generic DB-API 2.0 β a monkeypatch-free Cursor proxy
More findings rules (lock-wait, seq-scan heuristics)
See CONTRIBUTING.md for the backend contract and the < 15% overhead
gate that every capture path must pass.
Limitations (today)
SQLAlchemy 2.x (sync and async ORM/Core; 1.4 may work). Raw asyncpgoutside
SQLAlchemy is not attributed yet.
Single process β no multiprocessing fan-out.
Query times are app-observed (network + driver + server), by design.
Commit timing is obtained by wrapping the dialect's commit; if that wrap fails it prints β.
Per-iteration ratios are estimates (labelled β) inferred from co-occurring query
counts β shown only when the signal is strong, never guessed.
Per-unit counts (--unit-function / wherewent.unit()) are exact even under concurrent
async units; per-unit duration is wall time and may overlap when units run concurrently β
the common sequential-loop case is exact.
R6's attributed seconds are a deterministic lower-bound estimate, not a measurement. The
excess queries per unit are priced at the run's mean per-query DB time, so if the extra
queries are cheaper than average the true cost is higher (and vice versa). It is computed from
exact integer query counts rather than the clock, so it is reproducible run to run β but R6's
claim is the slope, not the seconds.
ORM flush attribution. Queries emitted by a session.flush()/commit() all resolve to that
one call site, so R4 can group unrelated writes under a single "workflow". When a cluster's
writes share one source line, wherewent labels it as possibly a single flush rather than
claiming you can collapse it β it will not tell you to batch something already batched.
Per-group median is a bounded sample median (reservoir of 5,000 executions per group) so
memory stays flat on million-query runs. calls and total_time remain exact.
Commit vs rollback time are reported separately. SQLAlchemy's pool issues a rollback on
every connection check-in, so rollback time is labelled (incl. pool resets) and is never
folded into commit time.
Findings describe where the time goes and how it scales β on a CPU-bound run they say so
explicitly, rather than implying that fixing the SQL will speed up this run.
These are the honest edges of a validation prototype, not permanent walls β see the roadmap.
Contributing
Contributions are very welcome β new backends, new rules, docs, bug reports. Start with
CONTRIBUTING.md, open an issue to discuss anything substantial, and
run pytest && python demo/benchmark.py before you push.