この Nginx worker プロセスの処理能力を毎秒 227〜286 リクエストに抑え込み、一方でシステム負荷を論理 CPU コア数近くまで押し上げていたものは何だったのでしょうか？OpenResty XRay の off-CPU 分析は、20 秒のサンプリング期間中に 43,952 件のイベントループ・ブロッキングサンプル（単発の最大値は 75 ミリ秒）を捕捉し、その原因を、ユーザー Lua ファイル内の同期 Lua I/O 呼び出し、ブロッキングファイル読み取り、そして worker_cpu_affinity ディレクティブ欠落による CPU リソース競合まで遡って特定しました。

従来の監視ツールでは、負荷の高さや遅延の増加といった表面的な現象しか把握できません。本稿では、この実際の事例を通して、OpenResty XRay の非侵入型動的トレーシングが、各 off-CPU ボトルネックを具体的な関数とコード行まで特定していく過程をご紹介します。

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

負荷は高いのに仕事が進まない：worker_cpu_affinity 欠落による CPU リソース競合

分析の第一歩として、OpenResty XRay の C レベル off-CPU フレームグラフを用いて、プロセスの待機イベントを調査しました。

nginx worker プロセスの C レベル off-CPU フレームグラフ：epoll_wait の待機スタックに加え、純粋な CPU 計算関数にも off-CPU 時間が消費されており、CPU リソース競合の兆候を示している

分析結果によると、想定通りの epoll_wait によるネットワーク I/O 待機に加え、かなりの off-CPU 時間が、mpi_mul_hlp や free といった純粋な CPU 計算に関連する関数で消費されていることが判明しました。

これは、プロセスの実行準備が整っているにもかかわらず、タイムリーに CPU タイムスライスを獲得できていないことを示しており、これは CPU リソース競合の典型的な特徴です。

専門の分析ツールを用いて、問題の根本原因を特定しました。それは、nginx の設定ファイルに worker_cpu_affinity ディレクティブが欠落していたことでした。

no cpu affinity set.
no cpu affinity set.

この設定の欠落により、複数の nginx worker プロセスが、Linux カーネルによって異なる CPU コア間で頻繁にスケジューリングされ、不要なコンテキストスイッチのオーバーヘッドが発生し、その結果、CPU の実効利用率が低下します。

ブロッキング Lua I/O 呼び出しが Nginx イベントループを停止させた仕組み

CPU 競合問題の解決後、引き続き off-CPU 時間の分析を進めました。

Lua レベル off-CPU フレームグラフ：ブロッキング時間が customize.lua の 15 行目から呼び出される file_list 関数内の popen と read の呼び出しに集中している

分析の結果、off-CPU ブロッキング時間の大部分が、ユーザー定義の customize.lua ファイルの 15 行目に起因していることが判明しました。

この行のコードは file_list という関数を呼び出しており、その関数内部では Lua 標準ライブラリが提供する io.popen および read 関数を使用してシェルコマンドを実行しています。

これらはすべて同期ブロッキング I/O 操作であり、外部コマンドの実行が完了し、結果が返されるまで Nginx イベントループ全体を停止させます。これこそが、システムのスループット低下を引き起こす主要な原因の一つです。

io.popen がイベントループをブロックするこの障害モードの詳細な解剖——および 7 倍・150 倍のスループット改善をもたらした非ブロッキングの代替手段——については、『Lua io.popen が Nginx イベントループをブロックする問題：スループット 150 倍改善の実例』をご覧ください。

ファイル I/O レイテンシーの測定：1 回あたり最大 1.5 ミリ秒

最も読み取り回数の多かったファイル I/O 呼び出し

サンプル 1

io.popen に加え、C レベル仮想ファイルシステムにおける読み書き回数のフレームグラフから、さらに二つの潜在的な性能ボトルネックが発見されました。

仮想ファイルシステム読み書き回数フレームグラフ（サンプル 1）：apr_generate_random_bytes の呼び出しスタックがハイライトされ、ファイル読み取り回数の 59.8% を占めている

上記のフレームグラフから見て取れるように、apr_generate_random_bytes 関数がファイル読み取り回数の 59.8% を占めています。

仮想ファイルシステム読み書き回数フレームグラフ（サンプル 1）：apr_sdbm_fetch の呼び出しスタックがハイライトされ、ファイル読み取り回数の 24% を占めている

また、二枚目のフレームグラフによりますと、apr_sdbm_fetch 関数がファイル読み取り回数の 24% を占めています。

サンプル 2

仮想ファイルシステム読み書き回数フレームグラフ（サンプル 2）：apr_generate_random_bytes の呼び出しスタックがハイライトされ、ファイル読み取り回数の 51.8% を占めている

