etcd サーバーの CPU が高騰した場合、原因を突き止める最速の方法は、実行中のプロセスを直接プロファイリングし、その Go レベルの CPU フレームグラフを読み解くことです。本チュートリアルでは、OpenResty XRay が CPU コアの 70% 以上を消費している未修正の etcd バイナリを、コード変更も再起動もなしに分析し、最も CPU を消費する Go コードパスを特定します。具体的には、gRPC リクエスト処理(processUnaryRPC)、キーバリューストアの range・put ハンドラ、そして Go ランタイムのスタック拡張(runtime.newstack)です。

このチュートリアルでは、OpenResty XRay を使用して、Go の etcd サーバー内部での CPU 時間の消費状況を分析します。最も CPU を消費する Go コードパスを示します。OpenResty XRay は Go(golang)言語レベルの CPU フレームグラフを自動的に分析します。

問題症状:etcd が CPU コアの 70% 以上を消費

top コマンドを実行すると、etcd プロセスが CPU コアの 70% 以上(ここでは 74.3%)を消費していることが分かります。

top コマンドが etcd プロセスによる CPU コアの 74.3% 使用を示している様子

ps コマンドで確認すると、これは通常のクラスタ用フラグで起動された標準的な etcd バイナリ(/usr/local/bin/etcd)であり、カスタムビルドもプロファイリング用の計装も、いかなる変更も加えられていないことが分かります。

ps コマンドが未修正の /usr/local/bin/etcd バイナリとそのコマンドラインを示している様子

ガイド付き分析による etcd の最も CPU を消費する Go コードパスの特定

OpenResty XRay を使えば、この未修正の実行中プロセスをリアルタイムに分析できます。「Guided Analysis」(ガイド付き分析)ウィザードでは、診断タイプ、対象、アプリケーションタイプを順に選択します。ここでは診断する問題として High CPU usage(高 CPU 使用率)を選択します。

High CPU usage を含む OpenResty XRay のガイド付き分析の問題タイプメニュー

次に、実行中の etcd プロセスを分析対象として選択します。OpenResty XRay はこれを Go アプリケーション(PID 3638889、約 76% CPU)として検出します。言語レベルはデフォルトの Go、最大実行時間もデフォルトの 300 秒のままにして分析を開始します。

OpenResty XRay で実行中の etcd Go プロセスを分析対象として選択する様子

数ラウンドのサンプリングの後、OpenResty XRay がレポートを生成します。CPU 時間の観点で最も CPU を消費する Go コードパスをランク付けし、read・write システムコールがそれぞれ消費した CPU 量も併せて表示します。

etcd の最も CPU を消費する Go コードパスをランク付けした OpenResty XRay の CPU レポート。processUnaryRPC が 17.6% で首位

これは CPU 時間を最も消費している Go レベルのコードパスで、CPU 時間の 17.6% を占めています。

レポートで第 1 位の最も CPU を消費する Go コードパス。CPU 時間の 17.6% を占める

この processUnaryRPC は Go の gRPC ライブラリの関数です。最もシンプルな種類の gRPC メッセージ、すなわち 1 つのリクエストに 1 つのレスポンスを返すものの処理を担当します。

コードパス内でハイライトされた Go の gRPC ライブラリの processUnaryRPC 関数

その上位の呼び出し関数は handleStream です。

processUnaryRPC の呼び出し元が handleStream であることを示すコードパス

詳細情報を確認するには「More」をクリックします。

More ボタンをクリックしてこのコードパスの詳細を確認する様子

Go CPU フレームグラフの読み方

上記のコードパスは、この Go レベルの CPU フレームグラフから自動的に導き出されたものです。フレームグラフでは、各フレームの幅がその CPU 時間の割合に比例します。

OpenResty XRay が実行中の etcd プロセスをサンプリングして得た Go レベルの CPU 時間フレームグラフ

このアイコンをクリックしてフレームグラフを拡大します。

