是甚麼把這個 Nginx worker 程序的 RPS 壓在每秒 227–286 個請求，而系統負載卻已逼近邏輯 CPU 核數？OpenResty XRay 的 off-CPU 分析在 20 秒取樣視窗內捕獲了 43952 個事件迴圈阻塞樣本——單次最長 75 毫秒——並將其追蹤到使用者 Lua 檔案中的同步 Lua IO 呼叫、阻塞式檔案讀取，以及缺失 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 網路IO等待之外，還有相當一部分 off-CPU 時間消耗在了 mpi_mul_hlp、free 等純 CPU 計算相關的函式上。

這表明，程序在準備好執行時，卻未能及時獲得 CPU 時間片，這是 CPU 資源爭用的典型特徵。

透過專門的分析器，我們確認了問題的根源：nginx 配置檔案中缺少了 worker_cpu_affinity 指令。

no cpu affinity set.
no cpu affinity set.

該配置的缺失，導致多個 nginx worker 程序在不同 CPU 核心間被 Linux 核心頻繁排程，產生了不必要的上下文切換開銷，從而降低了 CPU 的有效利用率。

阻塞的 Lua IO 操作如何拖停 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 函式來執行 shell 命令。

這些都是同步阻塞式 IO 操作，它會暫停整個 Nginx 事件迴圈，直到外部命令執行完畢並返回結果。這正是導致系統吞吐能力低下的核心原因之一。

關於 io.popen 阻塞事件迴圈這一故障模式的完整解剖——以及帶來 7 倍和 150 倍吞吐量提升的非阻塞替代方案——參見《Lua io.popen 阻塞 Nginx 事件迴圈：一次 150 倍吞吐量提升的實戰案例》。

量化檔案 IO 延時：單次最高 1.5 毫秒

哪些檔案讀取最熱

樣本一

除了 io.popen 之外，我們還透過 C 級別虛擬檔案系統讀寫次數火焰圖，發現了另外兩個潛在的效能瓶頸：

虛擬檔案系統讀寫次數火焰圖（樣本一）：apr_generate_random_bytes 呼叫棧被高亮，佔檔案讀取次數的 59.8%

從上面這張火焰圖可以看出，apr_generate_random_bytes 函式佔用了高達 59.8% 的檔案讀取次數。

虛擬檔案系統讀寫次數火焰圖（樣本一）：apr_sdbm_fetch 呼叫棧被高亮，佔檔案讀取次數的 24%

而根據第二張火焰圖，apr_sdbm_fetch 函式佔用了 24% 的檔案讀取次數。

樣本二

虛擬檔案系統讀寫次數火焰圖（樣本二）：apr_generate_random_bytes 呼叫棧被高亮，佔檔案讀取次數的 51.8%

從上面這張圖可以看到，來自 APR（Apache Portable Runtime）庫的 C 函式 apr_generate_random_bytes 佔了 51.8% 的檔案讀取次數，呼叫方是 Nginx 程序內的 ModSecurity 模組。

虛擬檔案系統讀寫次數火焰圖（樣本二）：apr_sdbm_fetch 呼叫棧被高亮，佔檔案讀取次數的 20.7%

而第二張圖顯示函式 apr_sdbm_fetch 一共佔了 20.7% 的檔案讀取次數。

檔案 IO 延時分佈

為了精確評估這些檔案 IO 操作的影響，我們透過專門的延時工具來測量 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 事件迴圈阻塞有多嚴重？43952 個樣本、最大 75 毫秒

最後，我們對 Nginx 事件迴圈的整體阻塞情況進行了全面評估。

在 20 秒的取樣週期內，我們捕捉到了 43952 個阻塞樣本，其中單次阻塞時長的最大值竟高達 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 閘道器中定位 244 毫秒的效能異常。

結合下面這個樣本的分析：

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 僅在 227-286 之間，程序的 RPS 是非常低的，每秒只處理了不到 300 個請求。而機器負載已經接近 4，已經是邏輯 CPU 核的個數。這與我們觀察到的嚴重阻塞情況完全吻合。

總結：是甚麼拖垮了這個 Nginx worker

在深入分析的過程中，我們發現了多個影響系統效能的關鍵問題：

  • nginx worker 程序間的 CPU 資源爭用導致了大量的上下文切換，嚴重影響了 CPU 的有效利用率。
  • 阻塞的 Lua IO 操作，如 io.popen 和 read，在 customize.lua 檔案中被頻繁呼叫，成為了系統效能的最大拖累。
  • apr_generate_random_bytes 和 apr_sdbm_fetch 函式的檔案 IO 操作也對事件迴圈造成了顯著的阻塞影響。
  • Nginx 事件迴圈的單次阻塞時長高達 75 毫秒，直接導致了單個 worker 程序的 RPS 僅在 227-286 之間，遠低於預期。

