本篇文章記錄了一次接口慢查問題排查過程，該問題産生的現象迷惑性較高。同時由于問題偶發性高，排查難度也比較大。排查過程從 druid 資料源“導緻”的一個慢查現象作為切入點，逐漸分析，排除諸多可能性後仍無解。之後重新審視故障現象，換個角度分析，找到了問題根因。最後對問題原因進行了驗證确認，結果符合預期。到此，排查過程算是結束了，本文對問題進行記錄歸檔。
前段時間收到業務同僚回報，說他們應用的某台機器連續兩天多個接口出現了兩次慢查情況（偶發性較高）。但持續時間比較短，但很快又恢複了。Pinpoint 調用鍊資訊如下：
圖1：長 RT 接口調用鍊資訊
上圖是業務同學回報過來的資訊，可以看出從 MyBatis 的 SqlSessionTemplate#selectList 方法到 MySQL 的 ConnectionImpl#prepareStatement 方法之間出現了 2111 毫秒的間隔，正是這個間隔導緻了接口 RT 升高。接下來針對這個現象進行分析。
從全鍊路追蹤系統給出的鍊路資訊來看，問題的原因似乎很明顯，就是 selectList 和 prepareStatement 之間存在着長耗時的操作。理論上隻要查出哪裡出現了長耗時操作，以及為什麼發生，問題就解決了。于是先不管三七二十一，直接分析 MyBatis 的源碼吧。
MyBatis 的 SqlSessionTemplate#selectList 方法的調用鍊比較長，這裡就不一一分析，感興趣可以看一下我三年前的文章 MyBatis 源碼分析 - SQL 的執行過程。SqlSessionTemplate#selectList 最終會執行到 SimpleExecutor#doQuery，該方法在執行後續邏輯前，會先調用 SimpleExecutor#prepareStatement 進行預編譯。prepareStatement 方法涉及到兩個外部操作，一個是擷取資料庫連接配接，另一個是執行調用 MySQL 驅動相關方法執行預編譯。
從圖1的監控上看，預編譯速度很快，可以确定預編譯沒有問題。現在，把注意力移到 getConnection 方法上，這個方法最終會向底層的 druid 資料源申請資料庫連接配接。druid 采用的是生産者消費者模型來維護連接配接池，更詳細的介紹參考我的另一篇文章。如果連接配接池中沒有可用連接配接，這個時候業務線程就會等待 druid 生産者建立連接配接。如果生産者建立連接配接速度比較慢，或者活躍連接配接數達到了最大值，此時業務線程就必須等待了。好在業務應用接了 druid 監控，我們可以通過監控了解連接配接池的情況。
圖2：druid 監控圖
上圖是用 excel 繪制的，資料經過編輯，與當時情況存在一定的偏差，但不影響後續的分析。從監控上來看，連接配接池中的空閑連接配接全部被借出去了，但仍然不夠，于是生産者不停的建立連接配接。這裡引發了我們的思考，為什麼活躍連接配接數會突然上升這麼多？可能是出現了慢查。與此同時，業務線程的等待次數和等待時間大幅上漲，這說明 druid 連接配接生産者的“産能”似乎不足，以至于部分業務線程出現了等待。什麼情況下生産者建立連接配接會出現問題呢？我們當時考慮到的情況如下：
網絡出現了延遲或者丢包，造成重傳
阿裡雲 RDS 執行個體負載很高，無法及時響應用戶端的連接配接建立請求
先說第二種情況，RDS 負載的問題很好确認，阿裡雲上有 RDS 的監控。我們确認了兩次問題發生時的監控曲線，發現執行個體負載并不高，沒有明顯波動，是以情況二可以排除。那情況一呢，網絡會不會出現問題呢？這個猜想不好排除。原因如下：
活躍連接配接數正常情況下會很低，暴漲一般都不是正常現象。假如一個 Java 線程從發出 SQL 請求到收到資料耗時 5ms，那麼一條連接配接可以達到 200 的 QPS。而這個單機 QPS 還不足 200，不應該用掉這麼多連接配接，除非出現了慢查。但是我們用阿裡雲的 SQL 洞察服務裡也沒發現慢 SQL，是以可以排除掉慢查的可能性。不是慢查，似乎隻能甩鍋給網絡了，一定是當時的網絡（接鍋好手）出了問題。
如果真是網絡出問題了，那麼 druid 生産者“産能”不足的問題似乎也能得到合理的解釋。但是經過我們的分析，發現了一些沖突點，如下：
圖3：某個長 RT 請求的鍊路追蹤資料
從鍊路資料上來看，SQL 的預編譯和執行時間都是很快的，沒有出現明顯的等待時間。如果說上面的情況是偶然，但是我們翻看了很多鍊路資料，都發現 SQL 的預編譯和執行速度都很快，不存在明顯的延遲。是以，把鍋甩給網絡是不合适的。
排查到這裡，思路斷了。首先沒有發現慢查，其次資料庫資源也是充足的，最後網絡似乎也沒問題。都沒有問題，那問題出在哪裡呢？
首先檢視了問題機器的 QPS，發現沒有突發流量。雖有一定波動，但總體仍然平穩。
圖4：QPS 折線圖
接着看了應用的 CPU 使用率，發現了一點問題，使用率突然上升了很多。
圖5：CPU 使用率折線圖
詢問了業務同學，這個點沒有定時任務，QPS 與以往相似，沒有什麼異常。目前不知道 CPU 為什麼會突然上升這麼多，這個資訊暫時無法提供有效的幫助，先放着。最後再看一下網絡 I/O 監控。
圖6：網絡流量監控圖
入站流量與出站流量在問題發生時間段内都出現了上升，其中出站流量上升幅度很大，說明當時應該有大量的資料發出去。但具體是哪些接口的行為，目前還不知道。
接着分析了一下業務日志，我們發現了一些 WARN 級别資訊：
這兩種日志說實話沒什麼用，因為這些日志是結果，本就應該發生的。除了 WARN 資訊，業務日志裡找不到任何異常資訊。需要說明的是，我們并沒有設定業務線程擷取連接配接重試次數，預設重試次數是0。但這裡卻進行了一次重試，而我們預期是業務線程在指定時間内擷取連接配接失敗後，應抛出一個 GetConnectionTimeoutException 異常。這個應該是 druid 的代碼有問題，我給他們提了一個 issue (#4381)，但是沒人回複。這個問題修複也很簡單，算是一個 good first issue，有興趣的朋友可以提個 Pull Request 修複一下。
業務日志沒有太多可用資訊，我們繼續尋找其他的線索，這次我們從 JVM 監控裡發現了端倪。
問題發生的那一小段時間内，JVM 發生了多次的 YGC 和 FGC，而且部分 GC 的耗時很長。
圖7：GC 次數與耗時監控
那麼現在問題來了，GC 是原因還是結果？由于 GC 發生的時間與接口慢查出現的時間都在 9.56:30 之後，時間上大家是重疊的，誰影響了誰，還是互相影響，這都是不清楚的。GC 的引入似乎讓排查變得更為複雜了。
到這裡資訊收集的差不多了，但是問題原因還是沒有推斷出來，十分郁悶。
如果我們仍然從 druid 這個方向排查，很難查出原因。時間寶貴，現在要綜合收集的資訊重新思考一下了。既然發生了 GC，那麼應用的記憶體消耗一定是上升了。再綜合網絡 I/O 的情況，短時間内出現了比較大的波動，好像也能說明這個情況。但當時網絡流量并不是特别大，似乎還不足以引發 GC。支撐力不足，先放一邊。另外，應用的 QPS 沒有多大變動，但是 CPU 負載卻突然上升了很多。加之幾次 GC 的耗時很長，搞不好它們倆之間有關聯，即長時間的 GC 導緻了 CPU 負載上升。目前，有兩個排查方向，一個是從網絡 I/O 方向排查，另一個是從 GC 方向排查。就現象而言，GC 的問題似乎更大，是以後續選擇從 GC 方向排查。
JVM 進行 GC，說明記憶體使用率一定是上去了。記憶體上升是一個累積過程，如果我們把排查時間從發生長耗時 GC 的時刻 9:57:00 向前推一分鐘，沒準會發現點什麼。于是我到全鍊路追蹤平台上按耗時倒序，拉取了問題應用在 9:56:00 這一分鐘内的長 RT 接口清單，發現耗時靠前的十幾個都是 queryAll 這個方法。如下：
圖8：queryAll 方法耗時倒序清單
我們看一下耗時最長請求的調用鍊資訊：
圖9：耗時最長請求的鍊路資訊
首先我們可以看到 MySQL 驅動的 execute 執行時間特别長，原因後面分析。其次 redis 緩存的讀取耗時非常短，沒有問題。但 redis 用戶端寫入資料耗時非常長，這就很不正常了。
于是立即向應用開發要了代碼權限，分析了一下代碼。僞代碼如下：
代碼做的事情非常簡單，那為什麼會耗時這麼多呢？原因是這樣的，如果緩存失效了，queryAll 這個方法一次性會從資料庫裡取出上萬條資料，且表結構包含了一些複雜的字段，比如業務規則，通訊位址等，是以單行記錄相對較大。加之資料取出後，又進行了兩次模型轉換（DO → DTO → TO），轉換的模型數量比原始模型數量要多一半，約 1.5 萬個，TO 數量與 DTO 一緻。模型轉換完畢後，緊接着是寫緩存，寫緩存又涉及序列化。queryAll 方法調用一次會在新生代生成約五份比較大的資料，第一份是資料集 ResultSet，第二份是 DO 清單，第三份是 DTO 清單，第四份 TO 清單，最後一份是 DTO 清單的序列化内容。加之兩秒内出現了二十多次調用，加劇了記憶體消耗，這應該能解釋為什麼 GC 次數會突然上升這麼多。下面還有幾個問題，我用 FAQ 的方式解答：
Q：那 GC 耗時長如何解釋呢？
A：我猜測可能是垃圾回收器整理和複制大批量記憶體資料導緻的。
-------------------------------------------------✂-------------------------------------------------
Q：還有 execute 方法和 set 方法之間為什麼會間隔這麼長時間内？
A：目前的猜測是模型類的轉換以及序列化本身需要一定的時間，其次這期間應該有多個序列化過程同時在就行，不過這也解釋不了時間為什麼這麼長。不過如果我們把 GC 考慮進來，就會得到相對合理的解釋。從 9:56:33 ~ 5:56:52 之間出現了多次 GC，而且有些 GC 的時間很長（長時間的 stop the world），造成的現象就是兩個方法之間的間隔很長。實際上我們可以看一下 9:56:31 第一個 queryAll 請求的調用鍊資訊，會發現間隔并不是那麼的長：
圖10：queryAll 正常情況下的耗時情況
是以，我們可以認為後續調用鍊 execute 和 set 方法之間的超長間隔是因為 CPU 使用率，GC 等因素共同造成的。
Q：第一個 set 和第二個 set 間隔為什麼也會這麼長？
A：第一個 set 是我們自定義的邏輯，到第二個 set 之間似乎沒有什麼特别的東西，當時沒有查出問題。不過好在複現的時候，發現了端倪，後面章節給予解釋。
最後，我們把目光移到初始的問題上，即業務同僚回報部分接口 RT 上升的問題。下面仍用 FAQ 的方式解答。
Q：為什麼多個接口的 RT 都出現了上升？調用鍊參考下圖：
圖11：某個長 RT 接口的鍊路資訊
A：部分業務線程在等待 druid 建立資料庫連接配接，由于 GC 的發生，造成了 STW。GC 對等待邏輯會造成影響。比如一個線程調用 awaitNanos 等待3秒鐘，結果這期間發生了5秒的 GC（STW），那麼當 GC 結束時，線程立即就逾時了。在 druid 資料源中， maxWait 參數控制着業務線程的等待時間，代碼如下：
經過前面的排查，很多現象都得到了合理的解釋，是時候給個結論了：
本次 xxx 應用多個接口在兩天連續出現了兩次 RT 大幅上升情況，排查下來，初步認為是 queryAll 方法緩存失效，短時間内幾十個請求大批量查詢資料、模型轉換以及序列化等操作，消耗量大量的記憶體，觸發了多次長時間的 GC。造成部分業務線程等待逾時，進而造成 Dubbo 線程池被打滿。
接下來，我們要按照這個結論進行複現，以證明我們的結論是正确的。
問題複現還是要盡量模拟當時的情況，否則可能會造成比較大的誤差。為了較為準确的模拟當時的接口調用情況，我寫了一個可以控制 QPS 和請求總數的驗證邏輯。
複現的效果符合預期，CPU 使用率，網絡 I/O 都上去了（由于監控屬于公司内部系統，就不截圖了）。同時 GC 也發生了，而且耗時也很長。GC 日志如下：
接着，我們再看一下那段時間内的接口耗時情況：
圖12：問題複現時的 queryAll 耗時倒序清單
所有接口的消耗時間都很長，也是符合預期的。最後再看一個長 RT 接口的鍊路資訊：
圖13：某個長 RT 接口的鍊路資訊
會發現和圖檔1，也就是業務同學回報的問題是一緻的，說明複現效果符合預期。
驗證到這裡，可以證明我們的結論是正确的了。找到了問題的根源，這個問題可以歸檔了。
出于性能考慮，Pinpoint 給出的鍊路資訊力度比較粗，以緻于我們無法詳細得知 queryAll 方法的耗時構成是怎樣的。為了搞清楚這裡面的細節，我對 queryAll 方法耗時情況進行比較詳細的測算。在應用負載比較低的情況下觸發一個請求，并使用 Arthas 的 trace 指令測算鍊路耗時。得到的監控如下：
圖14：正常情況下 queryAll 方法鍊路資訊
這裡我對三個方法調用進行了編号，方法 ① 和 ② 之間存在 252 毫秒的間隔，方法 ② 和 ③ 之間存在 294 毫秒的間隔。Arthas 列印出的鍊路耗時情況如下：
圖15：queryAll 方法耗時測量
這裡的編号與上圖一一對應，其中耗時比較多的調用我已經用顔色标注出來了。首先我們分析間隔1的構成，方法 ① 到 ② 之間有兩個耗時的操作，一個是批量的模型轉換，也就是把 DO 轉成 DTO，消耗了約 79.6 毫秒。第二個耗時操作是 Object 的 toString 方法，約 171.6。兩者加起來為 251.2，與全鍊路追蹤系統給出的資料是一緻的。這裡大家肯定很好奇為什麼 toString 方法會消耗掉這麼多時間，答案如下：
這是方法 ① 和 ② 路徑中的一個方法，這段代碼看起來人畜無害，問題發生在判空邏輯上（曆史代碼，不讨論其合理性）。當 value 是一個非常大集合或數組時，toString 會消耗掉很多時間。同時，toString 也會生成一個大字元串，無形中消耗了記憶體資源。這裡看似不起眼的一句代碼，實際上卻是性能黑洞。這也提醒我們，在操作大批量資料時，要注意時空消耗。
最後，我們再來看一下方法 ② 和 ③ 之間的間隔問題，原因已經很明顯了，就是 value 序列化過程消耗了大量的時間。另外，序列化好的位元組數組也會暫時存在堆記憶體中，也是會消耗不少記憶體資源的。
到這裡整個分析過程就結束了，通過上面的分析，我們可以看出，一次簡單的查詢竟然能引出了這麼多問題。很多在以前看起來稀疏平常的邏輯，偶然間也會成為性能殺手。日常工作中，還是要經常關注一下應用的性能問題，為應用的穩定運作保駕護航。
由于問題發生時，JVM 隻是進行了 FGC，記憶體并沒有溢出，是以沒有當時的記憶體 dump 資料。不過好在問題可以穩定複現，通過對 JVM 進行一些配置，我們可以讓 JVM 發生 FGC 前自動對記憶體進行 dump。這裡使用 jinfo 指令對正在運作的 JVM 程序設定參數：
拿到記憶體資料後，接下來用 mat 工具分析一下。首先看一下記憶體洩露吧：
圖16：應用記憶體洩露分析
從記憶體消耗比例上來看，确實存在一些問題，主要是與 dubbo 的線程有關。随便選一個線程，在支配樹（dominator tree）視圖中檢視線程支配的對象資訊：
圖17：dubbo 線程支配樹情況
從上圖可以看出，dubbo 線程 retained heap 約為 66 MB，主要由兩個大的對象 ArrayList 和 StringBuilder 組成。ArrayList 裡面存放的是 DTO，單個 DTO 的 retained heap 大小約為 5.1 KB。StringBuilder 主要是 toString 過程産生的，消耗了接近 26 MB 的記憶體。從 dump 的記憶體資料中沒找到 DO 清單，應該是在 YGC 時被回收了。
好了，關于記憶體的分析就到這吧，大概知道記憶體消耗是怎樣的就夠了，更深入的分析就不搞了。
由于排查經驗較少，這個問題斷斷續續也花了不少時間。這中間有找不到原因時的郁悶，也有發現一些猜想符合預期時的欣喜。不管怎麼樣，最後還是找到了問題的原因。在幫助别人的同時，自己也學到了不少東西。總的來說，付出是值得的。本文的最後，對問題排查過程進行簡單的總結吧。
一開始，我直接從具展現象開始排查，期望找到引發現象的原因。進行了各種猜想，但是都沒法得出合理的結論。接着擴大資訊面，仍然無果。之後綜合各種資訊，思考之後，換個方向排查，找到了原因。最後進行驗證，并對一些疑點進行解釋，整個過程結束。
最後說說這次排查過程存在的問題吧。第一個問題是沒有注意甄别别人回報過來的資訊，沒有對資訊進行快速确認，而是直接深入了。花了很多時間嘗試了各種猜想，最終均無果。由于别人回報過來的資訊通常都是比較零碎片面的，甚至是不正确的。對于這些資訊可以快速确認，幸運的話能直接找到原因。但如果發現此路不通，就不要鑽牛角尖了，因為這個現象可能隻是衆多現象中的一個。在這個案例中，接口長 RT 看起來像是 druid 導緻的，實際上卻是因為 GC 造成 STW 導緻的。繼續沿着 druid 方向排查，最終一定是南轅北轍。其他的問題都是小問題，就不說了。另外，排查過程中要注意儲存當時的一些日志資料，避免因資料過期而丢失，比如阿裡雲 RDS SQL 洞察是有時間限制的。
本篇文章到此結束，感謝閱讀！
本文在知識共享許可協定 4.0 下釋出，轉載請注明出處 作者：田小波 原創文章優先釋出到個人網站，歡迎通路：https://www.tianxiaobo.com
本作品采用知識共享署名-非商業性使用-禁止演繹 4.0 國際許可協定進行許可。