wherewent

wherewent run python your_job.py

5分かかる、0.4msのクエリ

クエリ単体は 0.4ms と速くても、1行のコードから50万回呼び出されると、ジョブ全体に大きな負荷を与えることがあります。アプリは往復処理に300秒を費やす一方で、Postgres自体の処理時間は80秒にすぎません。これまで試したどのプロファイラーも、*「psycopgで費やした時間」*を示すだけで、その先はわかりません。

wherewentは呼び出しパターンを可視化します。 クエリを形状ごとにまとめ、それぞれの実行回数と合計経過時間を集計し、クエリを発行したあなたのコード内の正確な file:line を示します。さらに、計算の内訳を示しながら、何をすべきかを平易な言葉で説明します。

====================================================================================================
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
====================================================================================================

他との違い

インストール

pip install wherewent

これだけです。レコーダーは標準ライブラリのみで動作します。SQLAlchemyが必要なのは、ジョブですでに使っている場合だけです。

使い方

任意のコマンドをラップします。スクリプトをまったく変更せずに実行できます。インポートも、デコレーターも、設定も不要です。

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

• 終了時にレポートがstderrへ出力されます。ジョブ自身のstdout／stderrはそのまま出力されます。
• Ctrl-Cで中断してもレポートが生成されます。 14時間のジョブの最初の5分をサンプリングするのが主なユースケースです。部分的なデータこそが重要です。
• 停止せずに途中経過を確認できます。 SIGUSR1（kill -USR1 <pid>）を送ると実行中に部分スナップショットを取得できます。または、WHEREWENT_INTERVAL=30を指定して30秒ごとに出力できます。ジョブはそのまま続行します。
• 非同期SQLAlchemyにも対応しています。 クエリはユーザーコードのフレームがないgreenlet内で実行されるため、単純なスタックウォークでは呼び出し元を特定できません。wherewentなら、実際の呼び出し元（AsyncSession／AsyncConnection）を正しく特定できます。
• ジョブのクラッシュや破損を引き起こすことはありません。 すべてのフック本体をラップしているため、レコーダーに問題が起きてもジョブを停止させず、エラーを通知せずに処理します。
• データを記録することはありません。 保持されるのはクエリの形状と回数だけです。保存前にリテラル値とバインドパラメーターを取り除きます。

組み込みのデモを試す

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

MCP サーバーとして使う（エージェントネイティブ）

wherewent は Model Context Protocol（MCP）サーバーを提供するため、 AI エージェントはジョブの処理が遅いときにすぐ呼び出し、機械可読な分析結果を取得できます。 生のクエリログを読んで同じ結論にたどり着くまで推論する必要はありません。公式の MCP Registry に io.github.habibafaisal/wherewent として登録されています。

[mcp] エクストラを指定してインストールします（MCP SDK が追加されます。コアのレコーダーは純粋な標準ライブラリのままです）。 次に、stdio サーバーを起動します。

uvx --from 'wherewent[mcp]' wherewent-mcp
# or:  pip install 'wherewent[mcp]'  &&  wherewent-mcp

トランスポート: stdio。公開されるツール:

各分析結果には、エージェントが利用・引用できる fix、call_site、calls、wall_fraction、および evidence オブジェクトが含まれます。設定を使って、Claude Desktop などの MCP クライアントに接続できます。

{
  "mcpServers": {
    "wherewent": {
      "command": "uvx",
      "args": ["--from", "wherewent[mcp]", "wherewent-mcp"]
    }
  }
}

リポジトリのルートにある Dockerfile を使うと、コンテナベースの MCP ホスト向けに、同じ stdio サーバーをビルドできます。

作業単位に名前を付ける

「81,749 件のクエリ」だけでは判断が難しいものです。**「売掛金 1 件あたり 135 件のクエリ」**なら、アーキテクチャが過剰に頻繁な通信を行っていることが、エンジニアにすぐ伝わります。ジョブが処理する単位に名前を付けると、wherewent はその単位 1 件あたりのコスト（所要時間の中央値、単位あたりのクエリ数／コミット数／行数）と、実行の進行に伴うコストの傾向を報告します。

# Zero-config: name a function; every top-level call is one unit
wherewent run --unit-function myapp.jobs:process_receivable python run.py