上記の図から、APR（Apache Portable Runtime）ライブラリの C 関数 apr_generate_random_bytes がファイル読み取り回数の 51.8% を占めていることがわかります。呼び出し元は Nginx プロセス内の ModSecurity モジュールです。

仮想ファイルシステム読み書き回数フレームグラフ（サンプル 2）：apr_sdbm_fetch の呼び出しスタックがハイライトされ、ファイル読み取り回数の 20.7% を占めている

そして、二枚目の図では、apr_sdbm_fetch 関数が合計でファイル読み取り回数の 20.7% を占めていることが示されています。

ファイル I/O レイテンシーの分布

これらのファイル I/O 操作が与える影響を正確に評価するため、専用のレイテンシー測定ツールを用いて apr_generate_random_bytes のレイテンシー分布を測定しました。

3110 samples' latency: min=10, avg=17, max=1494 (us)
value |-------------------------------------------------- count
    2 |                                                      0
    4 |                                                      0
    8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  1540
   16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@   1499
   32 |@@                                                   64
   64 |                                                      4
  128 |                                                      1
  256 |                                                      1
  512 |                                                      0
 1024 |                                                      1
 2048 |                                                      0
 4096 |                                                      0

この関数は最大で 1494 マイクロ秒、つまり約 1.5 ミリ秒のレイテンシーに達することが判明しました。この遅延は Nginx のイベントループをブロックし、現在処理中のすべての同時接続におけるリクエストのレイテンシーに影響を及ぼします。

また、apr_sdbm_fetch についても、時には 1 ミリ秒近くに達することがあります。

1570 samples' latency: min=5, avg=10, max=953 (us)
value |-------------------------------------------------- count
    1 |                                                      0
    2 |                                                      0
    4 |@@@@@@@@@@@@@@@@@                                   383
    8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  1080
   16 |@@@@                                                100
   32 |                                                      4
   64 |                                                      2
  128 |                                                      0
  256 |                                                      0
  512 |                                                      1
 1024 |                                                      0
 2048 |                                                      0

高スループットと低レイテンシーを追求する Nginx にとって、ミリ秒単位の同期ブロッキングは決して無視できません。

Nginx イベントループのブロッキングはどれほど深刻だったか：43,952 サンプル、最大 75 ミリ秒

最後に、Nginx イベントループ全体のブロッキング状況について包括的な評価を実施しました。

20 秒間のサンプリング期間中に、43952 件のブロッキングサンプルを捕捉しました。その中で、1 回あたりのブロッキング時間の最大値は驚くべきことに75165 マイクロ秒、すなわち 75 ミリ秒以上に達していました。

distribution of epoll loop blocking latencies (us): 43952 samples: min/avg/max: 754/0/75165
 value |-------------------------------------------------- count
     0 |                                                      31
     1 |                                                     149
     2 |                                                      33
     4 |                                                     166
     8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@                        6094
    16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  10839
    32 |@@@@@@@@@@@@@@@                                     3278
    64 |@@@@@@@@@                                           2060
   128 |@@@@@@@@@@@                                         2530
   256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@     10082
   512 |@@@@@@@@@@@                                         2544
  1024 |@@@@@                                               1162
  2048 |@@@@@@@@@@                                          2343
  4096 |@@@@@@@@@@                                          2377
  8192 |                                                     199
 16384 |                                                      55
 32768 |                                                       8
 65536 |                                                       2
131072 |                                                       0
262144 |                                                       0

このデータは、アプリケーションのパフォーマンスがこれほどまでに低下している理由を明確に説明しています。イベントループが 75 ミリ秒間ブロックされるということは、その間、当該 worker プロセスが新規リクエストを一切処理できないことを意味します。

このようなブロッキングは、当該 worker 上で処理中のすべてのリクエストにも同時に影響します。これはテールレイテンシ悪化の典型的な構図です。関連事例として、50 万 QPS の OpenResty ゲートウェイで謎の 244ms 遅延を特定した事例もご覧ください。

以下の具体的なサンプル分析からも、この状況が裏付けられます。

found 3237 in reqs and 3238 done reqs in 3.103 sec (1043.07 r/s and 1043.39 r/s).
in reqs:
  pid 3101: 255.21 r/s
  pid 3102: 285.82 r/s
  pid 3103: 227.82 r/s
  pid 3106: 274.22 r/s
done reqs:
  pid 3102: 286.47 r/s
  pid 3103: 227.50 r/s
  pid 3101: 254.89 r/s
  pid 3106: 274.54 r/s

単一の worker プロセスの RPS (Requests Per Second) は 227 から 286 の間に留まっており、これは非常に低い数値です。1 秒あたり 300 件未満のリクエストしか処理できていません。一方で、マシン負荷はすでに 4 に近く、これは論理 CPU コア数に匹敵します。この状況は、観測された深刻なブロッキング状況と完全に一致しています。

まとめ：この Nginx worker を停滞させたもの