アイコンをクリックして Go CPU フレームグラフを拡大する様子

さらに拡大します。

フレームグラフの最も CPU を消費するバックトレースをさらに拡大した様子

_KV_Range_Handler 関数は、キーバリューストア内の特定範囲の key を取得できます。

processUnaryRPC 配下の etcd の _KV_Range_Handler 関数に拡大したフレームグラフ

_KV_Put_Handler 関数は、指定された key をキーバリューストアに格納します。

key をキーバリューストアに書き込む etcd の _KV_Put_Handler 関数を示すフレームグラフ

Range 関数は、etcd に格納されているキーバリューデータを範囲指定して検索するために使用されます。

キーバリューデータを範囲指定で検索する etcd の Range 関数を示すフレームグラフ

これは runtime.newobject を呼び出して、多数の golang GC オブジェクトを作成します。

Range クエリ配下で runtime.newobject が多数の Go GC オブジェクトを割り当てている様子を示すフレームグラフ

runtime.newstack 関数は、etcd がデータを書き込む際に比較的高い CPU オーバーヘッドを示します。この関数は Go 言語ランタイムの内部関数で、新しい goroutine のためのランタイムスタックを作成します。

etcd の書き込みパスにおける runtime.newstack のオーバーヘッドを示すフレームグラフ

以下は、現在の問題についてのより詳細な説明と推奨事項です。ネットワークに送信するデータの削減、コネクションプールの利用、gRPC 設定のチューニングなどが提案されています。

processUnaryRPC コードパスの説明と最適化の提案を示す OpenResty XRay

processUnaryRPC 関数について言及しています。

説明文の中で言及されている processUnaryRPC 関数

また、これが Unary RPC を処理することについても触れています。

processUnaryRPC が Unary RPC を処理すると説明する文章

ソース行へのジャンプ

先ほどのコードパスに戻りましょう。最初の関数の緑色のボックスにマウスカーソルを置きます。

コードパスの最初の関数の緑色のボックスにマウスカーソルを合わせた様子

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

processUnaryRPC のソースファイル grpc server.go の完全なパスを示す OpenResty XRay のツールチップ

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

ソースコードの行番号 1024 を示すツールチップ

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

アイコンをクリックして完全な Go ソースファイルパスをコピーする様子

find コマンドを使用してソースファイルを検索します。

ターミナルで find コマンドを使って Go ソースファイルを検索する様子

先ほどコピーしたファイルパスを貼り付けます。

コピーしたソースファイルパスを find コマンドに貼り付ける様子

完全なファイルパスをコピーします。vim エディタを使用して、このファイル内の golang コードを確認します。お好みのエディタを使用することができます。

vim エディタで grpc server.go ソースファイルを開いた様子

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

vim で grpc server.go の 1024 行目にジャンプした様子

md.Handler 関数は、gRPC メッセージの種類に応じて適切なメッセージハンドラを選択して呼び出します。先ほど確認した _KV_Range_Handler_KV_Put_Handler は、md.Handler コールバック関数の 2 つの実装例です。

1024 行目の md.Handler 呼び出しが各 gRPC メッセージハンドラへディスパッチする様子

ステータスバーでは、このコードが先ほどレポートで言及された processUnaryRPC 関数内にあることも確認できます。

1024 行目が processUnaryRPC 関数内にあることを示す vim のステータスバー

その他の CPU を消費するコードパス

CPU 使用率が 2 番目に高い Go コードパスは、約 12% の CPU リソースを使用しています。

レポートで第 2 位の最も CPU を消費する Go コードパス。CPU 時間の約 12% を占める

この関数の目的は、データをネットワークソケットに書き込むことです。

レスポンスデータをネットワークソケットに書き込む関数を示すコードパス

ここでは write システムコールを実行しています。

コードパスの末端で実行されている write システムコール

この関数は HTTP/2 プロトコルを通じてレスポンスデータをネットワークソケットに送信します。

