一、搶救

2023 年 10月 27 日，是一個風和日麗的周五，我正在開車上班的路上。難得不怎么堵車，原本心情還是很不錯的。可時間來到 08:50 左右，飛書突然猛烈的彈出消息、告警電話響起，輕松的氛圍瞬間被打破。我們的一個核心應用 bfe-customer-application-query-svc 的 RT 飆升，沒過一會兒，整個 zone-2[1]陷入不可用的狀態(tài)。隨后便是緊張的應急處置，限流、回退配置、擴容…宛如搶救突然倒地不醒的病患，CPR、AED 除顫、腎上腺素靜推… 最終經過十幾分鐘的努力，應用重新上線，zone-2 完全恢復。

二、診斷病因

“病人” 是暫時救回來了，但病因還未找到，隨時都有可能再次陷入危急。到公司后，我便馬不停蹄的開始定位本次故障的根因。

好消息是，在前面應急的過程中，已經掌握了不少有用的信息：

1.bfe-customer-application-query-svc 是近期上線的新應用，故障發(fā)生時每個 zone 僅有 2 個 Pod 節(jié)點；

2.故障發(fā)生的前一天晚上，剛剛進行了確認訂單頁面二次估價接口（以下稱作 confirmEvaluate）的切流（50% → 100%），故障發(fā)生時，該接口的 QPS 是前一天同時段的約 2 倍，如圖1；

3.初步判斷，故障可能是 confirmEvaluate 依賴的一個下游接口（以下稱作 getTagInfo）超時抖動引起的（RT 上漲到了 500ms，正常情況下 P95 在 10ms 左右，持續(xù)約 1s）；

圖 1：confirmEvaluate 故障當日 QPS（zone-1 和 zone-2 流量之和）

綜合這些信息來看，Pod 節(jié)點數過少 + 切流導致流量增加 + 依賴耗時突發(fā)抖動，且最終通過擴容得以恢復，這疊滿的 buff， 將故障原因指向了 “容量不足”。

但這只能算是一種定性的判斷，就好比說一個人突然倒地不醒是因為心臟的毛病，但心臟（心血管）的疾病很多，具體是哪一種呢？在計算機科學的語境中提到 “容量” 這個詞，可能泛指各種資源，例如算力（CPU）、存儲(Mem) 等硬件資源，也可能是工作線程、網絡連接等軟件資源，那么，這次故障究竟是哪個或哪些資源不足了呢？還需要更細致的分析，才能解答。

2.1 初步定位異常指征：tomcat 線程池處理能力飽和，任務排隊

通過 Pod 監(jiān)控，輕易就能排除算力、存儲等硬件資源耗盡的可能性[2]。該應用不依賴數據庫，并未使用連接池來處理同步 I/O也不太可能是連接池耗盡[3]。因此，最有可能還是工作線程出了問題。

我們使用 tomcat 線程池來處理請求，工作線程的使用情況可以通過 “tomcat 線程池監(jiān)控” 獲得。如圖2、圖3，可以看到，Pod-1（..186.8）在 08:54:00 線程池的可用線程數（Available Threads）已經到了最大值（Max Threads）[4]，Pod-2（..188.173）則是在更早的 08:53:30 達到最大值。

圖 2：tomcat 線程池使用情況（*.*.186.8）

圖 3：tomcat 線程池使用情況（*.*.188.173）

為了更好的理解曲線變化的含義，我們需要認真分析一下 tomcat 線程池的擴容邏輯。

不過在這之前，先明確一下兩個監(jiān)控指標和下文將要討論的代碼方法名的映射關系：

圖片

實際上， tomcat線程池（org.apache.tomcat.util.threads.ThreadPoolExecutor）繼承了java.util.concurrent.ThreadPoolExecutor，而且并沒有重寫線程池擴容的核心代碼，而是復用了java.util.concurrent.ThreadPoolExecutor#execute方法中的實現，如圖4。其中，第4行～第23行的代碼注釋，已經將這段擴容邏輯解釋的非常清晰。即每次執(zhí)行新任務（Runnable command）時：

1. Line 25 - 26：首先判斷當前池中工作線程數是否小于 corePoolSize，如果小于 corePoolSize 則直接新增工作線程執(zhí)行該任務；
2. Line 30：否則，嘗試將當前任務放入 workQueue；
3. Line 37：如果第 30 行未能成功將任務放入 workQueue，即workerQueue.offer(command)返回 false，則繼續(xù)嘗試新增工作線程執(zhí)行該任務（第 37 行）；圖 4：tomcat 線程池擴容實現

比較 Tricky 的地方在于 tomcat 定制了第 30 行 workQueue 的實現，代碼位于org.apache.tomcat.util.threads.TaskQueue類中。TaskQueue 繼承自 LinkedBlockingQueue，并重寫了offer方法，如圖5。可以看到：

