OpenResty XRay を使用してソフトウェアの問題を迅速に可視化し解決する

Python プロセスがリクエストを受け続けているのに CPU 使用率が上がらない場合——本事例では gunicorn ワーカーが 8% 前後で頭打ちでした——何らかのコードパスが CPU で処理を行わずに OS スレッドをブロックしています。本記事では、OpenResty XRay の off-CPU 分析でブロッキング Python コードパスを正確に特定する方法をご紹介します。ブロック時間の 92.4% が、業務ロジックのファイル processor.py の 12 行目にある subprocess.run 呼び出しにあると突き止めました——コード変更もプロセス再起動も不要です。

症状：リクエストが殺到しても Python プロセスの CPU 使用率が上がらない

まず、top コマンドを実行して CPU の使用状況を確認します。

この gunicorn の Python プロセスに注目してください。CPU 使用率が非常に低く、わずか 8% 前後です。多くのリクエストが入ってきても上昇しません。

top コマンドの出力。gunicorn Python プロセスの CPU 使用率が 8% にとどまり、システムの 93% 以上がアイドル状態

ps コマンドを実行すると、このプロセスが Linux ディストリビューションに付属の標準 Python 3 バイナリ実行ファイルを使用していることが確認できます。また、この Python Web アプリケーションのアクセスログは新しいクライアントリクエストで増え続けているのに、CPU 使用率は依然として低いままです。これは、Python コードの効率的な実行を妨げる何かがあることを意味します。では、その原因は一体何でしょうか？どうすれば突き止められるでしょうか？

OpenResty XRay の Guided Analysis でブロッキング Python コードパスを特定する

OpenResty XRay を使用して、この未修正のプロセスをリアルタイムで分析し、何が起きているのかを確認できます。

ブラウザで OpenResty XRay の Web コンソールを開き、分析対象のマシンが正しいことを確認した上で、「Guided Analysis」ページに移動します。診断可能な問題タイプの中から「Low CPU usage and cannot go up」を選択し、続いてウィザードに従います。Python アプリケーションを選択し、CPU リソースの 10% を消費している gunicorn の子プロセス（先ほど top で見たもの）を選び、残りのステップはデフォルトのままにします——アプリケーションタイプ、Python と C の両方の言語レベル、そして最大分析時間の 300 秒です。

分析を開始します。システムは複数回の分析を継続的に実行しますが、この事例では 2 ラウンドで十分なため、そこで停止すると、分析レポートが自動生成されます。

レポートには、CPU の効率的な実行を阻害している第 1 位の C 言語レベルのコードパスが表示されています。これは off-CPU 時間の 96% を占めています。

ブロック時間の 96% を占める第 1 位の C 言語レベル off-CPU コードパスを表示する Guided Analysis レポート

最初の関数は poll システムコールです。これは Python インタプリタが I/O イベントを待っていることを意味します。しかし、どのような I/O イベントを待っているのでしょうか？この情報を見つけるには、より詳しい前後のコンテキストを確認する必要があります。

ブロッキングしている C 言語レベルのコードパスの先頭にある poll システムコール

関数 _PyEval_EvalFrameDefault は、Python のコードが現在実行中であることを示します。

Python コードが実行中であることを示す _PyEval_EvalFrameDefault 関数のフレーム

次に、第 1 位の off-CPU Python コードパスを見てみましょう。これはブロック時間の 92.4% を占めています。

ブロック時間の 92.4% を占める第 1 位の Python 言語レベル off-CPU コードパス

この Python の run 関数を見てください。これは標準の subprocess.py モジュールファイルで定義されています。これは、Python コードがサブプロセスコマンドを実行し、その出力を待っていることを意味します。

Python 言語レベルの off-CPU コードパスでハイライトされた標準 subprocess.py モジュールの run 関数

handle_by_script 関数は、業務ロジックの Python コードベースにあります。

off-CPU コードパスに現れた業務ロジックの注文処理コードの handle_by_script 関数

詳細を見るにはクリックしてください。

off-CPU レポートの項目を展開して詳細を表示

最も重要なブロッキングコードパスは、この Python 言語レベルの off-CPU フレームグラフから自動的に導き出されています。フレームグラフは全体的な状況を示しています。このような off-CPU 分析はレイテンシ問題を診断する標準的な手法でもあります——50 万 QPS の OpenResty ゲートウェイで 244ms のレイテンシスパイクを特定した事例をご覧ください。

最も重要なブロッキングコードパスの導出元となった Python 言語レベルの off-CPU フレームグラフ

以下は、現在の問題についてのより詳細な説明と提案です。

poll システムコールと selectors.py の select 関数に関するレポートの説明

これは、先ほど見た handle_by_script 関数について言及しています。

handle_by_script 関数に言及するレポートの文面

また、この関数がサブプロセスを実行していることにも触れています。

handle_by_script 関数がサブプロセスを実行していると説明するレポートの文面

Python 関数 handle_by_script を表す緑色のボックスにマウスカーソルを合わせてください。

フレームグラフ内の handle_by_script Python 関数の緑色のフレームにマウスカーソルを合わせた状態

この関数の Python ソースファイルが表示されます。また、ツールチップには processor.py ファイルの完全なパスが表示されています。

