作者：vivo 網際網路伺服器團隊- Li Gang

本文介紹了一次排查Dubbo執行緒池耗盡問題的過程。通過檢視Dubbo執行緒狀態、分析Jedis連線池獲取連線的原始碼、排查死鎖條件等方面，最終確認是因為使用了cluster pipeline模式且沒有設定超時時間導致死鎖問題。

一、背景介紹

Redis Pipeline是一種高效的命令批次處理機制，可以在Redis中大幅度降低網路延遲，提高讀寫能力。Redis Cluster Pipeline是基於Redis Cluster的pipeline，通過將多個操作打包成一組操作，一次性傳送到Redis Cluster中的多個節點，減少了通訊延遲，提高了整個系統的讀寫吞吐量和效能，適用於需要高效處理Redis Cluster命令的場景。

本次使用到pipeline的場景是批次從Redis Cluster批次查詢預約遊戲資訊，專案內使用的Redis Cluster Pipeline的流程如下，其中的JedisClusterPipeline是我們內部使用的工具類，提供Redis Cluster模式下的pipeline能力：

JedisClusterPipeline使用：

JedisClusterPipline jedisClusterPipline = redisService.clusterPipelined();
List<Object> response;
try {
    for (String key : keys) {
        jedisClusterPipline.hmget(key, VALUE1, VALUE2);
    }
    // 獲取結果
    response = jedisClusterPipline.syncAndReturnAll();
} finally {
    jedisClusterPipline.close();
}

二、故障現場記錄

某天，收到了Dubbo執行緒池耗盡的告警。檢視紀錄檔發現只有一臺機器有問題，並且一直沒恢復，已完成任務數也一直沒有增加。

檢視請求數監控，發現請求數歸零，很明顯機器已經掛了。

使用arthas檢視Dubbo執行緒，發現400個執行緒全部處於waiting狀態。

三、故障過程分析

Dubbo執行緒處於waiting狀態這一點沒有問題，Dubbo執行緒等待任務的時候也是waiting狀態，但是檢視完整呼叫棧發現有問題，下面兩張圖裡的第一張是問題機器的棧，第二張是正常機器的棧，顯然問題機器的這個執行緒在等待Redis連線池裡有可用連線。

使用jstack匯出執行緒快照後發現問題機器所有的Dubbo執行緒都在等待Redis連線池裡有可用連線。

調查到這裡，能發現兩個問題。

執行緒一直等待連線而沒有被中斷。
執行緒獲取不到連線。

3.1 執行緒一直等待連線而沒有被中斷原因分析

Jedis獲取連線的邏輯在org.apache.commons.pool2.impl.GenericObjectPool#borrowObject(long)方法下。

public T borrowObject(long borrowMaxWaitMillis) throws Exception {
    ...
    PooledObject<T> p = null;
 
    // 獲取blockWhenExhausted設定項，該設定預設值為true
    boolean blockWhenExhausted = getBlockWhenExhausted();
 
    boolean create;
    long waitTime = System.currentTimeMillis();
 
    while (p == null) {
        create = false;
        if (blockWhenExhausted) {
            // 從佇列獲取空閒的物件，該方法不會阻塞，沒有空閒物件會返回null
            p = idleObjects.pollFirst();
            // 沒有空閒物件則建立
            if (p == null) {
                p = create();
                if (p != null) {
                    create = true;
                }
            }
            if (p == null) {
                // borrowMaxWaitMillis預設值為-1
                if (borrowMaxWaitMillis < 0) {
                    // 執行緒棧快照裡所有的dubbo執行緒都卡在這裡，這是個阻塞方法，如果佇列裡沒有新的連線會一直等待下去
                    p = idleObjects.takeFirst();    
                } else {
                    // 等待borrowMaxWaitMillis設定的時間還沒有拿到連線的話就返回null
                    p = idleObjects.pollFirst(borrowMaxWaitMillis,
                            TimeUnit.MILLISECONDS);
                }
            }
            if (p == null) {
                throw new NoSuchElementException(
                        "Timeout waiting for idle object");
            }
            if (!p.allocate()) {
                p = null;
            }
        
        }
 
        ...
 
    }
 
    updateStatsBorrow(p, System.currentTimeMillis() - waitTime);
 
    return p.getObject();
}