1. Line 4：當線程池中的工作線程數已經達到最大線程數時，則直接將任務放入隊列；
2. Line 6：否則，如果線程池中的工作線程數還未達到最大線程數，當提交的任務數（parent.getSubmittedCount()）小于池中工作線程數，即存在空閑的工作線程時，將任務放入隊列。這種情況下，放入隊列的任務，理論上將立刻被空閑的工作線程取出并執(zhí)行；
3. Line 8：否則，只要當前池中工作線程數沒有達到最大值，直接返回false。此時圖 4第30行workQueue.offer(command) 就將返回false，這會導致execute方法執(zhí)行第37行的addWorker(command, false)，對線程池進行擴容；

圖 5：tomcat TaskQueue offer() 方法實現

通過分析這兩段代碼，得到如圖6的 tomcat 線程池擴容流程圖。

圖 6：tomcat 線程池擴容邏輯流程圖

歸納一下，可以將 tomcat 線程池的擴容過程拆分為兩個階段。

圖片

可見，一旦進入到 “階段 2”，線程池的處理能力就無法及時消費新到達的任務，于是這些任務就會開始在線程池隊列（workQueue）中排隊，甚至積壓。而結合 圖2、圖3，我們可以得出結論，兩個 Pod 先后都進入了 “階段 2” 飽和狀態(tài)，此時必然已經出現了任務的排隊。對 tomcat 線程池來說，“任務” 這個詞指的就是接收到的外部請求。

2.2 線程池處理能力飽和的后果：任務排隊導致探活失敗，引發(fā) Pod 重啟

當前，該應用基于默認配置，使用 SpringBoot 的健康檢查端口（Endpoint），即actuator/health，作為容器的存活探針。而問題就有可能出在這個存活探針上，k8s 會請求應用的actuator/health端口，而這個請求也需要提交給 tomcat 線程池執(zhí)行。

設想如圖7中的場景。Thread-1 ～ Thread-200 因處理業(yè)務請求而飽和，工作隊列已經積壓了一些待處理的業(yè)務請求（待處理任務 R1 ～ R4），此時 k8s 發(fā)出了探活請求（R5），但只能在隊列中等待。對于任務 R5 來說，最好的情況是剛剛放入工作隊列就立刻有5個工作線程從之前的任務中釋放出來，R1～R5 被并行取出執(zhí)行，探活請求被立即處理。但線程池因業(yè)務請求飽和時，并不存在這種理想情況。通過前文已經知道，confirmEvaluate 的耗時飆升到了 5s，排在 R5 前面的業(yè)務請求處理都很慢。因此比較壞的情況是，R5 需要等待 R1、R2、R3、R4 依次執(zhí)行完成才能獲得工作線程,將在任務隊列中積壓 20s()， 甚至更久。

圖 7：在任務隊列中等待的探活請求

而 bfe-customer-application-query-svc 的探活超時時間設置的是 1s，一旦發(fā)生積壓的情況，則大概率會超時。此時 k8s 會接收到超時異常，因此判定探活失敗。我在 《解決因主庫故障遷移導致的核心服務不可用問題》一文中討論過探活失敗導致 Pod 重啟引發(fā)雪崩的問題，看來這次故障，又是如出一轍。

果然，如圖8、圖9，通過查閱 Pod 事件日志，我發(fā)現 Pod-1（..186.8）在 08:53:59 記錄了探活失敗，隨后觸發(fā)了重啟，Pod-2（..188.173）則是在 08:53:33 記錄了探活失敗，隨后也觸發(fā)了重啟。而這兩個時間正是在上文提到的 “線程池達到飽和" 的兩個時間點附近（Pod-1 08:54:00 和 Pod-2 00:53:30）。

由于 zone-2 僅有 2 個 Pod，當 Pod-1 和 Pod-2 陸續(xù)重啟后，整個 zone-2便沒有能夠處理請求的節(jié)點了，自然就表現出完全不可用的狀態(tài)。

圖 8：探活失敗

圖 9：探活失敗

但為什么只有 zone-2 會整個不可用呢？于是，我又專門對比了 zone-1 的兩個 Pod，如 圖10到圖13。從圖10、圖11可以看到，zone-1 的兩個 Pod 在下游依賴抖動時也發(fā)生了類似 zone-2 的 tomcat 線程池擴容，不同之處在于，zone-1 兩個 Pod 的線程池都沒有達到飽和。從圖12、圖13也可以看到，zone-1 的兩個 Pod 在 八點五十分前后這段時間內，沒有任何探活失敗導致重啟的記錄。

圖 10：tomcat 線程池使用情況

圖 11：tomcat 線程池使用情況

圖 12：探活成功

圖 13：探活成功

顯然， zone-1 并沒有置身事外，同樣受到了耗時抖動的影響，同樣進行了線程池擴容。但可用線程仍有余量，因此并沒有遇到 zone-2 探活失敗，進而觸發(fā) Pod 重啟的問題。

