{
"markdown": "\n\n\n\n# wherewent\n\n### Where did the time go? Find out in one command.\n\n**A zero-config recorder that answers \"why did this Python batch job take so long?\"**\n\nRun it from your shell — or as an **[MCP server](#use-it-as-an-mcp-server-agent-native)** an AI agent invokes directly.\n\n[](https://pypi.org/project/wherewent/)\n[](https://pypi.org/project/wherewent/)\n[](LICENSE)\n[](https://github.com/habibafaisal/wherewent/actions/workflows/ci.yml)\n\n```bash\nwherewent run python your_job.py\n```\n\n
\n\n---\n\n## The 0.4ms query that costs you 5 minutes\n\nA query can be individually fast — `0.4ms` — and still sink your job, because it's\ncalled **500,000 times from a single line of code**. Your app burns 300 seconds on\nround-trips while Postgres itself only worked for 80. Every profiler you've tried shows\nyou *\"time spent in psycopg\"* and stops there.\n\n**wherewent shows you the calling pattern.** It groups queries by shape, counts how\noften each shape ran, sums the wall time, and points at the exact `file:line` in *your*\ncode that fired it — then tells you, in plain English with the arithmetic shown, what to\ndo about it.\n\n```\n====================================================================================================\nwherewent — SQL flight recorder\n----------------------------------------------------------------------------------------------------\nwall: 26.15s cpu: 25.41s (97% CPU busy) queries: 20,004 commits: 20,001 rollbacks: 1\nin-DB time: 5.46s (20.9% of wall; app-observed: includes network+driver+server)\ncommit time: 9.06s total rows: 20,000\nrecording added ~1.81s (~6.9% of wall)\n====================================================================================================\nQUERY GROUP CALLS TOTAL MEDIAN CALL SITE\n----------------------------------------------------------------------------------------------------\nINSERT INTO events (name, value) VALUES (?, ?) 20,000 5.46s 0.24ms demo/naive_job.py:65 in main\nSELECT count(*) AS count_1 FROM events 1 0.00s 0.16ms demo/naive_job.py:71 in main\n====================================================================================================\nFINDINGS\n----------------------------------------------------------------------------------------------------\n1. [R1+R2] commit-per-row loop\n 20,000 calls x 0.24ms median ~= 5.5s = 21% of 26.1s wall, at demo/naive_job.py:65. Batch it.\n 20,001 commits for 20,000 rows (1.0 rows/commit), 9.1s in commit = 35% of wall. Batch to 1,000+ rows/txn.\n ~= 14.5s attributable\n====================================================================================================\n```\n\n## Why it's different\n\n| | Sampling profilers | APM / tracing | **wherewent** |\n|---|:---:|:---:|:---:|\n| Zero code changes | ✅ | ❌ | ✅ |\n| Groups queries by shape | ❌ | ⚠️ | ✅ |\n| Blames *your* call site | ⚠️ | ⚠️ | ✅ |\n| Tells you the fix | ❌ | ❌ | ✅ |\n| Runs anywhere, no server | ✅ | ❌ | ✅ |\n| Works on a Ctrl-C'd partial run | ❌ | ⚠️ | ✅ |\n\n## Install\n\n```bash\npip install wherewent\n```\n\nThat's it — the recorder is **pure standard library**. You only need SQLAlchemy\nbecause *your job* already uses it.\n\n## Use it\n\nWrap any command. Your script runs **completely unmodified** — no imports, no decorators,\nno config:\n\n```bash\nwherewent run python your_job.py --some arg\nwherewent run python -m your_package\nwherewent run --save run.json python your_job.py # also dump machine-readable JSON\n```\n\n- The report prints to **stderr** at exit; your job's own stdout/stderr pass through untouched.\n- **Ctrl-C still produces a report.** Sampling the first 5 minutes of a 14-hour job is the\n main use case — partial data is the point.\n- **Peek without stopping.** Send `SIGUSR1` (`kill -USR1 `) for a partial snapshot mid-run,\n or run with `WHEREWENT_INTERVAL=30` to print one every 30s. The job keeps going.\n- **Works on async SQLAlchemy.** Queries run inside a greenlet with no user frames on the\n stack, so naive stack-walking blames nothing; wherewent attributes them to your real call\n site anyway (`AsyncSession` / `AsyncConnection`).\n- **It can never crash or corrupt your job.** Every hook body is wrapped so the recorder\n fails silent rather than taking your run down with it.\n- **It never records your data.** Only query *shapes* and *counts* are kept — literal\n values and bind parameters are stripped before anything is stored.\n\n### Try the built-in demo\n\n```bash\ngit clone https://github.com/habibafaisal/wherewent && cd wherewent\npip install -e \".[dev]\"\nwherewent run python demo/naive_job.py # watch the R1+R2 finding fire\npython demo/benchmark.py # naive vs fixed, with the overhead gate\n```\n\n## Use it as an MCP server (agent-native)\n\n**wherewent ships a [Model Context Protocol](https://modelcontextprotocol.io) (MCP) server**, so\nan AI agent can invoke it directly the moment a job is slow and get back machine-readable findings\n— instead of reading raw query logs and reasoning its way to the same conclusion. It is listed in\nthe official [MCP Registry](https://registry.modelcontextprotocol.io) as\n`io.github.habibafaisal/wherewent`.\n\nInstall with the `[mcp]` extra (this pulls in the MCP SDK; the core recorder stays pure-stdlib)\nand run the **stdio** server:\n\n```bash\nuvx --from 'wherewent[mcp]' wherewent-mcp\n# or: pip install 'wherewent[mcp]' && wherewent-mcp\n```\n\n**Transport:** stdio. **Tools exposed:**\n\n| MCP tool | What it does |\n|---|---|\n| `analyze_job(command, unit_function?, timeout_s=600)` | 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`). |\n| `explain_run(path)` | Return the enriched findings from a JSON file already produced by `wherewent run --save` — no re-run. |\n\nEach finding carries `fix`, `call_site`, `calls`, `wall_fraction`, and an `evidence` object an\nagent can act on and cite. Wire it into any MCP client (e.g. Claude Desktop) via config:\n\n```json\n{\n \"mcpServers\": {\n \"wherewent\": {\n \"command\": \"uvx\",\n \"args\": [\"--from\", \"wherewent[mcp]\", \"wherewent-mcp\"]\n }\n }\n}\n```\n\nA `Dockerfile` at the repo root builds this same stdio server for container-based MCP hosts.\n\n## Name your unit of work\n\n\"81,749 queries\" is hard to judge. **\"135 queries per receivable\"** tells an engineer\ninstantly that the architecture is chatty. Name the unit your job processes and wherewent\nreports the economics of *one* — median duration, queries/commits/rows per unit, and how\nthe cost trends as the run progresses:\n\n```bash\n# Zero-config: name a function; every top-level call is one unit\nwherewent run --unit-function myapp.jobs:process_receivable python run.py\n```\n\n```python\n# Or mark the unit in code (same machinery, same report)\nimport wherewent\nfor receivable in book:\n with wherewent.unit(\"receivable\"):\n process(receivable)\n```\n\n```\nUNIT: myapp.jobs:process_receivable (1,203 units)\n----------------------------------------------------------------------------------------------------\n median duration 341 ms queries/unit 135 (median)\n commits/unit 1.0 rows/unit 46.0\n GROWTH\n units 1–100 220 ms/unit\n units (last 100) 379 ms/unit\n queries 1–100 98 queries/unit\n queries (last 100) 171 queries/unit\n trend +72% slower over the run\n query trend +74% more queries/unit over the run ← R6 fires\n```\n\nR6 fires on **either** slope. That matters for a compute-bound job: if the clock stays flat but\nqueries/unit climbs, the duration trend reads `flat` and only the query trend exposes the problem —\nso wherewent reports both and says plainly that the pattern is a *scalability* risk rather than the\ncurrent wall-clock bottleneck.\n\nThe growth trend is why a *sampled* run is honest: it shows cost-per-unit **rising**, so you\nknow the full run will be worse than a linear extrapolation — the thing a totals-only profiler\ncan never tell you. Per-unit counts are exact even under concurrent async units; nothing but\nshapes and counts is ever recorded.\n\n## How it works\n\n1. **Injects itself** into the target process via a `PYTHONPATH` sitecustomize shim — no\n changes to your code, no wrapper imports.\n2. **Listens at the class level** — `event.listen(sqlalchemy.engine.Engine, ...)` — so\n *every* engine your app creates is captured automatically, config-free.\n3. **Normalizes each statement** into a query *group*: literals, bind params, `IN`-lists\n and multi-row `VALUES` collapse, so a million distinct inserts become one honest row.\n4. **Resolves the call site** by walking the stack past library frames to the first line\n of *your* code — cheaply: cached by filename, full stacks only for the first 5 samples\n per group, so the hot path stays cheap enough to hit its overhead budget.\n5. **Fires deterministic findings** from three rules, each showing its arithmetic.\n\n### The findings engine\n\n| Rule | Fires when | Tells you |\n|---|---|---|\n| **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`). |\n| **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. |\n| **R3 — DB-wait bound** | in-DB time > 60% of wall, CPU busy < 30% | The job is round-trip bound, not compute bound. |\n| **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. |\n| **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. |\n| **R6 — rising per-unit cost** | per-unit **time** *or* **queries/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. |\n\nFindings that share a root cause **merge** (e.g. `R1+R2`), everything under 5% of wall is\nsuppressed, and at most the top 3 are shown — ranked by seconds attributable. **R4** catches\nthe case a per-group threshold can't: an N+1 pattern spread across a SELECT + UPDATE + INSERT\nthat individually look innocent but fire as one unit each loop — and, since v0.3, it fires on\npatterns that **scale** even when one-time setup costs make them look small on a short sample run.\n\n**Every number is honest.** Query times are labelled *app-observed* (they include network,\ndriver, and server time — not just Postgres). Anything that can't be measured prints `—`,\nnever a guess. wherewent even times *its own hooks* and reports the overhead it added.\n\n## Roadmap — help wanted 🙌\n\nwherewent is built to grow **beyond SQLAlchemy**. Seven of its eight modules —\nnormalization, call-site resolution, the stats model, the rules engine, the report, the\nCLI, and the injection shim — are already **framework-agnostic**. They operate on a plain\n`RunSnapshot` of query events. Only `recorder.py`, which binds SQLAlchemy's event system,\nis framework-specific.\n\n**That means a new backend is a well-contained contribution:** capture query\nstart/end/rowcount/txn events from another driver, feed the same `RunSnapshot`, and the\nentire findings-and-report pipeline works for free. Good first backends:\n\n- [x] **Async SQLAlchemy** — call-site attribution through the greenlet boundary *(v0.2.0)*\n- [x] **Work-unit-aware profiling** — per-unit economics + growth trend *(v0.3.0)*\n- [ ] **Execution-pattern findings** *(the next big one — help wanted)* — today wherewent\n clusters the queries that fire together each iteration (R4). Next: **reconstruct the ordered,\n possibly nested workflow** behind them and name it, e.g.\n ```\n For each receivable:\n For each audit event ×23:\n SELECT chain_state → SELECT payload → INSERT payload → INSERT audit_event → UPDATE chain_state\n Finding: serialized audit-append loop — 23 repetitions/receivable, ≈115 statements/receivable,\n 58% of DB activity, at process_receivable → emit_firing → append_event.\n ```\n This is a real step past ordinary N+1 detection (Sentry/Scout find repeated single-shape\n queries; this would find multi-operation workflows spanning several SQL shapes and functions):\n read→modify→write loops, serialize→insert→commit per item, whole-state snapshots after every\n mutation, growing-history scans, and CPU rising with item position. Needs an ordered per-unit\n event log + repeated-subsequence mining, kept under the overhead gate.\n- [ ] **Raw `psycopg` / `psycopg2`** — cursor subclass or connection factory hook\n- [ ] **Raw `asyncpg`** (outside SQLAlchemy) — the async execution path\n- [ ] **Django ORM** — via `connection.execute_wrapper`\n- [ ] **Generic DB-API 2.0** — a monkeypatch-free `Cursor` proxy\n- [ ] More findings rules (lock-wait, seq-scan heuristics)\n\nSee [`CONTRIBUTING.md`](CONTRIBUTING.md) for the backend contract and the **< 15% overhead\ngate** that every capture path must pass.\n\n## Limitations (today)\n\n- SQLAlchemy **2.x** (sync **and** async ORM/Core; 1.4 may work). Raw `asyncpg` *outside*\n SQLAlchemy is not attributed yet.\n- Single process — no multiprocessing fan-out.\n- Query times are app-observed (network + driver + server), by design.\n- Commit timing is obtained by wrapping the dialect's commit; if that wrap fails it prints `—`.\n- Per-iteration ratios are **estimates** (labelled `≈`) inferred from co-occurring query\n counts — shown only when the signal is strong, never guessed.\n- Per-unit **counts** (`--unit-function` / `wherewent.unit()`) are exact even under concurrent\n async units; per-unit **duration** is wall time and may overlap when units run concurrently —\n the common sequential-loop case is exact.\n- **R6's attributed seconds are a deterministic lower-bound estimate**, not a measurement. The\n excess queries per unit are priced at the run's *mean* per-query DB time, so if the extra\n queries are cheaper than average the true cost is higher (and vice versa). It is computed from\n exact integer query counts rather than the clock, so it is reproducible run to run — but R6's\n claim is the *slope*, not the seconds.\n- **ORM flush attribution.** Queries emitted by a `session.flush()`/`commit()` all resolve to that\n one call site, so R4 can group unrelated writes under a single \"workflow\". When a cluster's\n writes share one source line, wherewent labels it as possibly a single flush rather than\n claiming you can collapse it — it will not tell you to batch something already batched.\n- Per-group **median** is a bounded *sample* median (reservoir of 5,000 executions per group) so\n memory stays flat on million-query runs. `calls` and `total_time` remain exact.\n- **Commit vs rollback time are reported separately.** SQLAlchemy's pool issues a rollback on\n every connection check-in, so rollback time is labelled *(incl. pool resets)* and is never\n folded into commit time.\n- Findings describe **where the time goes and how it scales** — on a CPU-bound run they say so\n explicitly, rather than implying that fixing the SQL will speed up this run.\n\nThese are the honest edges of a validation prototype, not permanent walls — see the roadmap.\n\n## Contributing\n\nContributions are very welcome — new backends, new rules, docs, bug reports. Start with\n[`CONTRIBUTING.md`](CONTRIBUTING.md), open an issue to discuss anything substantial, and\nrun `pytest && python demo/benchmark.py` before you push.\n\n## License\n\n[MIT](LICENSE) © 2026 Habiba Faisal\n",
"bytes": 16889,
"sha": "e78d577adcfcda96b645d70dd25a8f6ee269c5fe875212f802b007e65da109c4",
"repo_slug": "habibafaisal/wherewent",
"fonte": "repo",
"truncated": false,
"api": "https://agentalog.com/api/listings/mcp_io_github_habibafaisal_wherewent_870de57b/readme"
}