由於業務程式碼沒有設定borrowMaxWaitMillis，導致執行緒一直在等待可用連線，該值可以通過設定jedis pool的maxWaitMillis屬性來設定。

到這裡已經找到執行緒一直等待的原因，但執行緒獲取不到連線的原因還需要繼續分析。

3.2 執行緒獲取不到連線原因分析

獲取不到連線無非兩種情況：

連不上Redis，無法建立連線
連線池裡的所有連線都被佔用了，無法獲取到連線

猜想一：是不是連不上Redis?

詢問運維得知發生問題的時間點確實有一波網路抖動，但是很快就恢復了，排查時問題機器是能正常連上Redis的。那有沒有可能是建立Redis連線的流程寫的有問題，無法從網路抖動中恢復導致執行緒卡死？這一點要從原始碼中尋找答案。

建立連線：

private PooledObject<T> create() throws Exception {
    int localMaxTotal = getMaxTotal();
    long newCreateCount = createCount.incrementAndGet();
    if (localMaxTotal > -1 && newCreateCount > localMaxTotal ||
            newCreateCount > Integer.MAX_VALUE) {
        createCount.decrementAndGet();
        return null;
    }
 
    final PooledObject<T> p;
    try {
        // 建立redis連線，如果發生超時會丟擲異常
        // 預設的connectionTimeout和soTimeout都是2秒
        p = factory.makeObject();
    } catch (Exception e) {
        createCount.decrementAndGet();
        // 這裡會把異常繼續往上丟擲
        throw e;
    }
 
    AbandonedConfig ac = this.abandonedConfig;
    if (ac != null && ac.getLogAbandoned()) {
        p.setLogAbandoned(true);
    }
 
    createdCount.incrementAndGet();
    allObjects.put(new IdentityWrapper<T>(p.getObject()), p);
    return p;
}

可以看到，連線Redis超時時會丟擲異常，呼叫create()函數的borrowObject()也不會捕獲這個異常，這個異常最終會在業務層被捕獲，所以連不上Redis的話是不會一直等待下去的，網路恢復後再次呼叫create()方法就能重新建立連線。

綜上所訴，第一種情況可以排除，繼續分析情況2，連線被佔用了沒問題，但是一直不釋放就有問題。

猜想二：是不是業務程式碼沒有歸還Redis連線?

連線沒有釋放，最先想到的是業務程式碼裡可能有地方漏寫了歸還Redis連線的程式碼，pipeline模式下需要在finally塊中手動呼叫JedisClusterPipeline#close()方法將連線歸還給連線池，而普通模式下不需要手動釋放（參考redis.clients.jedis.JedisClusterCommand#runWithRetries，每次執行完命令後都會自動釋放），在業務程式碼裡全域性搜尋所有使用到了cluster pipeline的程式碼，均手動呼叫了JedisClusterPipeline#close()方法，所以不是業務程式碼的問題。

猜想三：是不是Jedis存在連線洩露的問題?

既然業務程式碼沒問題，那有沒有可能是歸還連線的程式碼有問題，存在連線洩露？2.10.0版本的Jedis確實可能發生連線洩露，具體可以看這個issue：https://github.com/redis/jedis/issues/1920，不過我們專案內使用的是2.9.0版本，所以排除連線洩露的情況。

猜想四：是不是發生了死鎖?

排除以上可能性後，能想到原因的只剩死鎖，思考後發現在沒有設定超時時間的情況下，使用pipeline確實有概率發生死鎖，這個死鎖發生在從連線池(LinkedBlockingDeque)獲取連線的時候。

先看下cluster pipeline模式下的Redis和普通的Redis有什麼區別。Jedis為每個Redis範例都維護了一個連線池，cluster pipeline模式下，先使用查詢用的key計算出其所在的Redis範例列表，再從這些範例對應的連線池裡獲取到連線，使用完後統一釋放。而普通模式下一次只會獲取一個連線池的連線，用完後立刻釋放。這意味著cluster pipeline模式在獲取連線時是符合死鎖的「佔有並等待」條件的，而普通模式不符合這個條件。