handle_by_script 関数が定義された processor.py ファイルの完全なパスを表示するツールチップ

ソースコードの行番号は 12 です。

ブロッキング呼び出しがソースコードの 12 行目にあることを示すツールチップ

アイコンをクリックして、この関数の完全な Python ソースファイルパスをコピーします。

フレームグラフのツールチップから完全な Python ソースファイルパスをコピー

vim エディタを使用して、先ほどコピーしたコードパスを貼り付け、該当する業務ロジックの Python コードを確認します。お好みのエディタを使用していただいて構いません。

コピーした Python ソースファイルパスを vim エディタで開く

OpenResty XRay が提案したように、12 行目にジャンプします。

OpenResty XRay の提案に従い vim エディタで processor.py の 12 行目にジャンプ

この Python コード行が実際に subprocess.run 関数を呼び出し、外部の bash スクリプトを実行してその出力を待っていることが確認できます。

processor.py の 12 行目で subprocess.run を呼び出して bash スクリプトを実行

これはレポートで示された handle_by_script 関数内にもあります。同じ off-CPU 分析の手法は Perl や Go のプロセスにも適用できます。

レポートに示された handle_by_script 関数の内部にある subprocess.run 呼び出し

OpenResty XRay で今すぐアプリのパフォーマンスを改善する（無料）

Insights ページの自動分析とレポート

OpenResty XRay はオンラインプロセスを自動的に監視し、「Insights」ページで日次および週次の分析レポートを生成することもできます。そのため、「Guided Analysis」機能を手動で使用する必要はありません。ただし、アプリケーションの開発やデモンストレーションには引き続き有用です。

FAQ

なぜ Python プロセスは高負荷でも CPU を使い切れないのですか？

何らかのコードパスが CPU で処理を行わずに OS スレッドをブロックしているためです。上記の事例では、Python コードがサブプロセスコマンドを実行してその出力を待ち、poll システムコールでブロックされていたため、gunicorn ワーカーは大量のリクエスト下でも CPU 使用率が 8% 前後にとどまっていました。

コードを変更せずに、どの Python コードがブロッキングしているかを特定するには？

未修正の実行中プロセスに対して OpenResty XRay の「Guided Analysis」を実行し、「Low CPU usage and cannot go up」を選択します。自動生成されたレポートが最も重要なブロッキングコードパスを導き出し、off-CPU フレームグラフ内の関数にマウスカーソルを合わせると、正確なソースファイルと行番号が表示されます。

なぜ subprocess.run は Python Web アプリケーションをブロックするのですか？

subprocess.run は外部コマンドを起動し、その終了を待ちます。上記の事例では、業務ロジックの関数 handle_by_script が processor.py の 12 行目で subprocess.run を呼び出して bash スクリプトを実行していたため、gunicorn ワーカーはブロック時間の 92.4% をリクエスト処理ではなくサブプロセスの出力待ちに費やしていました。

OpenResty XRay について

OpenResty XRay は動的トレーシング製品であり、実行中のアプリケーションを自動的に分析して、パフォーマンスの問題、動作の問題、セキュリティの脆弱性を診断し、実行可能な提案を提供いたします。基盤となる実装において、OpenResty XRay は弊社の Y 言語によって駆動され、Stap+、eBPF+、GDB、ODB など、様々な環境下で複数の異なるランタイムをサポートしております。

OpenResty XRay の試用をすぐに申請する

著者について

章亦春（Zhang Yichun）は、オープンソースの OpenResty® プロジェクトの創始者であり、OpenResty Inc. の CEO および創業者です。

章亦春（GitHub ID: agentzh）は中国江蘇省生まれで、現在は米国ベイエリアに在住しております。彼は中国における初期のオープンソース技術と文化の提唱者およびリーダーの一人であり、Cloudflare、Yahoo!、Alibaba など、国際的に有名なハイテク企業に勤務した経験があります。「エッジコンピューティング」、「動的トレーシング」、「機械プログラミング」 の先駆者であり、22 年以上のプログラミング経験と 16 年以上のオープンソース経験を持っております。世界中で 4000 万以上のドメイン名を持つユーザーを抱えるオープンソースプロジェクトのリーダーとして、彼は OpenResty® オープンソースプロジェクトをベースに、米国シリコンバレーの中心部にハイテク企業 OpenResty Inc. を設立いたしました。同社の主力製品である OpenResty XRay（動的トレーシング技術を利用した非侵入型の障害分析および排除ツール）と OpenResty Edge（マイクロサービスおよび分散トラフィックに最適化された多機能ゲートウェイソフトウェア）は、世界中の多くの上場企業および大企業から高い評価を得ております。OpenResty 以外にも、章亦春は Linux カーネル、Nginx、LuaJIT、GDB、SystemTap、LLVM、Perl など、複数のオープンソースプロジェクトに累計 100 万行以上のコードを寄与し、60 以上のオープンソースソフトウェアライブラリを執筆しております。

翻訳

英語版の原文と日本語訳版（本文）をご用意しております。読者の皆様による他の言語への翻訳版も歓迎いたします。全文翻訳で省略がなければ、採用を検討させていただきます。心より感謝申し上げます！