2.3 深度檢查：尋找線程池處理能力惡化的根因

現在，已經明確了 “tomcat 線程池飽和” 是導致這次容量問題的關鍵，但線程池為什么會飽和，還需要繼續(xù)尋找原因。結合應急處置過程中獲得的 #3 線索和過往經驗，首先浮現在我腦中的推論是：SOA 調用下游 getTagInfo 耗時增加，導致 tomcat 線程陸續(xù)陷入等待，最終耗盡了所有可用線程。

2.3.1 與推論相矛盾的關鍵證據：`WAITING`狀態(tài)線程數飆升

自從開始寫這個系列文章，線程就是 “常駐嘉賓”。看過該系列前面幾篇文章的讀者，此時應該想到，既然懷疑是線程等待的問題，高低是要調查下線程狀態(tài)機的。

以下圖14、圖15是 zone-2 兩個 Pod 在故障時段的線程狀態(tài)監(jiān)控曲線（X 軸為時間，Y 軸為線程的數量）。

圖 14：線程狀態(tài)

圖 15：線程狀態(tài)

可以看到，不論 Pod-1（..186.8）還是 Pod-2（..188.173）在故障開始之初（08:52:0030s），都是WAITING狀態(tài)的線程顯著飆升。這有點出乎意料，因為如果開頭的推測成立，下游 getTagInfo 耗時增加，線程的波動應該體現為TIMED_WAITING 狀態(tài)的線程數飆升。

2.3.2 是推論站不住腳，還是錯誤理解了證據？深度溯源框架代碼，撥開迷霧

感到意外也不是空穴來風，下方圖16是通過 jstack 捕獲的基于公司自研 SOA 框架（以下稱作 hermes）的一個典型 tomcat 線程調用棧。其中，第 9 行 ～ 第 11 行棧信息清晰提示了一次 SOA 調用的執(zhí)行過程。從圖中第 2 行可以看到，此時線程此時處于TIMED_WAITING狀態(tài)。

圖 16：一個典型的 Tomcat 線程調用棧

但為了防止先入為主，代入錯誤的假設進行調查，我還是決定重新確認一遍 hermes 框架中執(zhí)行 SOA 調用的代碼實現。圖16中的第11行，cn.huolala.arch.hermes.compatible.protocol.invoker.ConcreteInvocationInvoker#invoke是 SOA 調用的入口方法。該方法的核心代碼如圖17，其中最重要的是第8行和第12行。

1. Line 8：調用ConcreteInvocationInvoker類的另一個doInvoke方法獲得response。真正發(fā)起調用的邏輯其實都是在這個doInvoke方法里實現的；
2. Line 12：調用 response的recreate()方法，并將結果包裝為result。由于省略了非核心代碼，Line 12 實際上就是線程調用棧中提示的的ConcreteInvocationInvoker.java 71行的代碼；

圖 17：ConcreteInvocationInvoker#invoke 方法定義

而 doInvoke方法做的最核心的事情，就是將請求交給 asyncClient 執(zhí)行，這里asyncClient是org.apache.hc.client5.http.impl.async.CloseableHttpAsyncClient的實例（在 hermes 框架中，SOA 請求使用的低級通信協議是 HTTP）。代碼如圖18中第4行～第24行。