JedisClusterPipeline使用：

JedisClusterPipline jedisClusterPipline = redisService.clusterPipelined();
List<Object> response;
try {
    for (String key : keys) {
        // 申請連線，內部會先呼叫JedisClusterPipeline.getClient(String key)方法獲取連線
        jedisClusterPipline.hmget(key, VALUE1, VALUE2);
        // 獲取到了連線，快取到poolToJedisMap
    }
    // 獲取結果
    response = jedisClusterPipline.syncAndReturnAll();
} finally {
    // 歸還所有連線
    jedisClusterPipline.close();
}

JedisClusterPipeline部分原始碼：

public class JedisClusterPipline extends PipelineBase implements Closeable {
 
    private static final Logger log = LoggerFactory.getLogger(JedisClusterPipline.class);
 
    // 用於記錄redis命令的執行順序
    private final Queue<Client> orderedClients = new LinkedList<>();
    // redis連線快取
    private final Map<JedisPool, Jedis> poolToJedisMap = new HashMap<>();
 
    private final JedisSlotBasedConnectionHandler connectionHandler;
    private final JedisClusterInfoCache clusterInfoCache;
 
    public JedisClusterPipline(JedisSlotBasedConnectionHandler connectionHandler, JedisClusterInfoCache clusterInfoCache) {
        this.connectionHandler = connectionHandler;
        this.clusterInfoCache = clusterInfoCache;
    }
 
    @Override
    protected Client getClient(String key) {
 
        return getClient(SafeEncoder.encode(key));
    }
 
    @Override
    protected Client getClient(byte[] key) {
 
        Client client;
        // 計算key所在的slot
        int slot = JedisClusterCRC16.getSlot(key);
        // 獲取solt對應的連線池
        JedisPool pool = clusterInfoCache.getSlotPool(slot);
        // 從快取獲取連線
        Jedis borrowedJedis = poolToJedisMap.get(pool);
        // 快取中沒有連線則從連線池獲取並快取
        if (null == borrowedJedis) {
            borrowedJedis = pool.getResource();
            poolToJedisMap.put(pool, borrowedJedis);
        }
         
        client = borrowedJedis.getClient();
     
        orderedClients.add(client);
 
        return client;
    }
 
    @Override
    public void close() {
        for (Jedis jedis : poolToJedisMap.values()) {
            // 清除連線內的殘留資料,防止連線歸還時有資料漏讀的現象
            try {
                jedis.getClient().getAll();
            } catch (Throwable throwable) {
                log.warn("關閉jedis時遍歷異常，遍歷的目的是：清除連線內的殘留資料,防止連線歸還時有資料漏讀的現象");
            }
            try {
                jedis.close();
            } catch (Throwable throwable) {
                log.warn("關閉jedis異常");
            }
        }
        // 歸還連線
        clean();
        orderedClients.clear();
        poolToJedisMap.clear();
    }
 
    /**
     * go through all the responses and generate the right response type (warning :
     * usually it is a waste of time).
     *
     * @return A list of all the responses in the order
     */
    public List<Object> syncAndReturnAll() {
        List<Object> formatted = new ArrayList<>();
        List<Throwable> throwableList = new ArrayList<>();
        for (Client client : orderedClients) {
            try {
                Response response = generateResponse(client.getOne());
                if(response == null){
                    continue;
                }
                formatted.add(response.get());
            } catch (Throwable e) {
                throwableList.add(e);
            }
        }
        slotCacheRefreshed(throwableList);
        return formatted;
    }
}

舉個例子：

假設有一個叢集有兩臺Redis主節點（叢集模式下最小的主節點數量是3，這裡只是為了舉例），記為節點1/2，有個java程式有4個Dubbo執行緒，記為執行緒1/2/3/4，每個Redis範例都有一個大小為2的連線池。

執行緒1和執行緒2，先獲取Redis1的連線再獲取Redis2的連線。執行緒3和執行緒4，先獲取Redis2的連線再獲取Redis1的連線，假設這四個執行緒在獲取到連線第一個連線後都等待了一會，在獲取第二個連線的時候就會發生死鎖(等待時間越長，觸發的概率越大)。