詳細な分析を進める中で、システムパフォーマンスに影響を与える複数の重要な問題が明らかになりました。

  • nginx worker プロセス間のCPUリソース競合が大量のコンテキストスイッチ (Context Switch) を引き起こし、CPUの有効利用率を著しく低下させていました。
  • customize.lua ファイル内で頻繁に呼び出される io.popen や read といったブロッキング (Blocking) Lua I/O 操作が、システムパフォーマンスの最大のボトルネック (Bottleneck) となっていました。
  • apr_generate_random_bytes および apr_sdbm_fetch 関数によるファイルI/O操作も、イベントループ (Event Loop) に顕著なブロッキング影響を与えていました。
  • Nginx イベントループの 1 回あたりのブロッキング時間が最大 75 ミリ秒に達し、これが直接的に単一の worker プロセスの RPS (Requests Per Second) を 227〜286 という、期待値を大幅に下回る数値に留めていました。

これらの問題の存在こそが、システムパフォーマンス低下の根本原因です。OpenResty XRay の精密な診断により、これらのボトルネックを特定できただけでなく、その後の最適化に向けた明確な方向性も得られました。

よくある質問

システム負荷が高いのに Nginx の RPS が低いのはなぜですか？

worker のイベントループがブロックされているためです。本事例では、単一の Nginx worker が毎秒 227〜286 リクエストしか処理できない一方、システム負荷は論理 CPU コア数に接近していました。off-CPU 分析により、worker_cpu_affinity ディレクティブの欠落による CPU リソース競合と、イベントループを最大 75 ミリ秒停止させる同期ブロッキング I/O という、二つの複合的な原因が判明しました。

Nginx のイベントループをブロックするものは何ですか？

worker 内で実行されるあらゆる同期操作です。本事例では、ユーザー Lua ファイル内でシェルコマンドを実行する同期 Lua I/O 呼び出しと、1 回あたり約 1.5 ミリ秒に達するブロッキングファイル読み取りが原因でした。イベントループのブロック中は、その worker 上のすべての同時接続が待たされることになります。

Nginx イベントループのブロッキングレイテンシーはどのように測定しますか？

OpenResty XRay は、epoll ループのブロッキングレイテンシー分布をサンプリングし、off-CPU フレームグラフを生成します。コード変更や再起動が不要な非侵入型です。本事例では、20 秒のサンプリングで 43,952 件のブロッキングサンプル（最大 75 ミリ秒）を捕捉し、具体的な Lua コード行まで遡って特定しました。

OpenResty XRay で Nginx パフォーマンスの悪夢に終止符を打つ

OpenResty XRay は、複雑なパフォーマンス問題を解決するための究極のツールです。その比類なき動的トレーシング (Dynamic Tracing) 能力により、パフォーマンスボトルネックを正確に特定できるだけでなく、企業に計り知れない価値をもたらします。

  • 画期的な診断効率：従来の長期にわたるトラブルシューティング (Troubleshooting) プロセスに別れを告げ、OpenResty XRay は問題特定時間を数日から数時間へと短縮し、お客様のチームを常に一歩先へと導きます。
  • 究極のハードウェアリソース最適化：パフォーマンスボトルネックを解消することで、単一サーバーの処理能力を数倍に向上させ、より少ないサーバーリソースでより大きなビジネス負荷を処理可能にします。
  • シームレスな事業継続性確保：潜在的なパフォーマンス上の懸念を事前に特定し解消することで、システムの安定稼働を確保し、過負荷によるサービス中断を回避します。
  • 包括的な技術的負債 (Technical Debt) の解消：過去からのパフォーマンス問題を体系的に明らかにし解決することで、コード品質とシステムアーキテクチャ (System Architecture) 全体の健全性を向上させます。

ミリ秒単位で勝敗が決まるデジタル経済時代において、アプリケーションパフォーマンス (Application Performance) は、ユーザーエクスペリエンス (User Experience) とビジネスの成功に直接影響します。OpenResty XRay は、その先進的な動的トレーシング技術により、従来のパフォーマンス最適化手法を根本から覆し、お客様の技術的意思決定に確固たる科学的根拠を提供します。

導入企業のアプリケーションがパフォーマンスの課題に直面している場合、OpenResty XRay は比類なき精密な洞察力をご提供し、パフォーマンスをビジネス成長を推進する強力なエンジンへと変革いたします。

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

OpenResty XRay について

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

OpenResty XRay で実行中のアプリケーションを今すぐ分析する

本記事がお役に立ちましたら、ぜひ当ブログおよび 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、LuaJIT、GDB、SystemTap、LLVM、Perl など、複数のオープンソースプロジェクトに累計 100 万行以上のコードを寄与し、60 以上のオープンソースソフトウェアライブラリを執筆しております。

翻訳

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