Wrapture を使って遅いコードを見つける

Flask ショップの /order エンドポイントが遅い。 ビューはオーダーサービスを呼び出し、サービスはゲートウェイ、そしてレジャーを呼び出す。問題は、その時間のどこに費やされているかだ。 この記事でこの問いに現実的な答えを与えるために、Ledger.record に time.sleep(0.03) を仕込み、記事の残りの部分ではそれを知らなかったふりをする。 いつもの手はストップウォッチだ。サービス呼び出しの前後に perf_counter() を置き、差分をログに出力する。ゲートウェイの周りにもう一組、レジャーの周りにもう一組。 これらのそれぞれは、測定されていることを知らないはずのレイヤーでのコード変更であり、数字は別々のログ行として到着し、それらを目で照合する必要がある。そして、それらのどれもが属するリクエストに紐づいていないため、速いリクエストの中に一つだけ遅いリクエストがあっても、平均値では見えなくなる。 プロファイラは逆の問題を抱えている。プロファイラはプロセス内のすべてのフレームを見るが、そのほとんどはフレームワークの内部であり、リクエストごとに区別することができない。 時間の表示されたツリー 前回の設定では、すでにすべての終了行に経過時間が出力されているため、サーバーを最初に通過したオーダーが答えの大部分となる。 POST /order (webshop.wsgi_app) order() shop:OrderService.place(amount=500, card='<redacted>', tenant='acme') shop:Gateway.charge(amount=500, card='<redacted>') shop:Gateway.charge -> {'id': 'ch_500', 'amount': 500} [8us] shop:Ledger.record(entry="<dict {'id': 'ch_500', 'amount': 500}>") shop:Ledger.record -> 'led_ch_500' [35.1ms] shop:OrderService.place -> {'id': 'ch_500', 'amount': 500} [35.9ms] order -> '<Response 29 bytes [200 OK]>' [36.3ms] webshop.wsgi_app -> '200 OK' [37.3ms, body 10us over 1 chunk] 下から読むと、リクエストは 37.3ms、ビューは 36.3ms、サービスは 35.9ms、レジャーは 35.1ms、ゲートウェイは 8us かかった。 これらの数値は一度の実行結果であり、変動するが、その形状は変わらない。 サービス全体、そしてビュー全体のほとんどはレジャーによるものだ。 サービスとビューが遅いのは、それらが呼び出すもののためだ。レジャー自体が遅い。 この区別、つまり「それ自体が遅い」のか「子を呼び出すために遅い」のか、という区別は、サービス呼び出しの周りの壁時計タイマーでは表現できないものであり、名前がある。 セルフタイムとは、ある操作の実行時間から、観測された子要素が占める時間を除いたものだ。Wrapture は、イベントが閉じられる際に親リンクからこれを計算する。 テストでは、tape.tree(times=True) は両方の数値を表示し、tape.self_time() は一つのイベントに対してそれを取得するため、同じ観測をアサーションに変換して次のリグレッションを捕捉できる。 import wrapture from shop import Gateway, Ledger, OrderService from webshop import app def test_where_the_time_goes(): place = wrapture.binding(OrderService, "place", capture=wrapture.redact("card")) charge = wrapture.binding(Gateway, "charge", capture=wrapture.redact("card")) record = wrapture.binding(Ledger, "record") with wrapture.instrumentation("flask"), wrapture.timeline(place, charge, record) as tape: client = app.test_client() response = client.post("/order", json={"amount": 500, "card": "4111-1111-1111-1111", "tenant": "acme"}) assert response.status_code == 200 print() print(tape.tree(times=True)) order = place.events.assert_once()[0] ledger = record.events.assert_once()[0] assert tape.self_time(order) < 0.1 * order.duration assert tape.self_time(ledger) > 0.9 * order.duration Wrapture.instrumentation("flask") コンテキストは、設定ファイルで名前が付けられたのと同じ Flask インストルメンテーションをブロックにスコープして適用し、タイムラインは 3 つのバインディングが見たものを記録する。 pytest -s で実行すると、ツリーが表示される。 shop:OrderService.place(amount=500, card='<redacted>', tenant='acme') -> {'id': 'ch_500', 'amount': 500} [31.0ms, self 173us] shop:Gateway.charge(amount=500, card='<redacted>') -> {'id': 'ch_500', 'amount': 500} [7us] shop:Ledger.record(entry={'id': 'ch_500', 'amount': 500}) -> 'led_ch_500' [30.8ms] サービスは 31.0ms のうち 173us を自身で費やした。外部のプロファイラは、任意の少数のメソッドに対してこの数値を生成できない。なぜなら、プロファイラはコールスタック全体しか見ないからだ。Wrapture は、イベントが親を知っているため、それを可能にする。 複数のリクエストを横断して 一つのリクエストは逸話に過ぎない。 Aggregate コレクタは、バインドされた場所ごとに 1 行を保持し、開始および完了した操作の数、発生したエラーの数、合計時間、セルフタイム、最速・最遅時間を記録する。これは、プロファイラがランク付けする列であるセルフタイムでソートされる。 イベントは保持しないため、トラフィック量に関わらずメモリ使用量はバインディングの数に制限される。また、引数や結果の値は要求しないため、記録は記録対象がそれだけの場合、キャプチャを完全にスキップする。 コードでシンクとして登録できるが、私が望んだ形状は、サーバーの実行全体に対するレポートであり、設定ファイル内のウィンドウである。 [[window]] name = "stats" report = "stats.txt" [[window.collect]] type = "aggregate" トリガーも期間もないウィンドウは、プロセス全体で一度実行される。設定が適用されたときに開き、インタープリタ終了時に閉じられ、レポートが一つ生成される。 その設定でサーバーを実行し、ループから 30 件のリクエスト（あるテナントへの 10 件のオーダー、別のテナントへの 10 件の拒否されたオーダー、10 件の見積もり）を送信し、停止して、ファイルを読む。 aggregate "aggregate" run 1, 2026-09-01 14:57:29 to 14:57:31 +10:00 (1.6s), pid 87241 7 paths, 120 operations begun, 120 completed, 20 raised calls total self per-call min max errors path 10 358.3ms 358.3ms 35.8ms 30.7ms 39.5ms shop:Ledger.record 30 385.2ms 11.9ms 12.8ms 534us 40.5ms flask.app:Flask.wsgi_app 20 369.8ms 5.7ms 18.5ms 296us 40.1ms webshop:order 20 364.1ms 5.7ms 18.2ms 105us 39.9ms 10 shop:OrderService.place 10 2.2ms 2.2ms 223us 63us 1.6ms flask:render_template 10 3.5ms 1.3ms 354us 188us 1.8ms webshop:quote 20 106us 106us 5us 4us 11us 10 shop:Gateway.charge レジャーは圧倒的な差でトップ行だ。オーダービューとプレイスは合計時間が大きくセルフタイムが小さい。これは単一ツリーが語ったのと同じ話で、今は 20 件のオーダーに最小値と最大値が付加されている。 エラー列は、10 件の拒否されたカードを 2 回示している。一度はゲートウェイが例外を発生させ、もう一度はサービスがそれを逃がしたときだ。 同じレポートを、合計をリセットして毎時生成できる。同じファイルから、ウィンドウにスケジュールを与えることで可能になる。スケジューリングされたトレーシングページがそれをカバーしており、そこでは省略する。 誰にとって遅いのか エンドポイントは、特定のテナント、アカウント、またはリクエストIDにとって遅いことが多い。ミドルウェアは、どのヘッダーがその情報を持っているかを知ることはできない。 annotate() は、インフライトイベントのデータに値をマージする。呼び出しは無条件に安全であり、何も記録されていない場合は何もしないため、アプリケーションコードに永続的に残しておくことが合理的だ。 ショップでは、リクエストイベントが実行される時点ですでに開いているため、before_request フックが自然な場所だ。 @app.before_request def tag_tenant(): wrapture.annotate(tenant=request.headers.get("X-Tenant")) これは、このシリーズでのアプリケーションへの唯一の編集であり、テストシリーズがイベントにコードが知っていることをアタッチするために使用した annotate() と同じだ。 タグはリクエストイベントに乗る。そのため、設定ファイルにプリンターの隣に jsonlines シンクがあれば、ファイルに記録され、遅いリクエストは誰のためのものかによってスライスできる。 $ jq -c 'select(.kind=="request" and .data.tenant=="acme") | {tenant: .data.tenant, path: .data.path, ms: ((.duration*1000*10|round)/10)}' trace.jsonl {"tenant":"acme","path":"/order","ms":35.7} {"tenant":"acme","path":"/order","ms":32.5} {"tenant":"acme","path":"/order","ms":35.9} 他のテナントのオーダーはすべてゲートウェイで拒否され、レジャーに到達しなかったため、約 1 ミリ秒で終わっている。 同じ式は、イベントの matching() を通じて、テストでアサートするリクエストを選択する。プリンターの周りのフィルターは、ライブビューを 1 つのテナントのリクエストに絞り込む。 より安価な代替手段 上記すべては期間を保持していた。時には答えは単なる数値であり、Counter コレクタは操作が開始されるたびにカウントし、それ以外は何も保持しない。そのため、テストスイート全体で実行しても安価だ。 データベースレイヤーのバインド...