所以pipeline是可能導致死鎖的，這個死鎖的條件很容易破壞，等待連線的時候設定超時時間即可。還可以增大下連線池的大小，資源夠的話也不會發生死鎖。

四、死鎖證明

以上只是猜想，為了證明確實發生了死鎖，需要以下條件：

執行緒當前獲取到了哪些連線池的連線
執行緒當前在等待哪些連線池的連線
每個連線池還剩多少連線

已知問題機器的Dubbo執行緒池大小為400，Redis叢集主節點數量為12，Jedis設定的連線池大小為20。

4.1 步驟一：獲取執行緒在等待哪個連線池有空閒連線

第一步：先通過jstack和jmap分別匯出棧和堆

第二步：通過分析棧可以知道執行緒在等待的鎖的地址，可以看到Dubbo執行緒383在等待0x6a3305858這個鎖物件，這個鎖屬於某個連線池，需要找到具體是哪個連線池。

第三步：使用mat(Eclipse Memory Analyzer Tool)工具分析堆，通過鎖的地址找到對應的連線池。

使用mat的with incoming references功能順著參照一層層的往上找。

參照關係：ConditionObject->LinkedBlockingDeque

參照關係：LinkedBlockingDeque->GenericObjectPool

參照關係：GenericObjectPool->JedisPool。這裡的ox6a578ddc8就是這個鎖所屬的連線池地址。

這樣我們就能知道Dubbo執行緒383當前在等待0x6a578ddc8這個連線池的連線。

通過這一套流程，我們可以知道每個Dubbo執行緒分別在等待哪些連線池有可用連線。

4.2 步驟二：獲取執行緒當前持有了哪些連線池的連線

第一步：使用mat在堆中查詢所有JedisClusterPipeline類(正好400個，每個Dubbo執行緒都各有一個)，然後檢視裡面的poolToJedisMap，其中儲存了當前JedisClusterPipeline已經持有的連線和其所屬的連線池。

下圖中，我們可以看到JedisClusterPipeline(0x6ac40c088)物件當前的poolToJedisMap裡有三個Node物件(0x6ac40dd40, 0x6ac40dd60, 0x6ac40dd80)，代表其持有三個連線池的連線，可以從Node物件中找到JedisPool的地址。

第二步：第一步拿到JedisClusterPipeline持有哪個連線池的連線後，再查詢持有此JedisClusterPipeline的Dubbo執行緒，這樣就能得到Dubbo執行緒當前持有哪些連線池的連線。

4.3 死鎖分析

通過流程一可以發現雖然Redis主節點有12個，但是所有的Dubbo執行緒都只在等待以下5個節點對應的連線池之一：

0x6a578e0c8
0x6a578e048
0x6a578ddc8
0x6a578e538
0x6a578e838

通過流程二我們可以得知這5個連線池的連線當前被哪些執行緒佔用：

已知每個連線池的大小都設定為了20，這5個連線池的所有連線已經被100個Dubbo執行緒佔用完了，而所有的400個Dubbo執行緒又都在等待這5個連線池的連線，並且其等待的連線當前沒被自己佔用，通過這些條件，我們可以確定發生了死鎖。

五、總結

這篇文章主要展現了一次系統故障的分析過程。在排查過程中，作者使用jmap和jstack儲存故障現場，使用arthas分析故障現場，再通過閱讀和分析原始碼，從多個可能的角度一步步的推演故障原因，推測是死鎖引起的故障。在驗證死鎖問題時，作者使用mat按照一定的步驟來尋找執行緒在等待哪個連線池的連線和持有哪些連線池的連線，再結合死鎖檢測演演算法最終確認故障機器發生了死鎖。

排查線上問題並非易事，不僅要對業務程式碼有足夠的瞭解，還要對相關技術知識有系統性的瞭解，推測出可能導致問題的原因後，再熟練運用好排查工具，最終確認問題原因。

記一次Redis Cluster Pipeline導致的死鎖問題