Go サービスの CPU 使用率が異常に低い：稼働中プロセスの off-CPU 分析でブロッキングの根本原因を特定

off-CPU 分析とは、Go プログラムがコードを実行せずブロックされて待っている箇所を特定する手法です。リクエストが流入し続けているのに CPU 使用率が上がらない場合、原因はここにあります。本記事では、OpenResty XRay を使って稼働中の未修正の Go サービス（高負荷でも CPU 2%）を off-CPU 分析し、ブロッキングの原因をシェルコマンド呼び出しの 1 行まで特定します。コード変更・再デプロイは不要です。

症状：リクエストが増えても Go サービスの CPU 使用率が上がらない

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

chat-service という名前のプロセスが見えます。このプロセスは Go 言語で実装されていることが事前にわかっています。CPU 使用率が非常に低く、わずか 2% です。多くのリクエストが入ってきても上昇しません。（逆に CPU 使用率が高すぎる場合は、最も CPU を消費する Go コードパスの特定をご覧ください。）

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

多くのクライアントリクエストが流入しているにもかかわらず、CPU 使用率は依然として低いままです。これは、golang コードの効率的な実行を妨げる何かがあることを意味します。原因をどのように見つけることができるでしょうか？

稼働中の Go プロセスを OpenResty XRay で off-CPU 分析

OpenResty XRay をこの未修正のプロセスに向けて、リアルタイムに分析しましょう。計装（インストルメンテーション）も再起動も不要です。OpenResty XRay の Web コンソールを開き、Guided Analysis（ガイド付き分析）ページに移動して、問題タイプ「Low CPU usage and cannot go up」（CPU 使用率が低く、上がらない）を選択します。

ウィザードを進めて対象の Go プロセス（top で見た CPU 2% のプロセス）を選択し、言語レベルはデフォルトの「Go」、分析時間はデフォルトの 300 秒のままにして、分析を開始します。1 ラウンドのサンプリングが終わったら停止します。この例ではそれで十分です。OpenResty XRay がレポートを自動生成し、特定された問題タイプはまさに off-CPU です。この Go サービスは実行ではなく、ブロックされて待機することに時間を費やしていたのです。

レポートのブロッキングパスは下から上へ読みます。一番下の Go 関数は Syscall6、6 つの引数を取るシステムコールです。このフレームだけではどのシステムコールかは判別できないため、隣接するフレームをたどって文脈を確認します。

隣の Process.wait フレームから、内部のシステムコールは waitpid だとわかります。その上の標準ライブラリの exec.Cmd.Run は、プログラムがシステムのシェルコマンドを実行してその完了を待っていることを意味します。このパスを上へたどると、原因は業務ロジックのコードである chat.RateLimit 関数に行き着きます。

この最も顕著なブロッキングコードパスは、下の Go レベルの off-CPU フレームグラフから自動的に導き出されたものです。同じ off-CPU 分析のアプローチは Perl や Python のプロセスにも適用できます。

レポートには説明と提案も記載されています。Syscall6 は 6 引数のシステムコールを実行し、このパスは下から exec.Cmd.Run を経て chat.RateLimit に達し、その業務関数がシステムコマンドを実行して待機している、というものです。

問題のソースへ直接ジャンプするには、chat.RateLimit フレームにマウスカーソルを合わせます。ツールチップに正確なソースファイルと行番号が表示されます——chat/processor.go の 46 行目です。

そのファイルを 46 行目で開くと、ボトルネックがそこにあります。RateLimit が exec.Command("/usr/bin/sleep", "0.01") を呼び、続けて cmd.Run() を実行しており、シェルコマンドを起動してブロックしていたのです。これで簡単に最適化できます。

自動分析と日次・週次レポート

ガイド付き分析を手動で実行する必要はありません。OpenResty XRay は本番環境のプロセスを自動監視し、Insights ページに日次・週次レポートを生成することもできます。同じ off-CPU コードパスと CPU 使用率の概要が、自動的に提供されます。ガイド付き分析は主に開発やデモンストレーションの用途に向いています。

よくある質問

Go プログラムの off-CPU 分析はどのように行いますか？

稼働中の未修正プロセスに対してそのまま実行できます。OpenResty XRay のガイド付き分析（Guided Analysis）で「Low CPU usage and cannot go up」を選択し、対象の Go プロセスを指定してサンプリングを 1 ラウンド実行するだけです。分析レポートが自動生成され、Go レベルの off-CPU フレームグラフから最も顕著なブロッキングコードパスが自動的に推定されます。コード変更や再デプロイは不要です。

高負荷でも Go サービスの CPU 使用率が低いままなのはなぜですか？

OS スレッドが Go コードを実行せず、待機状態でブロックされているためです。本記事のケースでは、業務関数 chat.RateLimit が exec.Cmd.Run でシェルコマンドを実行し、その完了を待っていた（内部では waitpid システムコール）ことが原因で、リクエストがいくら増えても CPU 使用率は 2% のままでした。

Go の off-CPU フレームグラフに表示される Syscall6 とは何ですか？

Syscall6 は、6 つの引数を取るシステムコールを発行する Go ランタイムの関数です。このフレームだけではどのシステムコールかは判別できず、隣接するフレームから判断する必要があります。本記事のフレームグラフでは、隣の Process.wait フレームから、内部のシステムコールは waitpid であると推定できました。

OpenResty XRay について

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

著者について

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

翻訳

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