HTTP/2 プロトコルでレスポンスデータを送信する関数を示すコードパス

3 番目に CPU を消費する Go コードパスは、約 11% の CPU 時間を使用しています。

レポートで第 3 位の最も CPU を消費する Go コードパス。CPU 時間の約 11% を占める

ここでの runtime.mcall 関数は、主に goroutine のスケジューリングを担当します。

goroutine のスケジューリングを担当する runtime.mcall 関数を示すコードパス

これは CPU 使用率が 4 番目に高い Go コードパスで、CPU 時間の約 10.5% を占めています。

レポートで第 4 位の最も CPU を消費する Go コードパス。CPU 時間の約 10.5% を占める

この関数の機能は、各 Unary gRPC リクエストの呼び出しを記録することです。CPU リソースを節約するために、このようなログ記録を無効にすることも検討できます。

各 Unary gRPC 呼び出しをログに記録する関数を示すコードパス

etcd CPU の自動監視とレポート

オンデマンドのガイド付き分析に加えて、OpenResty XRay はオンラインプロセスを自動的に監視し、「Insights」ページで日次および週次のレポートを生成することもできます。この etcd インスタンスの場合、日次レポートでは CPU 使用率が平均 51.33%(ピーク時 164%)で、write システムコールと Go の GC オブジェクト割り当てが CPU 消費の上位に入っていることが示されています。

平均・ピーク時の CPU 使用率と CPU 消費の上位項目を示す etcd の OpenResty XRay Insights 日次レポート

これらのレポートは自動的に生成されるため、ご自身でガイド付き分析を実行する必要はありません。ガイド付き分析は、アプリケーションの開発やデモンストレーションに最も有用です。

よくある質問

なぜ etcd サーバーはこれほど CPU を消費するのか?

このケースでは、etcd の CPU 時間の大半は gRPC リクエストの処理に費やされていました。単一で最も CPU を消費する Go コードパスは Go の gRPC ライブラリの processUnaryRPC(CPU 時間の 17.6%)で、これは etcd の _KV_Range_Handler_KV_Put_Handler——キーバリューストアから key の範囲を読み取り、key を書き込む関数——へディスパッチします。HTTP/2 経由でのレスポンスデータの送信と Go ランタイムの処理(runtime.newobjectruntime.newstack、および runtime.mcall による goroutine のスケジューリング)が残りの大部分を占めていました。同じ手法は CPU 使用率の高いあらゆる Go プログラムに適用できます。最も CPU を消費する Go コードパスを特定する方法をご覧ください。

コードを変更したり再起動したりせずに etcd の CPU 使用率をプロファイリングするには?

OpenResty XRay は、実行中の未修正の etcd プロセスを直接分析します——コードの変更も、リビルドも、再起動も不要です。「Guided Analysis」(ガイド付き分析)機能が実行中のプロセスをサンプリングし、Go レベルの CPU フレームグラフと最も CPU を消費するコードパスを自動的に導き出します。

高 CPU 状態の etcd で最も CPU を消費するコードパスは?

今回のワークロードでの上位のパスは次のとおりです:(1) KV の range・put ハンドラへの Unary gRPC 呼び出しを処理する processUnaryRPC(17.6%)、(2) HTTP/2 経由でレスポンスデータをネットワークソケットに書き込む処理(11.7%)、(3) goroutine をスケジューリングする runtime.mcall(11.1%)、(4) すべての Unary gRPC 呼び出しのログ記録(10.5%)——これは省略すれば CPU 時間を節約できる場合があります。

OpenResty XRay について

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

このチュートリアルがお役に立ちましたら、当ブログや YouTube チャンネルのご購読をお願いいたします。ありがとうございます!

著者について

章亦春(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、LuaJITGDBSystemTapLLVM、Perl など、複数のオープンソースプロジェクトに累計 100 万行以上のコードを寄与し、60 以上のオープンソースソフトウェアライブラリを執筆しております。

翻訳

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