記一次介面慢查排查
1. 前言
本篇文章記錄了一次介面慢查問題排查過程，該問題產生的現象迷惑性較高。同時由於問題偶發性高，排查難度也比較大。排查過程從 druid 數據源「導致」的一個慢查現象作為切入點，逐步分析，排除諸多可能性後仍無解。之後重新審視故障現象，換個角度分析，找到了問題根因。最後對問題原因進行了驗證確認，結果符合預期。到此，排查過程算是結束了，本文對問題進行記錄歸檔。
2. 問題描述
前段時間收到業務同事回饋，說他們應用的某台機器連續兩天多個介面出現了兩次慢查情況（偶發性較高）。但持續時間比較短，但很快又恢復了。Pinpoint 調用鏈資訊如下：
圖1：長 RT 介面調用鏈資訊
上圖是業務同學回饋過來的資訊，可以看出從 MyBatis 的 SqlSessionTemplate#selectList 方法到 MySQL 的 ConnectionImpl#prepareStatement 方法之間出現了 2111 毫秒的間隔，正是這個間隔導致了介面 RT 升高。接下來針對這個現象進行分析。
3. 排查過程
3.1 直奔主題
從全鏈路追蹤系統給出的鏈路資訊來看，問題的原因似乎很明顯，就是 selectList 和 prepareStatement 之間存在著長耗時的操作。理論上只要查出哪裡出現了長耗時操作，以及為什麼發生，問題就解決了。於是先不管三七二十一，直接分析 MyBatis 的源碼吧。
public class SimpleExecutor extends BaseExecutor {
public <E> List<E> doQuery(MappedStatement ms, Object parameter, RowBounds rowBounds, ResultHandler resultHandler, BoundSql boundSql) throws SQLException {
Statement stmt = null;
try {
Configuration configuration = ms.getConfiguration();
StatementHandler handler = configuration.newStatementHandler(wrapper, ms, parameter, rowBounds, resultHandler, boundSql);
stmt = prepareStatement(handler, ms.getStatementLog()); // 預編譯
return handler.<E>query(stmt, resultHandler);
} finally {
closeStatement(stmt);
}
}
private Statement prepareStatement(StatementHandler handler, Log statementLog) throws SQLException {
Statement stmt;
Connection connection = getConnection(statementLog); // 獲取資料庫連接
stmt = handler.prepare(connection, transaction.getTimeout()); // 執行預編譯
handler.parameterize(stmt);
return stmt;
}
}
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 的預編譯和執行速度都很快，不存在明顯的延遲。因此，把鍋甩給網路是不合適的。
排查到這裡，思路斷了。首先沒有發現慢查，其次資料庫資源也是充足的，最後網路似乎也沒問題。都沒有問題，那問題出在哪裡呢？
3.2 擴大資訊面
3.2.1 基本資訊
首先查看了問題機器的 QPS，發現沒有突發流量。雖有一定波動，但總體仍然平穩。
圖4：QPS 折線圖
接著看了應用的 CPU 使用率，發現了一點問題，使用率突然上升了很多。
圖5：CPU 使用率折線圖
詢問了業務同學，這個點沒有定時任務，QPS 與以往相似，沒有什麼異常。目前不知道 CPU 為什麼會突然上升這麼多，這個資訊暫時無法提供有效的幫助，先放著。最後再看一下網路 I/O 監控。
圖6：網路流量監控圖
入站流量與出站流量在問題發生時間段內都出現了上升，其中出站流量上升幅度很大，說明當時應該有大量的數據發出去。但具體是哪些介面的行為，目前還不知道。
3.2.2 業務日誌資訊
接著分析了一下業務日誌，我們發現了一些 WARN 級別資訊：
# 業務執行緒打出的 WARN 日誌，表示等待連接超時，重試一次
2021-07-20 09:56:42.422 [DubboServerHandler-thread-239] WARN com.alibaba.druid.pool.DruidDataSource [DruidDataSource.java:1400] - get connection timeout retry : 1
2021-07-20 09:56:42.427 [DubboServerHandler-thread-242] WARN com.alibaba.druid.pool.DruidDataSource [DruidDataSource.java:1400] - get connection timeout retry : 1
2021-07-20 09:56:42.431 [DubboServerHandler-thread-240] WARN com.alibaba.druid.pool.DruidDataSource [DruidDataSource.java:1400] - get connection timeout retry : 1
# Dubbo TimeoutFilter 答疑超時日誌
2021-07-20 09:56:42.432 [DubboServerHandler-thread-254] WARN org.apache.dubbo.rpc.filter.TimeoutFilter [TimeoutFilter.java:60] - [DUBBO] invoke time out. method: xxx arguments: [yyy] , url is dubbo://172.***.***.***:20880/****
2021-07-20 09:56:42.489 [DubboServerHandler-thread-288] WARN org.apache.dubbo.rpc.filter.TimeoutFilter [TimeoutFilter.java:60] - [DUBBO] invoke time out. method: **** arguments: [***, ***] , url is dubbo://172.***.***.***:20880/****
這兩種日誌說實話沒什麼用，因為這些日誌是結果，本就應該發生的。除了 WARN 資訊，業務日誌里找不到任何異常資訊。需要說明的是，我們並沒有設置業務執行緒獲取連接重試次數，默認重試次數是0。但這裡卻進行了一次重試，而我們預期是業務執行緒在指定時間內獲取連接失敗後，應拋出一個 GetConnectionTimeoutException 異常。這個應該是 druid 的程式碼有問題，我給他們提了一個 issue (#4381)，但是沒人回復。這個問題修復也很簡單，算是一個 good first issue，有興趣的朋友可以提個 Pull Request 修復一下。
業務日誌沒有太多可用資訊，我們繼續尋找其他的線索，這次我們從 JVM 監控里發現了端倪。
3.2.3 GC 資訊
問題發生的那一小段時間內，JVM 發生了多次的 YGC 和 FGC，而且部分 GC 的耗時很長。
圖7：GC 次數與耗時監控
那麼現在問題來了，GC 是原因還是結果？由於 GC 發生的時間與介面慢查出現的時間都在 9.56:30 之後，時間上大家是重疊的，誰影響了誰，還是互相影響，這都是不清楚的。GC 的引入似乎讓排查變得更為複雜了。
到這裡資訊收集的差不多了，但是問題原因還是沒有推斷出來，十分鬱悶。
3.3 重新審視
3.3.1 綜合分析
如果我們仍然從 druid 這個方向排查，很難查出原因。時間寶貴，現在要綜合收集的資訊重新思考一下了。既然發生了 GC，那麼應用的記憶體消耗一定是上升了。再綜合網路 I/O 的情況，短時間內出現了比較大的波動，好像也能說明這個情況。但當時網路流量並不是特別大，似乎還不足以引發 GC。支撐力不足，先放一邊。另外，應用的 QPS 沒有多大變動，但是 CPU 負載卻突然上升了很多。加之幾次 GC 的耗時很長，搞不好它們倆之間有關聯，即長時間的 GC 導致了 CPU 負載上升。目前，有兩個排查方向，一個是從網路 I/O 方向排查，另一個是從 GC 方向排查。就現象而言，GC 的問題似乎更大，因此後續選擇從 GC 方向排查。
3.3.2 換個思路
JVM 進行 GC，說明記憶體使用率一定是上去了。記憶體上升是一個累積過程，如果我們把排查時間從發生長耗時 GC 的時刻 9:57:00 向前推一分鐘，沒準會發現點什麼。於是我到全鏈路追蹤平台上按耗時倒序，拉取了問題應用在 9:56:00 這一分鐘內的長 RT 介面列表，發現耗時靠前的十幾個都是 queryAll 這個方法。如下：
圖8：queryAll 方法耗時倒序列表
我們看一下耗時最長請求的調用鏈資訊：
圖9：耗時最長請求的鏈路資訊
首先我們可以看到 MySQL 驅動的 execute 執行時間特別長，原因後面分析。其次 redis 快取的讀取耗時非常短，沒有問題。但 redis 客戶端寫入數據耗時非常長，這就很不正常了。
於是立即嚮應用開發要了程式碼許可權，分析了一下程式碼。偽程式碼如下：
public XxxService {
// 備註：該方法快取實際上使用了 Spring @Cacheable 註解，而非顯示操作快取
public List queryAll(int xxxId) {
// 1、檢查快取，命中則立即返回
List xxxDTOs = customRedisClient.get(xxxId);
if (xxxDTOs != null) return list;
// 2、快取未命中，查詢資料庫
List xxxDOs = XxxDao.queryAll(xxxId);
xxxDTOS = convert(xxxDOs)
// 3、寫入快取
customRedisClient.set(xxxId, xxxDTOs, 300s);
return list;
}
}
程式碼做的事情非常簡單，那為什麼會耗時這麼多呢？原因是這樣的，如果快取失效了，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 參數控制著業務執行緒的等待時間，程式碼如下：
public class DruidDataSource extends DruidAbstractDataSource {
private DruidPooledConnection getConnectionInternal(long maxWait) throws SQLException {
// ...
final long nanos = TimeUnit.MILLISECONDS.toNanos(maxWait);
if (maxWait > 0) {
// 嘗試在設定時間內從連接池中獲取連接
holder = pollLast(nanos);
} else {
holder = takeLast();
}
// ...
}
}
3.4 初步結論
經過前面的排查，很多現象都得到了合理的解釋，是時候給個結論了：
本次 xxx 應用多個介面在兩天連續出現了兩次 RT 大幅上升情況，排查下來，初步認為是 queryAll 方法快取失效，短時間內幾十個請求大批量查詢數據、模型轉換以及序列化等操作，消耗量大量的記憶體，觸發了多次長時間的 GC。造成部分業務執行緒等待超時，進而造成 Dubbo 執行緒池被打滿。
接下來，我們要按照這個結論進行復現，以證明我們的結論是正確的。
4. 問題復現
問題復現還是要盡量模擬當時的情況，否則可能會造成比較大的誤差。為了較為準確的模擬當時的介面調用情況，我寫了一個可以控制 QPS 和請求總數的驗證邏輯。
public class XxxController {
@Resource
private XxxApi xxxApi;
public Object invokeQueryAll(Integer qps, Integer total) {
RateLimiter rl = RateLimiter.create(qps.doubleValue());
ExecutorService es = Executors.newFixedThreadPool(50);
for (Integer i = 0; i < total; i++) {
es.submit(() -> {
rl.acquire();
xxxApi.queryAll(0);
});
}
return "OK";
}
}
復現的效果符合預期，CPU 使用率，網路 I/O 都上去了（由於監控屬於公司內部系統，就不截圖了）。同時 GC 也發生了，而且耗時也很長。GC 日誌如下：
2021-07-29T19:09:07.655+0800: 631609.822: [GC (Allocation Failure) 2021-07-29T19:09:07.656+0800: 631609.823: [ParNew: 2797465K->314560K(2831168K), 2.0130187 secs] 3285781K->1362568K(4928320K), 2.0145223 secs] [Times: user=3.62 sys=0.07, real=2.02 secs]
2021-07-29T19:09:11.550+0800: 631613.717: [GC (Allocation Failure) 2021-07-29T19:09:11.551+0800: 631613.718: [ParNew: 2831168K->314560K(2831168K), 1.7428491 secs] 3879176K->1961168K(4928320K), 1.7443725 secs] [Times: user=3.21 sys=0.04, real=1.74 secs]
2021-07-29T19:09:13.300+0800: 631615.467: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1646608K(2097152K)] 1965708K(4928320K), 0.0647481 secs] [Times: user=0.19 sys=0.00, real=0.06 secs]
2021-07-29T19:09:13.366+0800: 631615.533: [CMS-concurrent-mark-start]
2021-07-29T19:09:15.934+0800: 631618.100: [GC (Allocation Failure) 2021-07-29T19:09:15.934+0800: 631618.101: [ParNew: 2831168K->2831168K(2831168K), 0.0000388 secs]2021-07-29T19:09:15.934+0800: 631618.101: [CMS2021-07-29T19:09:17.305+0800: 631619.471: [CMS-concurrent-mark: 3.668/3.938 secs] [Times: user=6.49 sys=0.01, real=3.94 secs]
(concurrent mode failure): 1646608K->1722401K(2097152K), 6.7005795 secs] 4477776K->1722401K(4928320K), [Metaspace: 224031K->224031K(1269760K)], 6.7028302 secs] [Times: user=6.71 sys=0.00, real=6.70 secs]
2021-07-29T19:09:24.732+0800: 631626.899: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1722401K(2097152K)] 3131004K(4928320K), 0.3961644 secs] [Times: user=0.69 sys=0.00, real=0.40 secs]
2021-07-29T19:09:25.129+0800: 631627.296: [CMS-concurrent-mark-start]
2021-07-29T19:09:29.012+0800: 631631.179: [GC (Allocation Failure) 2021-07-29T19:09:29.013+0800: 631631.180: [ParNew: 2516608K->2516608K(2831168K), 0.0000292 secs]2021-07-29T19:09:29.013+0800: 631631.180: [CMS2021-07-29T19:09:30.733+0800: 631632.900: [CMS-concurrent-mark: 5.487/5.603 secs] [Times: user=9.29 sys=0.00, real=5.60 secs]
(concurrent mode failure): 1722401K->1519344K(2097152K), 6.6845837 secs] 4239009K->1519344K(4928320K), [Metaspace: 223389K->223389K(1269760K)], 6.6863578 secs] [Times: user=6.70 sys=0.00, real=6.69 secs]
接著，我們再看一下那段時間內的介面耗時情況：
圖12：問題復現時的 queryAll 耗時倒序列表
所有介面的消耗時間都很長，也是符合預期的。最後再看一個長 RT 介面的鏈路資訊：
圖13：某個長 RT 介面的鏈路資訊
會發現和圖片1，也就是業務同學回饋的問題是一致的，說明復現效果符合預期。
驗證到這裡，可以證明我們的結論是正確的了。找到了問題的根源，這個問題可以歸檔了。
5. 進一步探索
5.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 方法會消耗掉這麼多時間，答案如下：
public void put(Object key, Object value) {
// 省略判空邏輯
// 把 key 和 value 先轉成字元串，再進行判空
if (StringUtils.isBlank(key.toString()) || StringUtils.isBlank(value.toString())) {
return;
}
CacheClient.set(key, value);
}
這是方法 ① 和 ② 路徑中的一個方法，這段程式碼看起來人畜無害，問題發生在判空邏輯上（歷史程式碼，不討論其合理性）。當 value 是一個非常大集合或數組時，toString 會消耗掉很多時間。同時，toString 也會生成一個大字元串，無形中消耗了記憶體資源。這裡看似不起眼的一句程式碼，實際上卻是性能黑洞。這也提醒我們，在操作大批量數據時，要注意時空消耗。
最後，我們再來看一下方法 ② 和 ③ 之間的間隔問題，原因已經很明顯了，就是 value 序列化過程消耗了大量的時間。另外，序列化好的位元組數組也會暫時存在堆記憶體中，也是會消耗不少記憶體資源的。
到這裡整個分析過程就結束了，通過上面的分析，我們可以看出，一次簡單的查詢竟然能引出了這麼多問題。很多在以前看起來稀疏平常的邏輯，偶然間也會成為性能殺手。日常工作中，還是要經常關注一下應用的性能問題，為應用的穩定運行保駕護航。
5.2 記憶體消耗測算
由於問題發生時，JVM 只是進行了 FGC，記憶體並沒有溢出，所以沒有當時的記憶體 dump 數據。不過好在問題可以穩定復現，通過對 JVM 進行一些配置，我們可以讓 JVM 發生 FGC 前自動對記憶體進行 dump。這裡使用 jinfo 命令對正在運行的 JVM 進程設置參數：
jinfo -flag +HeapDumpBeforeFullGC $JVM_PID
拿到記憶體數據後，接下來用 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 時被回收了。
好了，關於記憶體的分析就到這吧，大概知道記憶體消耗是怎樣的就夠了，更深入的分析就不搞了。
6. 總結
由於排查經驗較少，這個問題斷斷續續也花了不少時間。這中間有找不到原因時的鬱悶，也有發現一些猜想符合預期時的欣喜。不管怎麼樣，最後還是找到了問題的原因。在幫助別人的同時，自己也學到了不少東西。總的來說，付出是值得的。本文的最後，對問題排查過程進行簡單的總結吧。
一開始，我直接從具體現象開始排查，期望找到引發現象的原因。進行了各種猜想，但是都沒法得出合理的結論。接著擴大資訊面，仍然無果。之後綜合各種資訊，思考之後，換個方向排查，找到了原因。最後進行驗證，並對一些疑點進行解釋，整個過程結束。
最後說說這次排查過程存在的問題吧。第一個問題是沒有注意甄別別人回饋過來的資訊，沒有對資訊進行快速確認，而是直接深入了。花了很多時間嘗試了各種猜想，最終均無果。由於別人回饋過來的資訊通常都是比較零碎片面的，甚至是不正確的。對於這些資訊可以快速確認，幸運的話能直接找到原因。但如果發現此路不通，就不要鑽牛角尖了，因為這個現象可能只是眾多現象中的一個。在這個案例中，介面長 RT 看起來像是 druid 導致的，實際上卻是因為 GC 造成 STW 導致的。繼續沿著 druid 方向排查，最終一定是南轅北轍。其他的問題都是小問題，就不說了。另外，排查過程中要注意保存當時的一些日誌數據，避免因數據過期而丟失，比如阿里雲 RDS SQL 洞察是有時間限制的。
本篇文章到此結束，感謝閱讀！
本文在知識共享許可協議 4.0 下發布，轉載請註明出處
作者：田小波
原創文章優先發布到個人網站，歡迎訪問：//www.tianxiaobo.com
本作品採用知識共享署名-非商業性使用-禁止演繹 4.0 國際許可協議進行許可。
