本文介紹了 Prometheus 外掛造成長尾請求現象的原因，以及如何解決這個問題。
作者屠正松，Apache APISIX PMC Member。
現象
在 APISIX 社群中，曾有部分使用者陸續反饋一種神秘現象：部分請求延遲較長。具體表現為：當流量請求進入一個正常部署的 APISIX 叢集時，偶爾會出現部分請求有 1 ~ 2 秒的延遲。使用者的 QPS 規模大概在 1 萬，但是這種異常請求非常少見，每隔幾分鐘就會出現 1 ~ 3 次。一些使用者在 issue 中也提供了捕獲到的延遲較長的請求。從這些截圖中可以看出，確實有請求延遲較高，甚至可以達到秒級別。
這種現象伴隨著另一種現象：某個 worker 程式的 CPU 佔用率達到了 100%。
開發團隊透過不同渠道與這些反饋的使用者溝通得知，這個現象發生的條件是：
- 開啟 prometheus 外掛，並且有 Prometheus Exporter 訪問 APISIX 的 endpoint
/apisix/prometheus/metrics來採集指標； - prometheus 外掛統計的 metrics 的數量達到一定規模，通常是上萬級別；
這個現象是在業界稱為 "長尾請求"，是指在一個請求群體中，大部分請求響應時間較短，但有少部分請求響應時間較長的情況。它可能是由於後端系統的效能瓶頸、資源不足或其他原因導致的。它不是一個致命的 bug，但是它嚴重影響了終端使用者的體驗。
抽絲剝繭
APISIX 基於一個開源的 Lua 庫 nginx-lua-prometheus 開發了 Prometheus 外掛，提供跟蹤和收集 metrics 的功能。當 Prometheus Exporter 訪問 APISIX 暴露的 Prometheus 指標的 endpoint 時，APISIX 會呼叫 nginx-lua-prometheus 提供的函式來暴露 metrics 的計算結果。
開發團隊從社群使用者，企業使用者等渠道收集彙總了長尾請求發生的條件，基本定位了問題所在：nginx-lua-prometheus 中用於暴露 metrics 指標的函式 prometheus:metric_data()。
不過這只是初步推斷，還需要直接的證據來證明長尾請求與此有關，並且需要搞清楚以下問題：
- 這個函式具體做了什麼？
- 這個函式為什麼會造成長尾請求現象？
開發團隊構造了本地復現環境，這個復現環境主要模擬以下場景：
- 模擬客戶端傳送正常請求，被 APISIX 代理到上游
- 模擬 Prometheus Exporter 每隔 5 秒訪問
/apisix/prometheus/metrics，觸發 APISIX 執行prometheus:metric_data()函式
復現環境示意圖：
在執行復現測試時，我們會觀察 wrk2 的測試結果中的 P100 等指標來確認是否發生了長尾請求現象，並且會對執行中的 APISIX 生成火焰圖，來觀測發生長尾請求時，CPU 資源消耗在哪裡。
wrk2 的測試結果如下：
Latency Distribution (HdrHistogram - Uncorrected Latency (measured without taking delayed starts into account))
50.000% 1.13ms
75.000% 2.56ms
90.000% 4.82ms
99.000% 14.70ms
99.900% 27.95ms
99.990% 74.75ms
99.999% 102.78ms
100.000% 102.78ms根據這個測試結果可以得到結論：在測試期間，99% 的請求在 14.70 毫秒內完成了，但是還有很少一部分請求消耗了 100 多毫秒。並且我們用 metrics 數量作為變數，進行了多次測試，發現 metrics 數量與 P100 的延遲呈線性增長。如果 metrics 達到 10 萬級別，P100 將達到秒級別。
生成的火焰圖如下：
從火焰圖的函式堆疊可以看到，prometheus:metric_data() 佔據了最長的橫軸寬度，這證明了大量 CPU 消耗在這裡。這也直接證明了 prometheus:metric_data() 造成長尾請求現象。
下面我們來簡單分析一下 prometheus:metric_data() 函式做了什麼。prometheus:metric_data() 將會從共享記憶體中獲取指標，對指標進行分類，並加工成 Prometheus 相容的文字格式。在這個過程中，會對所有 metrics 按照字典序進行排序，會用正則處理 metrics 的字首。根據經驗，這些都是非常昂貴的操作。
不夠完美的最佳化
當定位到有問題的程式碼後，下一步就是結合火焰圖，詳細分析程式碼，尋找最佳化空間。
從火焰圖可以定位到 fix_histogram_bucket_labels 函式。透過 review 這個函式，我們發現了兩個比較敏感的函式：string:match 和 string:gsub。這兩個函式都不能被 LuaJIT 所 JIT 編譯，只能解釋執行。
LuaJIT 是一個針對 Lua 程式語言的 JIT 編譯器，可以將 Lua 程式碼編譯成機器碼並執行。這相比於使用直譯器來執行 Lua 程式碼，可以提供更高的效能。
使用 LuaJIT 執行 Lua 程式碼的一個優勢是，它可以大幅提升程式碼的執行速度。這使得 APISIX 在處理大量請求時可以保持較低的延遲，並且可以在高併發環境下表現出較好的效能。
關於 LuaJIT 的更多介紹可以參考：什麼是 JIT？
因此不能被 LuaJIT 編譯的程式碼必然會成為潛在的效能瓶頸。
我們整理以上資訊並提交了 issue: optimize the long-tail request phenomenon 到 nginx-lua-prometheus，與這個專案的作者 knyar 一起探討可以最佳化的空間。knyar 響應很及時，我們溝通後明確了可以最佳化的點。於是提交了 PR：chore: use ngx.re.match instead of string match to improve performance 進行最佳化。
在這個 PR 中，主要完成了：
- 用
ngx.re.match替代string:match - 用
ngx.re.gsub替代string:gsub
在完成這個最佳化後，我們其實非常理性地知道，這個最佳化只能提升一些效能，但不能根本解決問題。根本問題是：
Nginx 是一種多程式單執行緒的架構。所有的 worker 程式都會監聽 TCP 連線，但一旦連線進入了某個 worker 程式，就不能再被遷移到其他 worker 程式去處理了。
這意味著，如果某個 worker 程式非常忙碌，那麼該 worker 程式內的其他連線就可能無法及時獲得處理。另一方面，程式內的單執行緒模型意味著，所有 CPU 密集型和 IO 密集型的任務都必須按順序執行。如果某個任務執行時間較長，那麼其他任務就可能被忽略，導致任務處理時間不均勻。
prometheus:metric_data() 佔據了大量的 CPU 時間片進行計算，擠壓了處理正常請求的 CPU 資源。這也是為什麼會看到某個 worker 程式的 CPU 佔用率達到 100%。
基於這個問題，我們在完成上述最佳化後繼續分析，抓取了火焰圖：
上面火焰圖 builtin#100 表示的是 luajit/lua 的庫函式（比如 string.find 這種），可以透過 https://github.com/openresty/openresty-devel-utils/blob/master/ljff.lua 這個專案裡的指令碼來得到對應的函式名稱。
使用方式：
$ luajit ljff.lua 100
FastFunc table.sort由於計算 metrics 時佔用了過量的 CPU，所以我們考慮在計算 metrics 時適當讓出 CPU 時間片。
對於 APISIX 來說，處理正常請求的優先順序是最高的，CPU 資源應當向此傾斜，而 prometheus:metric_data() 只會影響 Prometheus Exporter 獲取指標時的效率。
在 OpenResty 世界，有一個隱秘的讓出 CPU 時間片的方式：ngx.sleep(0) 。我們在 prometheus:metric_data() 中引入這種方式，當處理所有的 metrics 時，每處理固定數目（比如 200 個）的 metrics 後讓出 CPU 時間片，這樣新進來的請求將有機會得到處理。
我們提交了引入這個最佳化的 PR：feat: performance optimization。
在我們的測試場景中，當 metrics 的總數量達到 10 萬級別時，引入這個最佳化之前用 wrk2 測試得到的結果：
Latency Distribution (HdrHistogram - Uncorrected Latency (measured without taking delayed starts into account))
50.000% 10.21ms
75.000% 12.03ms
90.000% 13.25ms
99.000% 92.80ms
99.900% 926.72ms
99.990% 932.86ms
99.999% 934.40ms
100.000% 934.91ms引入這個最佳化後，用 wrk2 測試得到的結果：
Latency Distribution (HdrHistogram - Uncorrected Latency (measured without taking delayed starts into account))
50.000% 4.34ms
75.000% 12.81ms
90.000% 16.12ms
99.000% 82.75ms
99.900% 246.91ms
99.990% 349.44ms
99.999% 390.40ms
100.000% 397.31ms可以看到 P100 的指標大約是最佳化前的 1/3 ～ 1/2。
不過這並沒有完美解決這個問題，透過分析最佳化後的火焰圖：
可以直接看到 builtin#100（即 table.sort） 和 builtin#92（即 string.format）等，仍然佔據了相當寬度的橫軸，這是因為：
prometheus:metric_data()中首先會對所有的 metrics 呼叫table.sort進行排序，當 metrics 到 10 萬級別時，相當於對 10 萬個字串進行排序，並且table.sort不可以被ngx.sleep(0)中斷。- 使用
string.format的地方，以及fix_histogram_bucket_labels無法最佳化，經過與 knyar 交流後得知，這些步驟必須存在以保證prometheus:metric_data()可以產出格式正確的 metrics。
至此，程式碼層面的最佳化手段已經用完了，但遺憾的是，還是沒有完美解決問題。P100 的指標仍然有明顯的延遲。
怎麼辦？
讓我們再回到核心問題：prometheus:metric_data() 佔據了大量的 CPU 時間片進行計算，擠壓了處理正常請求的 CPU 資源。
在 Linux 系統中，CPU 分配時間片的單位是執行緒還是程式？準確來說是執行緒，執行緒才是實際的工作單元。不過 Nginx 是多程式單執行緒的架構，實際在每個程式中只有一個執行緒。
此時我們會想到一個最佳化方向：將 prometheus:metric_data() 轉移到其他執行緒，或者說程式。於是我們調研了兩個方向：
- 用
ngx.run_worker_thread來執行prometheus:metric_data()的計算任務，相當於將 CPU 密集型任務交給執行緒池； - 用單獨的程式來處理
prometheus:metric_data()的計算任務，這個程式不會處理正常請求。
經過 PoC 後，我們否定了方案 1，採用了方案 2。否定方案 1 是因為 ngx.run_worker_thread 只適合執行與請求無關的計算任務，而 prometheus:metric_data() 明顯是與請求有關的。
方案 2 的實現：讓 privileged agent（特權程式）來處理 prometheus:metric_data()。但是特權程式本身不監聽任何埠，也不會處理任何請求。因此，我們需要對特權程式進行一些改造，讓它監聽埠。
最終，我們透過 feat: allow privileged agent to listen port 和 feat(prometheus): support collect metrics works in the priviledged agent 實現了方案 2。
我們使用帶上了這個最佳化的 APISIX 來測試，發現 P100 的指標延遲已經降低到合理的範圍內，長尾請求現象也不存在了。
Latency Distribution (HdrHistogram - Uncorrected Latency (measured without taking delayed starts into account))
50.000% 3.74ms
75.000% 4.66ms
90.000% 5.77ms
99.000% 9.99ms
99.900% 13.41ms
99.990% 16.77ms
99.999% 18.38ms
100.000% 18.40ms這個方案有些巧妙，也解決了最核心的問題。我們在生產環境中觀察並驗證了這個方案，它消除了長尾請求現象，也沒有造成其他額外的異常。
與此同時，我們發現社群中也有類似的修復方案，有興趣的話可以延伸閱讀：如何修改 Nginx 原始碼實現 worker 程式隔離。
展望
在我們修復這個問題的時候，產生了一個新的思考：nginx-lua-prometheus 這個開源庫適合 APISIX 嗎？
我們在 APISIX 側解決了 prometheus:metric_data() 的問題，同時，我們也發現了 nginx-lua-prometheus 存在的其他問題，並且修復了。比如修復記憶體洩漏，以及修復 LRU 快取淘汰。
nginx-lua-prometheus 剛開始是被設計為 Nginx 使用，並不是為了 OpenResty 以及基於 OpenResty 的應用所設計的。OpenResty 生態內沒有比 nginx-lua-prometheus 更成熟的對接 Prometheus 生態的開源專案，因此 nginx-lua-prometheus 不斷被開源社群的力量推動成為適合 OpenResty 生態的方向。
也許我們應該將視野放得更開闊一些，尋找不用修改 APISIX 底層的方式來對接 Prometheus 生態。比如設計一個更適合 APISIX 的依賴庫，或者用某種方式對接 Prometheus 生態中成熟的專案，將收集和計算 metrics 的過程轉移到那些成熟的專案中。
後續
該問題已經在 Apache APISIX 3.1 版本中修復。https://github.com/apache/apisix/pull/8434
關於 API7.ai 與 APISIX
API7.ai 是一家提供 API 處理和分析的開源基礎軟體公司，於 2019 年開源了新一代雲原生 API 閘道器 -- APISIX 並捐贈給 Apache 軟體基金會。此後，API7.ai 一直積極投入支援 Apache APISIX 的開發、維護和社群運營。與千萬貢獻者、使用者、支持者一起做出世界級的開源專案，是 API7.ai 努力的目標。