一、背景
本次問題涉及的系統鍊路如上圖，各系統的基本職責為：
- Proxy：提供請求代理服務。統一代理發往下遊系統的各類請求，進而讓上遊系統無需感覺下遊各服務的使用差異；同時提供精細化的限流、導流等服務特性；
- 拉圖 SDK：面向各存儲平台提供統一的圖檔下載下傳功能。它通常與圖像類算法模型被前後編排在一起；
- 預估引擎：提供模型推理服務。支援各種機器學習、深度學習算法模型的工程部署；
二、問題排查
說明：本文用到的消息隊列内部稱 MetaQ，外部開源版即為 RocketMQ，下文中統一用 “MQ” 指代。
1.問題描述
某天上午收到報警通知，提示 Proxy 系統的入口 MQ 有堆積。打開控制台，發現 500 台 Proxy 機器中，有 1 台機器堆積十分嚴重，而其餘機器均運作正常：
2.一句話根因
先開門見山直接講問題根因（詳細排查流程可參考後文内容）：
- 個别機器堆積：該機器有消費線程被卡住，雖然其餘線程正常消費，但 MQ 機制決定消費位點并不前進；
- HTTP 下載下傳卡住：所使用的 HttpClient 版本有 bug，特定情況下逾時不生效，可能導緻線程一直卡住；
3.排查流程
1）該機器消費速度太慢？
第一反應是這台機器的消費太慢。同樣的消息量，别的機器能快速消化，而它由于消費慢于是持續堆積。然而在 MQ 控制台詳細對比後，發現該機器的業務處理時長、消費 TPS 都與其他機器相近，且不同機器的規格本身也是一樣的：
其次，觀察 Arthas 畫出的火焰圖，右邊兩根比較細長的火焰即為我們系統的業務邏輯（火焰比較高是因為 RPC 的調用棧比較深）。從圖中可看出，火焰圖并沒有明顯的“平頂效應”，火焰的寬度都比較窄，也可說明該機器在執行業務邏輯時中并沒有明顯的耗時卡點，由此也可證明該機器并不是因為業務處理慢而造成的堆積：
2）系統名額是否正常？
登入機器，發現 CPU、MEM、LOAD 均正常，且與正常機器相近，沒有發現明顯線索：
且該機器并無明顯的 Full GC：
3）限流導緻？
Tip：Proxy 在代理請求時會有限流機制，超出限額的流量會觸發阻塞等待，進而保護下遊同步服務。
是以，假如今天系統流量很大，超出了下遊服務能承受的限制，則超出部分的請求會觸發 RateLimiter 限流而阻塞。于是大量 MQ 消費者線程被阻塞，故 Proxy 系統整體的消息消費速度會變慢，最終展現的結果即為入口 topic 堆積。
然而，不管是看該機器的日志還是監控，因限流而阻塞的現象都并不嚴重，比較通暢：
其次，如果真是因為今天系統入口流量大導緻，那應該所有 Proxy 機器（MQ 消費者）都會出現程度相近的堆積。不應該全堆在同 1 台機器上，而其他 499 台機器都正常。是以，排查系統入口流量太大的可能性。
4）MQ 資料傾斜？
預期應該是 500 台 Proxy 機器均分入口 MQ 裡面的消息，有沒有可能是資料配置設定時出現了傾斜，導緻這台機器分到的消息量太多，其他機器分到的消息很少？
檢視 Proxy 上遊系統的代碼，該系統在向 Proxy 發消息時并沒有做自定義 Shuffle，于是會使用 MQ 預設的selectOneMessageQueue政策。而該政策會把目前消息發到基于index % queue_size選出的隊列中。進一步檢視 index 的邏輯，發現它初始化時以一個随機數為起點，每次通路時會 +1 自增：
結合以上兩點，實作的效果即為：對各個 queue 從左到右、均勻地分發消息，并通過 % 實作自動循環：
綜上可知，MQ 預設 shuffle 政策為：把消息均分到各個 queue 中。是以，可排除因為 MQ 發送消息資料傾斜，導緻我們那台 Proxy 機器堆積的可能性。
5）CPU steal ？
Tip：CPU steal 表示虛拟機中運作的程序被主控端上的其他程序/虛拟機占用了 CPU 時間的百分比，高 CPU steal 值通常意味着虛拟機中的程序性能下降。
比如機器規格本身寫的是 4C，實際因為被 steal 後能用的可能隻有 2C。是以展現的結果就是單個請求的 RT 無明顯變化（不同 C 之間差異不大），但 C 的量變少了，是以這台機器整體吞吐變小、消費能力變弱，導緻堆積。
但排查發現，st 正常，排除這種可能：
6）找到線索：MQ 消費位點沒變！
兜兜轉轉一圈都沒找到異常點，由于問題現象是 MQ 堆積，是以又想到可以去檢視中間件的日志尋找線索。果然，通過定向搜尋卡住機器的 queueId，發現這個隊列的消費位點長時間不推進，一直卡在某個位置：
Tip：MQ 拉消息的機制是，拉到的消息會先存放在記憶體中容量為 1000 的 cache 中，然後這些記憶體中的消息将被消費者線程消費。當 cache 滿了時，就不會再從 queue 中拉取。
由此懷疑：是否因為 Proxy 消費停止 or 消費極慢，導緻本地緩存一直是滿的，于是 MQ 會停止向 queue 中拉消息，于是 offset 一直沒變？
但上文已提到，不管從 MQ 控制台、系統監控名額、機器日志來看，該機器都是正常的，與其餘機器沒什麼差別。那為什麼該機器的消費位點就是不動，導緻堆積越來越嚴重？
7）找到根因：某個消費者線程卡住了
Tip：對于本地緩存中的消息，MQ 會開多線程（線程數量由使用者指定）去拉取消費。且為了保證消息不丢失，offset 記錄的隻是最靠前的那條消息。
首先，這個機制是合理的。因為在 At Least Once 語義下，消息允許被消費多次但不允許被遺漏。假設現在有兩個線程同時拉取了前後兩條消息，且後面的消息先執行完畢。由于前一條消息的執行可能會出現異常，是以不能直接用後者的偏移量去更新 offset，否則消費失敗的消息就找不回了。是以，消費位點 offset 的含義是：在該位置及之前的所有消息都已經被正确消費（有點類似 Flink 的 Watermark 機制）。
根據以上機制，回到本問題，假如這台 Proxy 機器的衆多 MQ 消費者線程中有任意一個被卡住，那麼整個 queue 的消費位點将永遠停留在被卡住的消息對應的 offset。此時雖然其他線程都在持續正常消費，但并不能往前推進 offset。另一方面，由于上遊還在源源不斷往隊列中發消息，于是消息隻進不出，堆積量 = 最新入口消息的offset - 消費位點offset隻增不減，展現在控制台上就是堆積越來越嚴重！
基于此分析，通過 jstack 檢視所有 MQ 消費者線程的狀态，的确發現第 251 号線程永遠處于 runnable 狀态！
有理由懷疑，它就是被卡住的消費線程。因為在 Proxy 系統的業務場景中，絕大部分耗時都在 RPC 同步調用深度學習模型這個環節（快的幾百毫秒，慢的可能要幾秒），是以線程大部分時間應該處于等待同步調用傳回的 waiting 狀态！而此處 251 線程永遠是 runnable，一定有問題。
進一步列印詳情，可找到線程卡住的具體代碼位置：
這裡getImageDetail方法内部會通過 HTTP 下載下傳圖檔，以便深度學習模型進行預估。其次，搜尋業務日志也發現，搜不到這個線程的日志。因為從昨晚 10 點開始卡住後，該線程就不會産生任何新的日志了，随着機器日志滾動清理，現在所有日志都将不含該線程的内容：
至此，Proxy 系統個别機器 MQ 堆積嚴重的問題根因找到：該機器的某個消費者線程在通過 HTTP 下載下傳圖檔時一直卡住，導緻整個 queue 的消費位點無法往前推進，進而持續堆積。
8）為什麼 HTTP 會一直卡住？
至此，雖然堆積的根因已經找到，且經過嘗試短期内可通過應用重新開機/機器下線等方式臨時解決。但長遠來看始終存在隐患，因為近期每隔幾天時不時就會出現相同問題。需要徹底查清楚 HTTP 卡住的根因，才能從根本上解決本次問題。
通過幾次蹲點，撈到了一些會導緻線程卡住的圖檔 URL。發現它們都不是内部的圖檔位址，且位址也打不開，也不是 jpg 形式結尾的格式：
https://ju1.vmhealthy.cn
https://978.vmhealthy.cn
https://xiong.bhjgkjhhb.shop 但問題是，即便是輸入這種打不開的極端 URL，由于我們對 HttpClient 設定了 5s 逾時，頂多也就會卡住 5s 啊，為什麼好像逾時機制沒生效，一直卡住了十多個小時？
Tip：HTTP 會需要先建立連接配接，再進行資料傳輸。由此對應着兩種逾時：1、連接配接逾時，針對建立連接配接這一階段；2、socket 逾時，針對資料傳輸過程中的逾時。
經檢查，目前代碼中隻設定了 socket timeout，沒設定 connection timeout，是以懷疑上面那些請求直接卡在了前面的 connect 階段，而又由于沒設定 connect 逾時，是以請求一直卡住？然而，修改代碼後重新嘗試請求這些位址，發現還是會一直卡住，需要進一步排查。
9）找到 HTTP 卡住的根因
Tip：找到根因。在特定版本的 HttpClient 中，基于 SSL 連接配接的請求有 bug：實際會先嘗試建立連接配接，再設定逾時時長，先後順序反了。是以若在連接配接時卡住，逾時還沒來得及設定，本次 HTTP 請求就會一直卡下去……
再回過頭看上面那幾個卡住的 URL，無一例外都是https開頭的！破案了，原來是項目用的 HttpClient 有 bug。在更新了 HttpClient 版本後，重新在預發構造測試請求，線程不再卡住，且全部發到線上環境後，近期頻繁出現的少量機器堆積問題再也沒有出現過。
至此，經曆了許多曲折，問題終于徹底解決。
4.通盤梳理
從最外層 Proxy 個别機器堆積的表象，不斷往内層排查中經曆了許多關鍵節點，直到找到根源。目前所有問題已全部查清，現在站在上帝視角，從内向外完整的因果鍊條如下：
--> Proxy 系統會基于 HttpClient 去下載下傳圖檔，然後調用圖像類模型做預估；
--> 所使用 HttpClient 版本有 bug，在通路 https 位址時，逾時不會生效；
--> Proxy 系統恰好遇到了少量 https 位址，且恰好卡住（低機率事件），于是會因逾時不生效而一直卡住；
--> 基于 MQ 的 At Least Once 機制，消費位點将一直停留在卡住消息所對應的 offset 處（盡管其餘線程都在正常消費）；
--> 上遊系統仍然源源不斷向 Proxy 發送消息，于是消息隻進不出，堆積越來越嚴重；
--> 堆積量超過一定門檻值，觸發監控報警，使用者察覺。
三、總結
本次問題的排查過程略微曲折，但也能學到不少共性的方法論和經驗教訓，在本節統一提煉歸納：
- 善用排查工具：學會使用 jstack、Arthas、jprofile 等利器，在不同情景下善用合适的工具，能高效地發現異常點，找到線索，進而逐漸找到問題根因；
- 異常的敏感度：有時一些發現問題的線索其實早早就展現在了眼前，但當時因為各種原因（比如最初對問題的疑團很多，未排除的幹擾因素多等）導緻并不能立馬發現線索，還需多積累經驗；
- 廣泛查閱資料：除了内網查文檔、找相關人員咨詢，還要學會去外部英文網站查第一手資料；
- 困難時要堅持：對一些隐蔽的問題，很多時候不是出現一次就能立馬發現問題并解決的。可能需要前前後後經曆了幾輪排查，最終才能找到根因；
- 補充底層知識：如果最開始能知道 MQ 的 offset 機制，一些問題就不會走那麼多彎路了。後續在用各種中間件的過程中，要多去了解它們的底層原理；
- 沒有玄學問題：代碼和機器不會騙人，一切“玄學”問題的背後，都有一套嚴謹又合理的成因。
>>>>
參考資料
- HttpClient Bug
- https://issues.apache.org/jira/browse/HTTPCLIENT-1478
- Connection timeout v.s Socket timeout
- https://stackoverflow.com/questions/7360520/connectiontimeout-versus-sockettimeout
作者丨吉多
來源丨公衆号：阿裡開發者（ID：ali_tech）
dbaplus社群歡迎廣大技術人員投稿，投稿郵箱：[email protected]
關于我們
dbaplus社群是圍繞Database、BigData、AIOps的企業級專業社群。資深大咖、技術幹貨，每天精品原創文章推送，每周線上技術分享，每月線下技術沙龍，每季度Gdevops&DAMS行業大會。
關注公衆号【dbaplus社群】，擷取更多原創技術文章和精選工具下載下傳