# Or mark the unit in code (same machinery, same report)
import wherewent
for receivable in book:
    with wherewent.unit("receivable"):
        process(receivable)

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 はどちらか一方の傾きでも検出します。これは計算負荷が高いジョブで重要です。処理時間が変わらず、単位あたりのクエリ数だけが増えている場合、処理時間の傾向は flat と表示され、クエリの傾向だけが問題を明らかにします。そのため wherewent は両方を報告し、現在の実時間上のボトルネックではなく、スケーラビリティのリスクであることを明確に伝えます。

コストの増加傾向が分かるため、サンプリングによる実行結果も正確です。単位あたりのコストが増加していることが分かるので、全件実行時のコストは線形外挿よりも大きくなると把握できます。合計値しか示さないプロファイラーでは決して分からないことです。非同期の単位を並行処理している場合でも、単位あたりの件数は正確です。記録されるのは形状と件数だけです。

仕組み

1. PYTHONPATH の sitecustomize シムを通じて、対象プロセスに自身を注入します。コードの変更も、ラッパーのインポートも不要です。
2. クラスレベルでリッスンします。event.listen(sqlalchemy.engine.Engine, ...) を使うため、アプリが作成するすべてのエンジンを、設定不要で自動的に捕捉します。
3. 各ステートメントを正規化してクエリ グループ にまとめます。リテラル、バインドパラメーター、IN リスト、複数行の VALUES は集約されるため、100 万件の異なる挿入も、実態を反映した 1 行になります。
4. ライブラリのフレームを越えてスタックをたどり、あなたのコードの最初の行から呼び出し箇所を特定します。ファイル名でキャッシュし、各グループの最初の 5 サンプルでのみ完全なスタックを取得するため、ホットパスを軽量に保ち、オーバーヘッドの予算内に収めます。
5. 3 つのルールから決定論的な分析結果を生成し、それぞれの計算過程を示します。

検出エンジン

根本原因が同じ検出結果は統合され（例：R1+R2）、実行時間の 5% 未満の項目は 表示されず、上位 3 件までが表示されます。順位は関連する秒数に基づきます。R4 は、 グループごとのしきい値では検出できないケースを捉えます。個別には問題なさそうな SELECT + UPDATE + INSERT が、ループごとにひとまとまりで発生する N+1 パターンです。 また v0.3 以降は、一度だけのセットアップコストによって短いサンプル実行では小さく 見える場合でも、スケールするパターンを検出します。

数値はすべて正確です。 クエリ時間には アプリケーションで観測 とラベルが付き ます（ネットワーク、ドライバー、サーバーの時間を含み、Postgres の時間だけでは ありません）。測定できない項目は推測せず、— と表示します。wherewent は 自身のフックの時間も計測し、追加したオーバーヘッドを報告します。

ロードマップ — ご協力をお願いします 🙌

wherewent は SQLAlchemy の枠を超えて成長できるように構築されています。8 つのモジュールのうち 7 つ（正規化、呼び出し元の解決、統計モデル、ルールエンジン、レポート、CLI、インジェクションシム）は、すでに フレームワークに依存しません。これらは、クエリイベントを含むプレーンな RunSnapshot を処理します。SQLAlchemy のイベントシステムにバインドする recorder.py だけが、フレームワーク固有です。

つまり、新しいバックエンドの追加は範囲を明確に限定できる貢献です。 別のドライバーからクエリの開始／終了／行数／トランザクションイベントを取得し、同じ RunSnapshot に渡せば、検出結果とレポートのパイプライン全体をそのまま利用できます。最初のバックエンドとしておすすめのもの：

• Async SQLAlchemy — greenlet の境界を越えた呼び出し元の特定 (v0.2.0)
• 作業単位を考慮したプロファイリング — 単位ごとのコスト分析と成長傾向 (v0.3.0)
• 実行パターンの検出結果 (次の大きな機能 — ご協力をお願いします) — 現在の wherewent は、各イテレーションで一緒に実行されるクエリをグループ化します（R4）。次の段階では、その背後にある、順序付けられた、場合によっては入れ子になったワークフローを再構成し、名前を付けます。たとえば：

  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.
  

  これは一般的な N+1 検出を超える、実質的な一歩です（Sentry／Scout は形の同じクエリの繰り返しを検出しますが、こちらは複数の SQL 形式と関数にまたがる複数操作のワークフローを検出します）。読み取り→変更→書き込みのループ、項目ごとのシリアライズ→挿入→コミット、各変更後の全状態のスナップショット、増え続ける履歴のスキャン、項目の位置に応じた CPU 使用量の増加などです。オーバーヘッドの上限を守りながら、単位ごとの順序付きイベントログと、繰り返し部分列のマイニングが必要です。
