Python のサーバーが遅いとき — py-spy で 5 分以内にボトルネックを探す

Python パフォーマンス バックエンド
読了 5分

Python の API サーバーが遅い。API 診断の記事の区間割りで絞っても「その他のロジック」が大きかったり、そもそもプロセスが何をしているのか分からなかったりする状況があります。コードの中を直接見る番ですが、伝統的な cProfile はコードを包んで実行し直す必要があり、オーバーヘッドも大きくて本番環境には負担です。この場面に合う道具が py-spy です。稼働中のプロセスに、コードの修正も再起動もなしで、無視できるオーバーヘッドで取り付くサンプリングプロファイラです。

動作の仕方 — 外からのぞき見ます #

py-spy は対象プロセスの中で実行されるコードではありません。別のプロセスが対象のメモリを外から読み(Linux の process_vm_readv)、Python インタープリタのコールスタックを毎秒数十〜数百回復元します。統計的に「どの関数で時間が流れているか」を測るサンプリング方式なので、すべての呼び出しを記録する cProfile と違って対象をほとんど遅くせず、Rust 製で自身のコストも小さいのです。本番に取り付けてもいい理由がこの構造にあります。

インストールは一行で、対象プロセスのメモリを読む構造のため、Linux では普通 sudo または SYS_PTRACE の権限が必要です。

インストール 
$ uv tool install py-spy   # または pip install py-spy

dump — 「いま何をしている最中か」を一発で #

最も安くて頻繁に使うコマンドから見ます。dump はいまこの瞬間の全スレッドのコールスタックを写してくれます。

py-spy dump 
$ sudo py-spy dump --pid 4321
Process 4321: gunicorn: worker [api]
Thread 4321 (idle): "MainThread"
    _worker (psycopg_pool/pool.py:128)
    wait (threading.py:320)
Thread 4380 (idle): "ThreadPoolExecutor-0_0"
    acquire (psycopg_pool/pool.py:203)   ← コネクションプール待ち
    ...

止まったように見えるプロセス、応答のないワーカーの正体が、この一枚で明らかになります。すべてのスレッドが pool.acquire に立っているならコネクションプールの枯渇(データベースの記事のあの症状)、lock.acquire ならロックの競合、外部 API の read ならアップストリームの待ちです。サーバーが遅い理由 #1 で「off-CPU 分析へ進む」と言った箇所の Python 版の入口が、まさにこのコマンドです。ハングしたプロセスなら、dump を数秒間隔で 2〜3 回取って、スタックが同じ場所に留まっているかを見るだけで判定できます。

top — リアルタイムで見る関数別の消費 #

top は名前のとおり Linux の top の関数版です。毎秒サンプルを集めて、どの関数(とその下位の呼び出し)が時間を食っているかをリアルタイムに更新します。

py-spy top 
$ sudo py-spy top --pid 4321
Total Samples 3200, GIL: 62%, Active: 71%, Threads: 4

  %Own   %Total  Function (filename)
 24.0%   24.0%   _serialize_row (app/serializers.py)
 11.5%   38.2%   render_items (app/views.py)
  8.1%    8.1%   loads (json/decoder.py)

ヘッダーの GIL と Active の比率が Python 特有のヒントです。Active が低ければプロセスが大半を待って過ごしている(I/O・ロック)という意味で、GIL が 100% 近くに張り付いているのにスレッドが複数なら、スレッド同士が GIL を奪い合う CPU バウンドのワークロードという意味です。後者ならスレッドを増やしても無駄で、プロセスのワーカーを増やす側が答えだという、構造的な結論までここですぐ出ます。

record — フレームグラフとして残す #

観察を共有可能な証拠にするなら record です。一定時間サンプルを集めて、フレームグラフの SVG として保存します。

py-spy record 
$ sudo py-spy record -o profile.svg --pid 4321 --duration 60
# CPU ではなく待ちが疑わしいとき: off-CPU の時間まで含める
$ sudo py-spy record -o profile-idle.svg --pid 4321 --duration 60 --idle

フレームグラフの読み方は ハードウェア上級 #1 で扱ったとおりです。横幅が時間の割合、広い峰がボトルネックです。注目すべきオプションが --idle です。デフォルトの record は CPU を使うサンプル中心なので、DB の応答やロックを待っている時間は見えません。--idle を付けると待機中のスタックまで含まれるので、「CPU は暇なのに遅い」サーバーの時間がどこへ漏れているかが図に現れます。CPU のボトルネックはデフォルトモード、待ちのボトルネックは –idle モード、と覚えれば済みます。非同期(asyncio)のサーバーはスタックがイベントループ中心に見える限界があり、必要なら --gil・--threads オプションと一緒に解釈します。

実戦の手順 — 5 分の診断ルーティン #

症状別の入口を整理するとこうなります。

  1. 応答がまったくない / ハングした — dump を 2〜3 回取ります。すべてのスレッドが同じ待ち箇所で止まっていれば、そこ(プール、ロック、外部呼び出し)が答えです。
  2. 遅いのに CPU が高い — top で上位の関数を確認し、record(デフォルトモード)でフレームグラフを取ります。シリアライズ・パース・正規表現のような CPU の消費者が峰として出てきます。GIL の比率でスレッド戦略も一緒に判定します。
  3. 遅いのに CPU が低い — record --idle を使います。待ち(off-CPU)が図に含まれるので、DB・外部 API・ロックのどこで待っているかが見えます。
  4. コンテナ環境なら — 同じコンテナに py-spy がなくても、ホストからコンテナのプロセスの PID で取り付くか、SYS_PTRACE の権限を与えたサイドカー・一時コンテナから取り付きます。Kubernetes なら kubectl debug の一時コンテナが定石の経路です。

開発段階の精密な測定(呼び出し回数、正確な累積時間)には相変わらず cProfile が合います。道具の全体像は モダン Python 上級 #7 で扱ったので、py-spy の持ち場は「稼働中のプロセスの、いまの真実」です。

まとめ #

  • py-spy は稼働中の Python プロセスに修正・再起動なしで取り付くサンプリングプロファイラです。外からメモリを読む構造なので本番に使っても負担がありません。
  • dump はハングしたプロセスの正体を一枚で見せてくれます。すべてのスレッドが立っている場所がすなわちボトルネックです。
  • top の GIL・Active の比率は、CPU バウンドか待ちか、スレッド戦略が合っているかまで教えてくれます。
  • CPU のボトルネックは record のデフォルトモード、待ちのボトルネックは --idle モードでフレームグラフを取ります。
  • Linux では SYS_PTRACE の権限が必要で、Kubernetes では kubectl debug の一時コンテナが定石です。
X