1. Line 4：執(zhí)行 asyncClient.execute 方法，發(fā)起 HTTP 請求。execute方法有三個參數，此處只需要重點關注第三個參數。由于是異步客戶端，調用 execute方法將立刻返回，待請求執(zhí)行完成后，asyncClient 將通過第三個參數注冊的回調（callback）邏輯，通知調用方執(zhí)行結果?；卣{邏輯必須實現 org.apache.hc.core5.concurrent.FutureCallback接口，實際上就是自定義 3 個方法：a. void completed(T result)：HTTP 請求執(zhí)行成功，如何處理結果（response）；b .void failed(Exception ex)：請求執(zhí)行失敗，如何處理異常；c. void cancelled()：如何處理請求取消；
2. Line 11：我們重點關注正向流程，即 completed方法的實現。實際上就是解析（unpack） HTTP 的響應結果，然后調用 response.succeeded(result)；

圖 18：ConcreteInvocationInvoker#doInvoke 方法定義

兩段代碼中的 response都是 cn.huolala.arch.hermes.compatible.protocol.handler.JsonRpcResponse的實例，它的實現如圖19，重點關注圖17中用到的 recreate 方法和圖18中用到的 succeeded 方法在 JsonRpcResponse 中是如何定義的。我們會發(fā)現，JsonRpcResponse本質上就是對 CompletableFuture的一層包裝：

1. Line 5：一上來就綁定了一個 future 對象；
2. Line 11：recreate 方法的核心，就是在 future 對象的 get 方法上等待；
3. Line 22：succeeded方法的核心，就是將值（從 HTTP 響應中解析出的調用結果）寫入到 future；

圖 19：JsonRpcResponse 定義

為了更方便理解，我將圖17～圖19 的三段代碼整理為了如圖20的序列圖。通過序列圖可以更清晰的觀察到，調用過程分為 “發(fā)送請求” 和 “等待回調” 兩個階段。在發(fā)送請求階段，asyncClient 將 I/O 任務注冊到內部事件循環(huán)后就立刻返回[8]，tomcat 線程在這一階段不存在任何等待。唯一會導致線程等待的，是在回調階段的第 11 步 future.get(Integer.MAX_VALUE, TimeUnit.MILLISECONDS)調用。但調用 get 方法時指定了超時時間（Integer.MAX_VALUE 毫秒），線程將進入 TIMED_WAITING 狀態(tài)。

圖 20：客戶端發(fā)起 SOA 調用序列圖

更進一步，將 asyncClient 的內部實現展開，完整的 “線程池 + 連接池” 模型如圖21：

圖 21：SOA 調用客戶端線程池、連接池模型

1. 在 asyncClient 內部，專門定義了用于處理網絡 I/O 的工作線程，即 IOReactorWorker Thread。注意它并不是一個線程池，僅僅是多個獨立的 IOReactorWorker 線程，因此 IOReactorWorker 并不會動態(tài)擴容，線程數量是在asyncClient 初始化時就固定下來的。當請求被提交給 asyncClient 時，會根據一個特定的算法選擇其中一個 IOReactorWorker 線程進行接收；
2. 每個 IOReactorWorker 線程內部都綁定了一個請求隊列（requestQueue） 和 一個該線程獨享的 Selector，線程啟動后，即開啟 Selector 事件循環(huán)，代碼如圖22；
3. 在 tomcat 線程中，SOA 調用最終會被包裝成一個 HTTP 請求并投遞到某個 IOReactorWorker 線程的請求隊列里。隨后 IOReactorWorker 在 Selector 事件循環(huán)中會不斷的取出（poll）隊列中的請求，包裝為 Channel 注冊到 Selector 循環(huán)中，即圖22中代碼的第19行。請求提交給 asyncClient 后，tomcat 線程就將在 future.get(Integer.MAX_VALUE, TimeUnit.MILLISECONDS)上等待回調；
4. IOReactorWorker 會從連接池中取出（lease）一個連接并執(zhí)行請求。注意 asyncClient 的連接池管理方式比較特別，是根據 route（即不同的 host+port/domain 組合）進行分組的，每個 route 有一個獨立的連接池；
5. 請求執(zhí)行完成后，IOReactorWorker 會通過 future.complete(value)將請求結果回寫給 tomcat 線程，此時第 3 步中的get方法調用將返回；

圖 22：IOReactorWorker 線程內部的事件循環(huán)核心邏輯

通過上面的分析可以得出結論：一次標準的 SOA 調用，并不會導致 tomcat 線程進入 WAITING 狀態(tài)。

1. 雖然 tomcat 線程確實會在 HTTP 請求執(zhí)行完成前，一直等待 future.get(Integer.MAX_VALUE, TimeUnit.MILLISECONDS) 返回，隨著 SOA 調用耗時增加，等待的時間也會更久，從而導致可用線程逐漸耗盡。但正如最初的設想一樣，此時應該 TIMED_WAITING狀態(tài)的線程數飆升，與實際監(jiān)控曲線的特征不符；
2. 此外，IOReactorWorker 線程的嫌疑也可以排除。一是因為IOReactorWorker線程的數量在初始化 asyncClient 的時候就已經固定了下來，不會 “飆升”。二是不論this.selector.select(this.selectTimeoutMillis)（如圖22，第5行）還是讀寫 I/O，線程狀態(tài)都是 RUNNABLE，而非 WAITING。

2.3.3 弄巧成拙的業(yè)務代碼

既然已經意識到 WAITING 狀態(tài)線程數飆升的事實，不如基于這個事實給問題代碼做個畫像。那么，什么樣的代碼可能會導致線程進入WAITING狀態(tài)呢？

還是在 《解決因主庫故障遷移導致的核心服務不可用問題》 一文中（3.1 節(jié)），我曾詳細分析了WAITING和 TIMED_WAITING 狀態(tài)的區(qū)別。線程進入WAITING 或 TIMED_WAITING狀態(tài)，通常是因為代碼中執(zhí)行了如下表格列出的方法。

圖片

或者，也有可能是執(zhí)行了將這些方法進行過上層包裝后的方法。例如，

• 當執(zhí)行 CompletableFuture 實例的 future.get(timeout, unit)方法時，在 CompletableFuture 的底層實現中，最終會調用`LockSupport.parkNanos(o, timeout)方法；
• 而如果執(zhí)行 CompletableFuture 實例的 future.get()方法（不指定超時時間），則最終會調用 LockSupport.park(o) 方法；

因此，執(zhí)行 future.get(timeout, unit)方法將導致線程進入 TIMED_WAITING狀態(tài)（正如前文討論的框架代碼一樣），而執(zhí)行 future.get()方法則會導致線程進入WAITING 狀態(tài)。

Sherlock Holmes 有句名言：

“當你排除一切不可能的情況，剩下的，不管多難以置信，那都是事實?！?/p>

盡管 bfe-customer-application-query-svc 的定位是業(yè)務聚合層的應用，主要是串行調用下游領域服務，編排產品功能，通常不太可能主動使用上面提到的這些方法來管理線程。但畢竟已經確定了框架代碼中并無任何導致WAITING狀態(tài)線程數飆升的證據，因此我還是決定到業(yè)務代碼中一探究竟。

沒想到很快就發(fā)現了蛛絲馬跡。幾乎沒廢什么功夫，就從 confirmEvaluate 方法中找到了一段高度符合畫像的代碼，經過精簡后，如圖23。當看到第 15 行和第 16 行的 future.get()調用時，我不禁眉頭一緊。

圖 23：confirmEvaluate 方法實現

和當時開發(fā)這段代碼的同學了解了一下， 創(chuàng)作背景大致是這樣的：

由于種種歷史原因，在確認頁估價時，需要根據 “是否到付”，分兩次調用下游進行估價（即圖23中第6行getArrivalPayConfirmEvaluateResult 和 第 10 行 getCommonConfirmEvaluateResult）。confirmEvaluate 的耗時主要受調用下游計價服務的耗時影響，原先日常 P95 約為 750ms，串行調用兩次會導致 confirmEvaluate 方法的耗時 double，達到 1.5s 左右。考慮到用戶體驗，于是決定通過多線程并發(fā)執(zhí)行來減少耗時。

雖然想法無可厚非，但具體到代碼實現卻有幾個明顯的問題：

1. 在調用 future.get() 等待線程返回結果時，沒有設置超時時間，這是非常不可取的錯誤實踐；
2. getArrivalPayConfirmEvaluateResult 和 getCommonConfirmEvaluateResult 中包裝了繁重的業(yè)務邏輯（且重復性極高），不僅會調用下游的計價服務，還會調用包括 getTagInfo 在內的多個其他下游服務的接口。而最初的目的僅僅是解決 “調用兩次計價服務” 的問題；
3. 使用了自定義線程池 BizExecutorsUtils.EXECUTOR 而不是框架推薦的動態(tài)線程池；

尤其是看到使用了自定義線程池 BizExecutorsUtils.EXECUTOR 的時候，我第二次眉頭一緊，心中預感問題找到了。BizExecutorsUtils.EXECUTOR 的定義如圖24。

1. Line 16：可以看到線程池的最大線程數只有 20；
2. Line 19：工作隊列卻很大，可以允許 1K+ 個任務排隊；

此外，一個平?？雌饋砗锨楹侠恚迷谶@里卻雪上加霜的設計是，EXECUTOR 是靜態(tài)初始化的，在同一個 JVM 進程中全局唯一。這里的線程池定義，很難不讓我想到只有 3 個診室，卻排了 500 號病人的呼吸內科。

圖 24：自建線程池定義

正是因為這個線程池的引入，導致了 “瓶頸效應”，如圖25，顯然 confirmEvaluate 的執(zhí)行過程要比圖21描繪的模型更加復雜。作為 SOA 請求的入口，方法本身確實是通過 tomcat 線程執(zhí)行的。故障發(fā)生時，tomcat 線程池配置的最大線程數為 200（單個 Pod 最多能夠并發(fā)處理 200 個請求）。但在方法內部，估價的核心邏輯被包裝成了兩個子任務，提交到了最大僅有 20 個工作線程的 EXECUTOR 自定義線程池執(zhí)行。也就是說，EXECUTOR 自定義線程池的處理能力僅有 tomcat 線程池的 1/10，卻需要處理 2 倍于 QPS 的任務量。

圖 25：引入自定義線程池導致的 “瓶口效應”

我們不妨結合前文的信息做個粗略的估算：

1. 首先，在 getTagInfo 耗時抖動前，請求量約為 75+ requests/s，負載均衡到 2 個 zone 的共 4 個 Pod 上，單個 Pod 的請求量約為 18 ～ 20 requests/s；
2. 在 getTagInfo 耗時抖動前，一次估價流程的耗時約為 750ms，getTagInfo 耗時飆升后（10ms → 500ms），一次估價流程的耗時理論上增加到 1.3s 左右。由于 confirmEvaluate 內部拆分的子任務，幾乎就是完整的估價流程，因此，兩個子任務的執(zhí)行耗時也需要 1.3s 左右；
3. 在 getTagInfo 耗時抖動的 1s 內，雖然請求量無顯著變化，但根據 2 倍關系，這 1s 內將會產生 36 ～ 40 個任務（單個 Pod），提交給 EXECUTOR 線程池執(zhí)行；
4. 由于單個子任務執(zhí)行耗時 1s，也就是說，在這 1s 內提交到 EXECUTOR 線程池的任務都無法執(zhí)行完，EXECUTOR 的 20 個工作線程，將全部飽和，大約有一半的任務正占用工作線程，另一半的任務在工作隊列中等待；

顯然，這是一個十分簡單的計算模型，并不能反映現實中更加復雜的情況[12]，但并不妨礙說明問題（和 2.2 節(jié)中分析的案例一模一樣的問題）。子任務可能在 EXECUTOR 線程池工作隊列中排隊很久， 從而導致 confirmEvaluate 方法在 future.get() 上等待（圖23第15、16行），一直占用 tomcat 工作線程，新到達的請求只能不斷創(chuàng)建新的 tomcat 線程來執(zhí)行。同時，confirmEvaluate 響應變慢或超時錯誤，又會誘發(fā)用戶重試，進一步帶來請求量激增（如圖1，抖動發(fā)生后，請求量飆升到了約 100 requests/s），導致 EXECUTOR 線程池的處理能力進一步惡化。如此惡性循環(huán)，最終徹底耗盡 tomcat 線程池的可用工作線程。

通過 Trace 跟蹤，我們可以輕松找出支持 “瓶頸效應” 的證據，如圖26。confirmEvaluate 方法首先會調用下游的 get_user_info 接口獲取用戶信息[13]。然后，該方法將構建兩個子任務并將其提交至 EXECUTOR 線程池（圖23 第 5～7 行、 第 9～11 行）。值得注意的是，get_user_info 調用完成后，到子任務被提交到 EXECUTOR 線程池的這段時間里，代碼只做了一些參數包裝和驗證的簡單邏輯輯[13]，因此這部分代碼的執(zhí)行時間基本可以忽略不計。我們可以近似的理解為，在 get_user_info 的調用完成后，子任務就立即提交給了 EXECUTOR 線程池。

圖 26：子任務在 EXECUTOR 線程池工作隊列中排隊

當 EXECUTOR 線程池處理能力足夠時，子任務被提交到 EXECUTOR 線程池后也應該迅速被執(zhí)行，因此從 get_user_info 接口調用完成到子任務開始執(zhí)行中間的間隔時間應該很短。但從 圖26中給出的 Trace 鏈路可以看到[14]，從 get_user_info 接口調用，到子任務 1 和子任務 2 開始執(zhí)行，間隔了約 6s 的時間[15]。而這 6s 反映的正是子任務在 EXECUTOR 線程池中等待執(zhí)行的耗時。

2.4 診斷結論

至此，終于可以給出診斷結論：

圖片

三、醫(yī)囑和處方

本文的最后，來談談從這次故障中能獲得怎樣的經驗教訓？

3.1 穩(wěn)定性預算要有保障，評估 I/O 密集型應用的容量時不能只看 CPU 水位

不知大家在閱讀前文時是否好奇過，為什么堂堂一個核心應用，每個 zone 只部署 2 個 Pod？

一個最基本的共識是，部署兩個 Pod 是故障冗余的最低限度[16]。但對于核心應用而言，僅用兩個 Pod 互為備份有點過于極限了。這是因為，核心應用通常需要處理更復雜的業(yè)務邏輯并承載更多的流量，當其中一個 Pod 故障時，剩下唯一的 Pod 將瞬間承載全部的正常流量和陡增的異常流量（往往會伴有用戶重試的流量），很容易引發(fā)性能問題。

事實上，就在故障發(fā)生前不久，該應用在每個 zone 還部署有 4 個 Pod。按照 2.3.3 節(jié)的計算方式算一下就會發(fā)現，如果故障發(fā)生時的流量均勻分配到 8 個 Pod 上，單個 Pod 上 EXECUTOR 線程池每秒需要處理的子任務數量約為 18 個，工作線程還有余量，這次的故障有極大的可能就不會發(fā)生[17]。

那為什么 Pod 數量縮水了呢？因為在控制成本的大背景下，CI 團隊多次找到應用的 Owner 并以 CPU 水位為唯一標準溝通縮容計劃，最終兩邊達成一致，將每個 zone 的 Pod 數量縮容到了 2 個?；剡^頭來看，這是一個非常錯誤的決策，原因至少有以下兩點：

1. 正如剛才所說，這是一個核心應用。每個 zone 僅部署 2 個 Pod 過于極限；
2. 這是一個 I/O 密集型應用，不應該將 CPU 水位作為評估容量的唯一參考指標；

前者本質上是一個“成本（或預算）規(guī)劃”的問題。通過系統縮容以減少整體運營成本，的確行之有效。但如果在執(zhí)行過程中，各方過于追求 “節(jié)省成本”，便可能在不自知的情況下，削減了原本必要的開支。比如在本文討論的場景中，部署額外的若干個 Pod 以增強應對異常情況（依賴耗時、流量等波動）的能力就是必要的投入，即提供基本業(yè)務功能以外的穩(wěn)定性預算。

后者則反映出一個更為艱巨的問題：我們缺乏科學的方法（或統一的標準）來評估容量應該設定為多少。對于一個 I/O 密集型應用，許多有限資源均可能在 CPU 算力達到瓶頸之前先達到瓶頸，比如本文討論的線程池，以及連接池、帶寬等。因此，評估 I/O 密集型應用的容量并不是一件容易的事情。往往需要根據流量的預測值進行壓測，同時根據線程池、連接池、帶寬等有限資源的飽和度指標，結合接口響應時間（延遲），異常數量（錯誤）等健康度指標來綜合分析判斷。然而我們仍缺乏指導這種評估的最佳實踐，下一節(jié)我們將繼續(xù)討論。

3.2 謹慎的對系統性能做出假設，壓測結果才是檢驗性能的唯一方

實際上，bfe-customer-application-query-svc 及其依賴的下游 bfe-commodity-core-svc 均為同一項目申請、同一批次上線的新應用。一般情況下，我們會對新上線的應用進行專門的壓力測試。而正如上文討論的，自定義線程池瓶頸問題在壓力測試中應該很容易被觸發(fā)。然而后來經過證實，只針對 bfe-commodity-core-svc 進行了壓測，卻并未對 bfe-customer-application-query-svc 進行壓測，這讓我感到難以理解。

進一步深入了解當時的上下文后，我發(fā)現在決定不對 bfe-customer-application-query-svc 進行壓力測試的過程中，主要有兩種觀點：

1. 壓測也難以發(fā)現導致本次故障的問題；
2. confirmEvaluate 是由舊應用遷移過來的。舊應用運行穩(wěn)定且沒有任何問題，新應用也會同樣運行良好；

首先，且不論第一種觀點是否正確，它都不能作為不進行壓測的充分理由。因為在當時我們并未具有現在的全知全覽視野，壓測的目的并不僅僅在于尋找本次發(fā)生的這一具體問題，而是揭示所有可能存在的、尚未明確的性能風險。我更傾向于將這一觀點定性為事后為之前的過失找補的話術，而不是一個專業(yè)的技術性判斷。

第二種觀點則揭示了我們在日常工作中常有的偏見。相較于編碼和功能測試，由于工期緊張、時間壓力等因素，我們常常將那些非日常的任務，如壓測，視為可有可無的附加項，主觀上傾向于省略這項工作。然而，壓測真的那么復雜嗎？答案并非如此。舉個例子，后期我們在預發(fā)環(huán)境通過壓測復現此次故障的演練，包括前期準備工作和制定演練方案，幾個小時內就可完成。

往根兒上說，這反映了我們在 “測試方案設計（或測試分析）” 工作上的不足，本質上還是在 “如何開展容量/性能評估“ 的問題上，缺少最佳實踐、缺少科學的方法論指導。

另一個致命的假設，是在將流量比例從 50% 提升到 100% 的窗口前期做出的：

“50% 流量運行了很多天都沒問題，放量到 100% 應該穩(wěn)了。”

只論業(yè)務邏輯的正確性，這個假設或許沒有太大的問題。但如果把容量因素納入考慮，這個假設就過于想當然了，缺少了一次至關重要的壓測論證。

其實，實踐檢驗真理的粗淺道理每個人都懂。難的是在工作中不心存僥幸，踏踏實實的執(zhí)行到位。

3.3 將有限資源納入監(jiān)控

在穩(wěn)定性工程中，我們常會談到 “可監(jiān)控” 這個詞，指的是通過具有統計意義和顯著性的可觀測指標來反映系統運行狀況。

對系統中的有限資源進行針對性監(jiān)控往往大有裨益。主要有以下三點理由：

1. 有限資源的耗竭往往是許多性能問題的根本原因。因此，針對性的監(jiān)控將大大加速性能問題的排查；
2. 有限資源經常也是跨越多個業(yè)務場景的“共享資源”。因此，一旦這些資源引發(fā)性能問題，可能迅速導致整個系統的崩潰；
3. 有限資源的耗竭過程通常伴隨著流量的增加。但在達到瓶頸之前，常規(guī)的業(yè)務指標很難反映出這一趨勢；

實際上，在大家熟知的那些被廣泛使用的開源項目中，就有很多值得借鑒的例子。例如，通過圖2、圖3所示的監(jiān)控指標，能夠很好的幫助我們觀察運行時 tomcat 線程池的飽和度。再比如 HikariCP，提供了十分豐富的監(jiān)控指標，以便于觀察連接池運行時的各種狀態(tài)。

如果從一開始，能夠效仿 tomcat 的做法，在引入 EXECUTOR 自定義線程池的時候，將繁忙線程數、最大線程數指標監(jiān)控起來，是有機會在切流 50% 的時候就發(fā)現危機的。按 2.3.3 節(jié)討論的方式粗略換算，切流 50% 時 EXECUTOR 線程池的繁忙線程占比將超過 80%[19]。任何素質過關的研發(fā)，此時都會審慎的評估容量風險。

腳注

[1] 基于現有架構，我們的應用部署拆分成了兩個 zone，zone 的概念在這里不做展開，可以簡單理解為兩個異地機房，流量按照接近 1:1 的比例均分到兩個 zone 中；

[2] zone-2 兩個 Pod 的 CPU 利用率、內存利用率等指標都處于低水位。注意文中將 CPU、內存 稱作硬件資源只是為了敘述方便，實際上它們都是基于真實硬件資源 “虛擬化“ 之后的 ”配額”；

[3] 我在《解決因主庫故障遷移導致的核心服務不可用問題》一文中討論過連接池耗盡的問題，如果你感興趣，可以看一看這篇文章；

[4] 圖3、圖4中的曲線含義：① Max Threads，即圖中的藍色曲線，表示由人為配置的 tomcat 線程池的最大線程數，該應用的最大線程數被設置為 200。② Available Threads，即圖中的橙色曲線，表示當前線程池中已經創(chuàng)建的線程數。③Busy Threads，即圖中的綠色曲線，表示當前線程池中正在處理任務的繁忙線程數；

[5] 這里實際上還判斷了線程池是否仍在運行（isRunning(c))，為了表述重點，省略了對這段代碼的解釋；

[6] 也有可能是線程池已經被 shutdown，即 isRunning(c) 返回了 false。同[4]，為了表述重點，省略了對這種可能性的解釋；

[7] 這個過程主要是讀取 HTTP 響應的 body（JSON String），反序列化為 Java POJO。這部分代碼不在這里展開；

[8] 這個表達為了能更簡單的說明問題，其實并不準確。更準確的是請求被放入 IOReactorWorker 線程的請求隊列后立即返回。下文會通過更清晰的模型來解釋這個邏輯；

[9] 通過 IOReactorConfig 類的 ioThreadCount屬性設置，通常是 CPU 核數的 2 倍；

[10] 實現代碼在org.apache.hc.core5.reactor.IOWorkers#newSelector 方法中，有兩種實現 PowerOfTwoSelector 和 GenericSelector，在這里不做詳細展開；

[11] 實際上，除了直接處理請求的 tomcat 線程，框架代碼還創(chuàng)建并管理著一些其他的工作線程，但這類線程的飽和度、擴縮容通常并不會受到業(yè)務流量變化的影響。例如 consulCacheScheduledCallback 線程，主要和依賴的下游 SOA 應用的數量有關。因此，這類線程的嫌疑也可以排除；

[12] 例如，在這個計算模型中，getTagInfo 抖動前后，一次估價流程耗時分別為 750ms 和 1.3s，增加的耗時是由 getTagInfo 接口的響應時長唯一決定的，這是一種理想狀態(tài)。實際上，一旦線程池處理能力衰退，會有相當一部分請求的耗時，遠遠大于 1.3s 這個值，耗時并不僅僅只受 getTagInfo 接口的影響；

[13] 這部分的代碼并未在圖23中展示，包含在了第 3 行 [Ellipis Java code] 省略的代碼中；

[14] 需要注意的是，盡管圖26中我標注了 子任務 1（getArrivalPayConfirmEvaluateResult）在前、子任務 2（getCommonConfirmEvaluateResult）在后，但在并發(fā)狀態(tài)下，實際的執(zhí)行順序并不一定是這樣。這里僅僅是為了敘述方便；

[15] 嚴謹的說，最后一列時間戳（Timestamp）表示的是 “開始執(zhí)行” 的時間，因此 6s 實際上是 get_user_info 調用開始執(zhí)行到子任務開始執(zhí)行的間隔時間，包含了 get_user_info 調用的耗時。但這里 get_user_info 調用耗時只有 10ms，相對于 6s 而言，完全可以忽略不計；

[16] 單一 Pod 發(fā)生故障的概率是非常高的，而兩個 Pod 同時發(fā)生故障的概率則會大大降低，因此，至少部署兩個 Pod 以防止在單一 Pod 故障時整個應用都不可用。同時，兩個 Pod 也是為了更好的實現平滑發(fā)布；

[17] 注意，這里并不是說一定不會發(fā)生。實際上每秒 18 個任務對于 EXECUTOR 線程池來說也已經比較極限，即便躲過了這一次故障，也未必能躲過下一次；

[18] 這就好比在急性心梗發(fā)病前，患者的心電圖通常不會有太顯著的異常。但如果進行冠狀動脈造影就能夠更早的發(fā)現心梗風險。更進一步，通過定期體檢檢測血脂、膽固醇等指標，也能夠更早體現疾病發(fā)生的趨勢；

[19] 注意，這只是一個參考：34 reqeusts/s ÷ 4 pods × 2 ÷ 20(max pool size) × 100% = 85%;