記一次接口慢查排查

時間 2021-08-12

標籤 java git github redis 數據庫 apache 數組緩存 bash 網絡欄目 Java 简体版

原文原文鏈接

1. 前言

本篇文章記錄了一次接口慢查問題排查過程，該問題產生的現象迷惑性較高。同時因爲問題偶發性高，排查難度也比較大。排查過程從 druid 數據源「致使」的一個慢查現象做爲切入點，逐步分析，排除諸多可能性後仍無解。以後從新審視故障現象，換個角度分析，找到了問題根因。最後對問題緣由進行了驗證確認，結果符合預期。到此，排查過程算是結束了，本文對問題進行記錄歸檔。java

2. 問題描述

前段時間收到業務同事反饋，說他們應用的某臺機器連續兩天多個接口出現了兩次慢查狀況（偶發性較高）。但持續時間比較短，但很快又恢復了。Pinpoint 調用鏈信息以下：git

圖1：長 RT 接口調用鏈信息github

上圖是業務同窗反饋過來的信息，能夠看出從 MyBatis 的 SqlSessionTemplate#selectList 方法到 MySQL 的 ConnectionImpl#prepareStatement 方法之間出現了 2111 毫秒的間隔，正是這個間隔致使了接口 RT 升高。接下來針對這個現象進行分析。redis

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 驅動相關方法執行預編譯。apache

從圖1的監控上看，預編譯速度很快，能夠肯定預編譯沒有問題。如今，把注意力移到 getConnection 方法上，這個方法最終會向底層的 druid 數據源申請數據庫鏈接。druid 採用的是生產者消費者模型來維護鏈接池，更詳細的介紹參考個人另外一篇文章。若是鏈接池中沒有可用鏈接，這個時候業務線程就會等待 druid 生產者建立鏈接。若是生產者建立鏈接速度比較慢，或者活躍鏈接數達到了最大值，此時業務線程就必須等待了。好在業務應用接了 druid 監控，咱們能夠經過監控瞭解鏈接池的狀況。數組

圖2：druid 監控圖緩存

上圖是用 excel 繪製的，數據通過編輯，與當時狀況存在必定的誤差，但不影響後續的分析。從監控上來看，鏈接池中的空閒鏈接所有被借出去了，但仍然不夠，因而生產者不停的建立鏈接。這裏引起了咱們的思考，爲何活躍鏈接數會忽然上升這麼多？多是出現了慢查。與此同時，業務線程的等待次數和等待時間大幅上漲，這說明 druid 鏈接生產者的「產能」彷佛不足，以致於部分業務線程出現了等待。什麼狀況下生產者建立鏈接會出現問題呢？咱們當時考慮到的狀況以下：bash

網絡出現了延遲或者丟包，形成重傳
阿里雲 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) {
        // 一、檢查緩存，命中則當即返回
        List xxxDTOs = customRedisClient.get(xxxId);
        if (xxxDTOs != null) return list;
        
        // 二、緩存未命中，查詢數據庫
        List xxxDOs = XxxDao.queryAll(xxxId);
        xxxDTOS = convert(xxxDOs)
        
        // 三、寫入緩存
        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 洞察是有時間限制的。

本篇文章到此結束，感謝閱讀！