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

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"

トリガーも期間もないウィンドウは、プロセス全体での 1 回の実行を意味し、設定が適用されるときに開き、インタプリタ終了時に閉じられる。私はその設定でサーバーを実行し、ループから 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

レジャーは圧倒的にトップの行だ。order ビューと place は合計時間が長くセルフタイムが短い。これは単一ツリーが語ったのと同じ話で、今は最小値と最大値が付いた 20 件のオーダーにわたる。errors 列は、ゲートウェイで発生した 10 件の却下されたカードを 2 回示しており、一度はゲートウェイで発生し、一度はサービスがそれを逃した。同じレポートを、同じファイルから、毎時リセットされた合計値で生成できる。これは、ウィンドウにスケジュールを与えることで可能になる。スケジュールされたトレースページ でその方法をカバーしており、ここでは省略する。

誰にとって遅いのか

エンドポイントは、しばしば特定のテナント、アカウント、またはリクエスト ID にとって遅いことがあるが、ミドルウェアはどのヘッダーがそれを持っているかを知ることはできない。annotate() は値をインフライトイベントの data にマージし、無条件に安全に呼び出すことができる。記録が行われていない場合は何もしないため、アプリケーションコードに永続的に残しておくのは合理的だ。ショップでは、リクエストイベントが実行される時点ですでに開かれているため、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}

他のテナントのオーダーはすべてゲートウェイで却下され、レジャーに到達しなかったため、ミリ秒単位で終わっている。同じ式は、events.matching() を介してテストでアサートするリクエストを選択し、プリンターの周りの Filter はライブビューを 1 つのテナントのリクエストに絞り込む。

より安価な代替手段

上記すべては期間を保持していた。時には答えは単なる数値であり、Counter コレクタは操作が開始されるときにそれをカウントし、それ以外は何も保持しない。これにより、テストスイート全体で実行しても十分安価になる。データベースレイヤーの execute を一度バインドし、カウンターを登録し、フィクスチャで各テストにクエリ予算を与えれば、古典的な N+1 リグレッションは、遅くなっただけのテストとして通り抜けるのではなく、数値が付いて失敗する。アドホックトレースページの コレクタセクション にその例がすべて記載されている。

これまでのすべてのトレースは、人にレンダリングされるか、ファイルに書き込まれた。次のステップは、ショップが実行中に同じイベントをトレースバックエンドにフィードすることだ。