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

API7_技術團隊發表於2023-03-10

本文介紹了 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 努力的目標。

相關文章