從 1 秒到 10 毫秒!在 APISIX 中減少 Prometheus 請求阻塞

語言: CN / TW / HK

本文介紹了 Prometheus 插件造成長尾請求現象的原因,以及如何解決這個問題。

作者屠正鬆,Apache APISIX PMC Member。

原文鏈接

現象

在 APISIX 社區中,曾有部分用户陸續反饋一種神祕現象:部分請求延遲較長。具體表現為:當流量請求進入一個正常部署的 APISIX 集羣時,偶爾會出現部分請求有 1 ~ 2 秒的延遲。用户的 QPS 規模大概在 1 萬,但是這種異常請求非常少見,每隔幾分鐘就會出現 1 ~ 3 次。一些用户在 issue 中也提供了捕獲到的延遲較長的請求。從這些截圖中可以看出,確實有請求延遲較高,甚至可以達到秒級別。

High Latency Requests 1.png

High Latency Requests 2.png

這種現象伴隨着另一種現象:某個 worker 進程的 CPU 佔用率達到了 100%。

100% CPU.png

開發團隊通過不同渠道與這些反饋的用户溝通得知,這個現象發生的條件是:

  1. 開啟 prometheus 插件,並且有 Prometheus Exporter 訪問 APISIX 的 endpoint /apisix/prometheus/metrics 來採集指標;
  2. 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()

不過這只是初步推斷,還需要直接的證據來證明長尾請求與此有關,並且需要搞清楚以下問題:

  1. 這個函數具體做了什麼?
  2. 這個函數為什麼會造成長尾請求現象?

開發團隊構造了本地復現環境,這個復現環境主要模擬以下場景:

  1. 模擬客户端發送正常請求,被 APISIX 代理到上游
  2. 模擬 Prometheus Exporter 每隔 5 秒訪問 /apisix/prometheus/metrics,觸發 APISIX 運行 prometheus:metric_data() 函數

復現環境示意圖:

Reproduced Environment.png

在執行復現測試時,我們會觀察 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 將達到秒級別。

生成的火焰圖如下:

Flame Graph1

從火焰圖的函數堆棧可以看到,prometheus:metric_data() 佔據了最長的橫軸寬度,這證明了大量 CPU 消耗在這裏。這也直接證明了 prometheus:metric_data() 造成長尾請求現象。

下面我們來簡單分析一下 prometheus:metric_data() 函數做了什麼。prometheus:metric_data() 將會從共享內存中獲取指標,對指標進行分類,並加工成 Prometheus 兼容的文本格式。在這個過程中,會對所有 metrics 按照字典序進行排序,會用正則處理 metrics 的前綴。根據經驗,這些都是非常昂貴的操作。

不夠完美的優化

當定位到有問題的代碼後,下一步就是結合火焰圖,詳細分析代碼,尋找優化空間。

從火焰圖可以定位到 fix_histogram_bucket_labels 函數。通過 review 這個函數,我們發現了兩個比較敏感的函數:string:matchstring: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%。

基於這個問題,我們在完成上述優化後繼續分析,抓取了火焰圖:

Flame Graph2

上面火焰圖 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。

不過這並沒有完美解決這個問題,通過分析優化後的火焰圖:

Flame Graph After Optimization

可以直接看到 builtin#100(即 table.sort) 和 builtin#92(即 string.format)等,仍然佔據了相當寬度的橫軸,這是因為:

  1. prometheus:metric_data() 中首先會對所有的 metrics 調用 table.sort 進行排序,當 metrics 到 10 萬級別時,相當於對 10 萬個字符串進行排序,並且 table.sort 不可以被 ngx.sleep(0) 中斷。
  2. 使用 string.format 的地方,以及 fix_histogram_bucket_labels 無法優化,經過與 knyar 交流後得知,這些步驟必須存在以保證 prometheus:metric_data() 可以產出格式正確的 metrics。

至此,代碼層面的優化手段已經用完了,但遺憾的是,還是沒有完美解決問題。P100 的指標仍然有明顯的延遲。

怎麼辦?

讓我們再回到核心問題:prometheus:metric_data() 佔據了大量的 CPU 時間片進行計算,擠壓了處理正常請求的 CPU 資源。

在 Linux 系統中,CPU 分配時間片的單位是線程還是進程?準確來説是線程,線程才是實際的工作單元。不過 Nginx 是多進程單線程的架構,實際在每個進程中只有一個線程。

此時我們會想到一個優化方向:將 prometheus:metric_data() 轉移到其他線程,或者説進程。於是我們調研了兩個方向:

  1. ngx.run_worker_thread 來運行 prometheus:metric_data() 的計算任務,相當於將 CPU 密集型任務交給線程池;
  2. 用單獨的進程來處理 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 portfeat(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 努力的目標。