這些問題的存在，正是導致系統效能低下的根本原因。透過 OpenResty XRay 的精準診斷，我們不僅識別了這些瓶頸，還為後續的最佳化提供了明確的方向。

常見問題

為甚麼系統負載很高，Nginx 的 RPS 卻很低？

因為 worker 的事件迴圈被阻塞了。本案例中，單個 Nginx worker 每秒只能處理 227–286 個請求，而系統負載已逼近邏輯 CPU 核數。off-CPU 分析發現了兩個疊加的原因：缺失 worker_cpu_affinity 指令導致的 CPU 爭搶，以及單次長達 75 毫秒、令事件迴圈停擺的同步阻塞 IO。

甚麼會阻塞 Nginx 事件迴圈？

worker 內的任何同步操作。本案例中，阻塞來自使用者 Lua 檔案中執行 shell 命令的同步 Lua IO 呼叫，以及單次延時接近 1.5 毫秒的阻塞式檔案讀取。事件迴圈被阻塞期間，該 worker 上所有併發連線都在等待。

如何測量 Nginx 事件迴圈的阻塞延時？

OpenResty XRay 可以取樣 epoll 迴圈的阻塞延時分佈，並生成 off-CPU 火焰圖——非侵入式，無需修改程式碼或重啟程序。本案例在 20 秒取樣視窗內捕獲了 43952 個阻塞樣本，最大單次 75 毫秒，並最終追蹤到具體的 Lua 程式碼行。

使用 OpenResty XRay 告別 Nginx 效能噩夢

OpenResty XRay 是您解決複雜效能問題的終極利器。憑藉其無與倫比的動態追蹤能力，我們不僅能精準定位效能瓶頸，更能為企業帶來深遠的價值：

  • 突破性的診斷效率：告別傳統的漫長排查過程，OpenResty XRay 將問題定位時間從數天縮短至數小時，讓您的團隊始終快人一步。
  • 極致的硬體資源最佳化：透過消除效能瓶頸，單機處理能力實現數倍提升，助您以更少的伺服器資源承載更大的業務負載。
  • 無縫的業務連續性保障：主動識別並消除潛在的效能隱患，確保系統穩定執行，避免因過載導致的服務中斷。
  • 全面的技術債務清理：系統性地揭示並解決歷史遺留的效能問題，提升程式碼質量和系統架構的整體健康度。

在這個以毫秒計較勝負的數字經濟時代，應用效能直接影響使用者體驗和商業成功。OpenResty XRay 以其先進的動態追蹤技術，徹底顛覆傳統的效能最佳化方式，為您的技術決策提供堅實的科學依據。

如果您的應用正面臨效能挑戰，OpenResty XRay 將為您提供無與倫比的精準洞察力，讓效能成為推動業務增長的強大引擎。

關於 OpenResty XRay

OpenResty XRay 是一款動態追蹤產品，它可以自動分析執行中的應用，以解決效能問題、行為問題和安全漏洞，並提供可行的建議。在底層實現上，OpenResty XRay 由我們的 Y 語言驅動，可以在不同環境下支援多種不同的執行時，如 Stap+、eBPF+、GDB 和 ODB。

立即申請 OpenResty XRay 試用

關於作者

章亦春是開源 OpenResty® 專案創始人兼 OpenResty Inc. 公司 CEO 和創始人。

章亦春（Github ID: agentzh），生於中國江蘇，現定居美國灣區。他是中國早期開源技術和文化的倡導者和領軍人物，曾供職於多家國際知名的高科技企業，如 Cloudflare、雅虎、阿里巴巴, 是 “邊緣計算“、”動態追蹤 “和 “機器程式設計 “的先驅，擁有超過 22 年的程式設計及 16 年的開源經驗。作為擁有超過 4000 萬全球域名使用者的開源專案的領導者。他基於其 OpenResty® 開源專案打造的高科技企業 OpenResty Inc. 位於美國矽谷中心。其主打的兩個產品 OpenResty XRay（利用動態追蹤技術的非侵入式的故障剖析和排除工具）和 OpenResty Edge（最適合微服務和分散式流量的全能型閘道器軟體），廣受全球眾多上市及大型企業青睞。在 OpenResty 以外，章亦春為多個開源專案貢獻了累計超過百萬行程式碼，其中包括，Linux 核心、Nginx、LuaJIT、GDB、SystemTap、LLVM、Perl 等，並編寫過 60 多個開源軟體庫。

關注我們

如果您喜歡本文，歡迎關注我們 OpenResty Inc. 公司的部落格網站 。也歡迎掃碼關注我們的微信公眾號：

我們的微信公眾號

翻譯

我們提供了英文版原文和中譯版（本文）。我們也歡迎讀者提供其他語言的翻譯版本，只要是全文翻譯不帶省略，我們都將會考慮採用，非常感謝！