• 生の psycopg／psycopg2 — カーソルのサブクラス化、または接続ファクトリーフック
• 生の asyncpg（SQLAlchemy の外部） — 非同期実行パス
• Django ORM — connection.execute_wrapper 経由
• 汎用 DB-API 2.0 — モンキーパッチを使わない Cursor プロキシ
• その他の検出ルール（ロック待ち、シーケンシャルスキャンのヒューリスティクス）

バックエンドの契約と、すべての取得パスが満たす必要のある オーバーヘッド < 15% の基準については、CONTRIBUTING.md をご覧ください。

制限事項（現時点）

• SQLAlchemy 2.x（同期 および 非同期の ORM/Core。1.4 でも動作する可能性があります）。SQLAlchemy の 外部で使用する生の asyncpg は、まだ計測対象として特定されません。
• 単一プロセスです。マルチプロセスによる並列実行には対応していません。
• クエリ時間は、設計上、アプリケーションから観測した時間（ネットワーク＋ドライバー＋サーバー）です。
• コミット時間は、方言のコミット処理をラップして取得します。ラップに失敗した場合は — と表示されます。
• 反復ごとの比率は推定値（≈ と表示）で、同時に発生したクエリ数から推定します。シグナルが強い場合のみ表示し、推測で値を出すことはありません。
• ユニットごとの件数（--unit-function / wherewent.unit()）は、非同期ユニットが同時実行されても正確です。ユニットごとの所要時間は実時間であり、ユニットが同時実行されると重複する場合があります。一般的な逐次ループのケースでは正確です。
• **R6 の帰属秒数は、決定論的な下限推定値であり、測定値ではありません。**ユニットごとの超過クエリ数には、実行全体のクエリあたり平均 DB 時間を適用します。そのため、追加クエリが平均より短時間で処理される場合は実際のコストのほうが高くなり、逆の場合は低くなります。クロックではなく正確な整数のクエリ数から算出するため、実行ごとに再現可能です。ただし、R6 が示すのは秒数ではなく傾きです。
• ORM のフラッシュ処理の帰属。session.flush()／commit() が発行するクエリはすべて、その呼び出し箇所に帰属するため、R4 は関連のない書き込みを単一の「ワークフロー」としてまとめる場合があります。あるクラスターの書き込みが同じソース行を共有している場合、wherewent はそれらをまとめられると断言せず、単一のフラッシュである可能性があると表示します。すでに一括処理されているものをさらにまとめるよう促すことはありません。
• グループごとの中央値は、有界な標本中央値です（グループごとに最大 5,000 回の実行を保持するリザーバーサンプリング）。そのため、数百万クエリの実行でもメモリー使用量は一定に保たれます。calls と total_time は正確な値です。
• **コミット時間とロールバック時間は別々に報告されます。**SQLAlchemy のプールは、接続がプールに返却されるたびにロールバックを実行するため、ロールバック時間には (プールのリセットを含む) と表示され、コミット時間に合算されることはありません。
• 検出結果では、時間がどこで費やされ、どのように増減するかを示します。CPU バウンドの実行ではその旨を明記し、SQL を修正すれば今回の実行が速くなるかのような誤解を招くことはありません。

これらは検証用プロトタイプの誠実な適用範囲であり、恒久的な制約ではありません。ロードマップをご覧ください。

コントリビューション

コントリビューションを歓迎します。新しいバックエンドやルール、ドキュメント、バグ報告などをお寄せください。まずは CONTRIBUTING.md を確認し、大きな変更については issue を作成して相談してください。プッシュする前に pytest && python demo/benchmark.py を実行してください。

ライセンス

MIT © 2026 Habiba Faisal