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

Perl プロセスにリクエストが届き続けているのに CPU 使用率が低いまま（本例では約 13%）の場合、何らかのコードパスが OS スレッドをブロックしています。典型的なのは select で応答を待つ HTTP 呼び出しのような同期 I/O です。本記事では、OpenResty XRay の off-CPU フレームグラフを使い、ブロッキングしている Perl コードパスをソースファイルと行番号まで特定する方法を紹介します。コード変更もプロセス再起動も不要です。

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

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

こちらの Perl プロセスに注目してください。CPU の使用率は約 13% です。多くのリクエストが入ってきても、CPU の使用量は上昇しません。

top コマンドの出力で Perl プロセスの CPU 使用率が約 13% にとどまっている様子

次に ps コマンドを実行して、このプロセスの詳細を確認しましょう。

ここでは、Linux ディストリビューションに標準で付属している Perl のバイナリ実行ファイルであることがわかります。

ps コマンドの出力で Linux ディストリビューション標準の perl バイナリであることを確認

次に、この Perl アプリケーションのアクセスログを見てみましょう。

多くのクライアントリクエストが来ているのが見えますが、CPU 使用率は依然として低いです。これは、何かが Perl コードの効率的な実行をブロックしていることを意味します。その原因はどのように特定すればよいのでしょうか。

Perl アプリケーションのアクセスログに多数のクライアントリクエストが記録されている様子

CPU 使用率が低いままアクセスログが増え続けている様子

OpenResty XRay の off-CPU フレームグラフでブロッキング Perl コードパスを特定する

OpenResty XRay を使用して、この未修正のプロセスを検査することができます。リアルタイムで分析を行い、原因を特定できます。

ブラウザで OpenResty XRay の Web コンソールを開き、分析対象のマシンが正しいことを確認してから、「Guided Analysis」ページに移動します。

OpenResty XRay Web コンソールの Guided Analysis ページ

分析可能な問題タイプの中から「Low CPU usage and cannot go up」を選択します。

Guided Analysis で「Low CPU usage and cannot go up」問題タイプを選択

あとはウィザードに従って進めます。先ほどの Perl アプリケーションを選び、14% の CPU を消費しているプロセス（先ほど top で確認したもの）を選択し、残りのステップはデフォルトのままにします。アプリケーションのタイプ、Perl と C/C++ の両言語レベル、最大分析時間の 300 秒です。

Guided Analysis ウィザードで 14% の CPU を消費している Perl プロセスを選択

分析を開始します。システムは複数回の分析を継続的に実行しますが、この例では 1 回で十分なので、そこで停止します。

Guided Analysis が Perl プロセスに対して初回の分析を実行中

自動生成された分析レポートが表示されます。

自動生成された Guided Analysis の分析レポート

これは分析対象の問題タイプである off-CPU です。

off-CPU 問題タイプを示す Guided Analysis レポート

これは、オペレーティングシステムスレッドを最も深刻にブロックしている C コードパスです。

OS スレッドを最も深刻にブロックしている C コードパス

最初の関数は select というシステムコール関数です。

ブロッキング C コードパスの先頭にある select システムコール

Perl_pp_select は、Perl の select 関数を処理するための組み込み関数です。これは Perl 内部の一部で、socket や他のファイル上の I/O イベントを監視し、待機するために使用されます。

Perl の select 関数を処理する組み込み関数 Perl_pp_select

この C 関数から、現在 Perl コードが実行されていることがわかります。

Perl コードが実行中であることを示す C 関数のスタックフレーム

次に、OS スレッドを最も強くブロックしている Perl コードパスを確認しましょう。

OS スレッドを最も強くブロックしている Perl コードパス

最上部の C 関数 select は、先ほど見た C コードパスのブロッキングポイントです。

Perl コードパスのブロッキングポイントである select 関数

Net::HTTP::Methods モジュールの can_read Perl 関数は、ソケットが読み取り可能な新しいデータを受信するまで待機します。

ソケットのデータを待機している Net::HTTP::Methods モジュールの can_read 関数

呼び出しチェーンに沿って、read_response_headers 関数でレスポンスヘッダーを読み取っているときにブロッキングが発生していることがわかります。

HTTP レスポンスヘッダーの読み取り中にブロッキングしている read_response_headers 関数

remote_fetch は業務ロジックのコードにある関数で、弊社独自の Perl モジュール Service::Processor に属しています。

ビジネスレベルの Perl モジュール Service::Processor の remote_fetch 関数

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

最も重要なブロッキングコードパスを示す Perl 言語レベルの off-CPU フレームグラフ

ここでは、現在の問題に関する詳細な説明と提案が示されています。

off-CPU 問題に関するレポートの詳細な説明と提案

前に見た select 関数が言及されています。

select 関数に言及しているレポートの記述

Net::HTTP::Methods::can_read 関数がデータに基づいて次のステップを選択するために select を呼び出していることが述べられています。

can_read 関数が select 呼び出しを使用していることを説明するレポート

これも、以前見た remote_fetch 関数の参照です。

レポート内の remote_fetch 関数への参照

前のホットコードパスに戻りましょう。

remote_fetch という名前の Perl 関数の緑のボックスにマウスカーソルを合わせると、

フレームグラフ内の remote_fetch 関数の緑のボックスにマウスを重ねている様子

この関数の Perl ソースファイルの完全なパスが表示されます。

remote_fetch 関数のソースファイルパスと行番号を表示するツールチップ

この関数の完全な Perl ソースファイルパスをコピーするためにクリックします。

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

ターミナルで、先ほどコピーしたパスを貼り付け、vim エディタで該当の Perl 業務コードを開きます。お好みのエディタを使用していただいて構いません。

ターミナルで vim エディタを使って Perl ソースファイルを開いている様子

OpenResty XRay が提案したように、66 行目をチェックします。

OpenResty XRay の提案どおり Perl ソースファイルの 66 行目を確認

HTTP GET リクエストを送信し、その応答を待機していることがわかります。

HTTP GET リクエストを送信して応答を待機している Perl コード

Perl で HTTP リクエストがブロックされるのを避けるために、Coro のような非ブロッキングフレームワークの使用をご検討ください。同じ off-CPU 分析のアプローチは Go や Python のプロセスにも適用できます。

Coro などの非ブロッキング Perl フレームワークの使用を提案する画面

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

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

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

OpenResty XRay の Insights ページに表示される日次・週次の分析レポート

OpenResty XRay は弊社独自の動的トレーシング技術に基づく非侵入型の診断システムです。パフォーマンスの問題、動作の問題、セキュリティ脆弱性をリアルタイムで監視・スキャンできます。

非侵入型診断システム OpenResty XRay の概要

FAQ

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

何らかのコードパスが CPU 上で処理を行う代わりに OS スレッドをブロックしているためです。本記事のケースでは、Net::HTTP::Methods モジュールの can_read 関数が select システムコールでソケットの新しいデータを待ち続けており、リクエストが積み上がる一方でプロセスはほぼ待機状態でした。

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

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

本記事の off-CPU フレームグラフは何を示していますか？

OS スレッドが CPU 上で実行される代わりに、ブロックされて待機している時間を費やしたコードパスを示しています。本記事のケースでは、Perl 言語レベルの off-CPU フレームグラフがビジネス関数 remote_fetch を直接指し示しており、この関数は read_response_headers 内の select 呼び出しで HTTP 応答を待つ間ブロックしていました。

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 以上のオープンソースソフトウェアライブラリを執筆しております。

翻訳

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