# 一、背景

某一日收到上游呼叫方的反饋，提供的某一個Dubbo介面，每天在固定的時間點被短時間熔斷，丟擲的異常資訊為提供方dubbo執行緒池被耗盡。當前dubbo介面日請求量18億次，報錯請求94W/天，至此開始了最佳化之旅。

# 二、快速應急

## 2.1 快速定位

首先進行常規的系統資訊監控（機器、JVM記憶體、GC、執行緒），發現雖稍有突刺，但都在合理範圍內，且跟報錯時間點對不上，先暫時忽略。

其次進行流量分析，發現每天固定時間點會有流量突增的情況，流量突增的點跟報錯的時間點也吻合，初步判斷為短時大流量導致。

流量趨勢

![](https://static001.geekbang.org/infoq/ac/ace49acc5bc2b254ee731364a358ba75.png)

**被降級量**

![](https://static001.geekbang.org/infoq/3c/3cc063ebb1b1d762dfaf586260161959.png)

**介面99線**

![](https://static001.geekbang.org/infoq/54/547d97366352697cc45228e7ac06df72.png)

# 三、尋找效能瓶頸點

## 3.1 介面流程分析

### 3.1.1 流程圖

![](https://static001.geekbang.org/infoq/e5/e5e5709e6adcc1bcd25a3a2290d99653.png)

### 3.1.2 流程分析

> 收到請求後呼叫下游介面，使用hystrix熔斷器，熔斷時間為500MS；

> 根據下游介面返回的資料，進行詳情資料的封裝，第一步先到本地快取中獲取，如果本地快取沒有，則從Redis進行回源，Redis中無則直接返回，非同步執行緒從資料庫進行回源。

> 如果第一步呼叫下游介面異常，則進行資料兜底，兜底流程為先到本地快取中獲取，如果本地快取沒有，則從Redis進行回源，Redis中無則直接返回，非同步執行緒從資料庫進行回源。

## 3.2 效能瓶頸點排查

### 3.2.1 下游介面服務耗時比較長

呼叫鏈顯示，雖然下游介面的P99線在峰值流量時存在突刺，超出1S，但因為熔斷超時的設定（熔斷時間500MS，coreSize&masSize=50，下游介面平均耗時10MS以下），判斷下游介面不是問題的關鍵點，為進一步排除干擾，在下游服務存在突刺時能快速失敗，調整熔斷時間為100MS，dubbo超時時間100MS。

### 3.2.2 獲取詳情本地快取無資料，Redis回源

藉助呼叫鏈平臺，第一步分析Redis請求流量，以此來判斷本地快取的命中率，發現Redis的流量是介面流量的2倍，從設計上來說不應該出現這個現象。開始程式碼Review，發現在有一處邏輯出現了問題。

沒有從本地快取讀取，而是直接從Redis中獲取了資料，Redis最大響應時間也確實發現了不合理的突刺，繼續分析發現Redis響應時間和Dubbo99線突刺情況基本一致，感覺此時已經找到了問題的原因，心中暗喜。

**Redis請求流量**

![](https://static001.geekbang.org/infoq/0d/0d125fec49a6cbced8f8d36ffd34051d.png)

**服務介面請求流量**

![](https://static001.geekbang.org/infoq/fc/fcd9bf47452667d3fc34a9eb977d8b09.png)

**Dubbo99線**

![](https://static001.geekbang.org/infoq/ff/ffdfc17960caedcf2e1f7a40683c5ef9.png)

**Redis最大響應時間**

![](https://static001.geekbang.org/infoq/7a/7a9f3fe6b6a958699c613bc44f88a05b.png)

### 3.2.3 獲取兜底資料本地快取無資料，Redis回源

正常

### 3.2.4 記錄請求結果入Redis

因為當前Redis做了資源隔離，且未在DB後臺查詢到慢日誌，此時分析導致Redis變慢的原因有很多，不過其他的都被主觀忽略了，注意力都在請求Redis流量翻倍的問題上了，故優先解決3.2.2中的問題。

# 四、解決方案

## 4.1 3.3.2中定位的問題上線

**上線前Redis請求量**

![](https://static001.geekbang.org/infoq/0d/0d125fec49a6cbced8f8d36ffd34051d.png)

**上線後Redis請求量**

![](https://static001.geekbang.org/infoq/2f/2f0fc2d08c9af47015ad094c5b0343e5.png)

上線後Redis流量翻倍問題得到解決，Redis最大響應時間突刺有所緩解，但依舊沒能徹底解決，說明大流量查詢不是最根本的原因。

**redis最大響應時間（上線前）**

![](https://static001.geekbang.org/infoq/66/6667b0ca10a3d33453a731b4859676f9.png)

**redis最大響應時間（上線後）**

![](https://static001.geekbang.org/infoq/9a/9a6116968b85f1a456e107af0253fd26.png)

## 4.2 Redis擴容

在Redis異常流量問題解決後，問題並未得到徹底解決，此時能做的就是靜下心來，仔細去梳理導致Redis慢的原因，思路主要從以下三個方面:

-   出現了慢查詢
    
-   Redis服務出現效能瓶頸
    
-   客戶端配置不合理

基於以上思路，一個個的進行排查；查詢Redis慢查詢日誌，未發現慢查詢。

借用呼叫鏈平臺詳細分析慢的Redis命令，沒有了大流量導致的慢查詢的干擾，問題定位流程很快，大量的耗時請求在setex方法上，偶爾出現查詢的慢請求也都是在setex方法之後，根據Redis單執行緒的特性判斷setex是Redis99線突刺的元兇。找到具體語句，定位到具體業務後，首先申請擴容Redis，由6個master擴到8個master。

![](https://static001.geekbang.org/infoq/a8/a8ae8caf453f091ec260bd048ab25b9e.png)

![](https://static001.geekbang.org/infoq/b4/b4cf1d4a23b53b06f4443f41ee1f9db7.png)

**Redis擴容前**

![](https://static001.geekbang.org/infoq/38/382e030c7a1779af34503278305e2eb6.png)

**Redis擴容後**

![](https://static001.geekbang.org/infoq/d5/d5d81475112685699cc27fa20e4ccaaf.png)

從結果上看，擴容基本上沒有效果，說明redis服務本身不是效能瓶頸點，此時剩下的一個就是客戶端相關配置了。

## 4.3 客戶端引數最佳化

### 4.3.1 連線池最佳化

Redis擴容沒有效果，針對客戶端可能出現的問題，此時懷疑的點有兩個方向。

第一個是客戶端在處理Redis叢集模式時，對連線的管理上存在BUG，第二個是連線池引數設定不合理，此時原始碼分析和連線池引數調整同步進行。

#### 4.3.1.1 判斷客戶端連線管理上是否有BUG

在分析完，客戶端處理連線池的原始碼後，沒有問題，跟預想一致，按照槽位快取連線池，第一個假設被排除，原始碼如下。

```java
1、setEx
  public String setex(final byte[] key, final int seconds, final byte[] value) {
    return new JedisClusterCommand<string>(connectionHandler, maxAttempts) {
      @Override
      public String execute(Jedis connection) {
        return connection.setex(key, seconds, value);
      }
    }.runBinary(key);
  }
 
2、runBinary
  public T runBinary(byte[] key) {
    if (key == null) {
      throw new JedisClusterException("No way to dispatch this command to Redis Cluster.");
    }
 
    return runWithRetries(key, this.maxAttempts, false, false);
  }
3、runWithRetries
  private T runWithRetries(byte[] key, int attempts, boolean tryRandomNode, boolean asking) {
    if (attempts <= 0) {
      throw new JedisClusterMaxRedirectionsException("Too many Cluster redirections?");
    }
 
    Jedis connection = null;
    try {
 
      if (asking) {
        // TODO: Pipeline asking with the original command to make it
        // faster....
        connection = askConnection.get();
        connection.asking();
 
        // if asking success, reset asking flag
        asking = false;
      } else {
        if (tryRandomNode) {
          connection = connectionHandler.getConnection();
        } else {
          connection = connectionHandler.getConnectionFromSlot(JedisClusterCRC16.getSlot(key));
        }
      }
 
      return execute(connection);
 
    }
 
4、getConnectionFromSlot
  public Jedis getConnectionFromSlot(int slot) {
    JedisPool connectionPool = cache.getSlotPool(slot);
    if (connectionPool != null) {
      // It can't guaranteed to get valid connection because of node
      // assignment
      return connectionPool.getResource();
    } else {
      renewSlotCache(); //It's abnormal situation for cluster mode, that we have just nothing for slot, try to rediscover state
      connectionPool = cache.getSlotPool(slot);
      if (connectionPool != null) {
        return connectionPool.getResource();
      } else {
        //no choice, fallback to new connection to random node
        return getConnection();
      }
    }
  }

```

**4.3.1.2 分析連線池引數**

透過跟中介軟體團隊溝通，以及參考commons-pool2官方文件修改如下；

![](https://static001.geekbang.org/infoq/6c/6c3f477e3ac68b49eab7f189613c8287.png)

引數調整後，1S以上的請求量得到減少，但還是存在，上游反饋降級量由每天90萬左右降到每天6W個（關於maxWaitMillis設定為200MS後為什麼還會有超過200MS的請求，下文有解釋）。

引數最佳化後Reds最大響應時間

![](https://static001.geekbang.org/infoq/c8/c86644c5436a2c5d01ebd9bf47d6e1ce.png)

引數最佳化後介面報錯量

![](https://static001.geekbang.org/infoq/50/50c2fca0770e9bfe0175342f82af12a3.png)

### 4.3.2 持續最佳化

最佳化不能停止，如何把Redis的所有寫入請求降低到200MS以內，此時的最佳化思路還是調整客戶端配置引數，分析Jedis獲取連線相關原始碼；

**Jedis獲取連線原始碼**

```java
final AbandonedConfig ac = this.abandonedConfig;
if (ac != null && ac.getRemoveAbandonedOnBorrow() &&
        (getNumIdle() < 2) &&
        (getNumActive() > getMaxTotal() - 3) ) {
    removeAbandoned(ac);
}

PooledObject<t> p = null;

// Get local copy of current config so it is consistent for entire
// method execution
final boolean blockWhenExhausted = getBlockWhenExhausted();

boolean create;
final long waitTime = System.currentTimeMillis();

while (p == null) {
    create = false;
    p = idleObjects.pollFirst();
    if (p == null) {
        p = create();
        if (p != null) {
            create = true;
        }
    }
    if (blockWhenExhausted) {
        if (p == null) {
            if (borrowMaxWaitMillis < 0) {
                p = idleObjects.takeFirst();
            } else {
                p = idleObjects.pollFirst(borrowMaxWaitMillis,
                        TimeUnit.MILLISECONDS);
            }
        }
        if (p == null) {
            throw new NoSuchElementException(
                    "Timeout waiting for idle object");
        }
    } else {
        if (p == null) {
            throw new NoSuchElementException("Pool exhausted");
        }
    }
    if (!p.allocate()) {
        p = null;
    }

if (p != null) {
        try {
            factory.activateObject(p);
        } catch (final Exception e) {
            try {
                destroy(p);
            } catch (final Exception e1) {
                // Ignore - activation failure is more important
            }
            p = null;
            if (create) {
                final NoSuchElementException nsee = new NoSuchElementException(
                        "Unable to activate object");
                nsee.initCause(e);
                throw nsee;
            }
        }
        if (p != null && (getTestOnBorrow() || create && getTestOnCreate())) {
            boolean validate = false;
            Throwable validationThrowable = null;
            try {
                validate = factory.validateObject(p);
            } catch (final Throwable t) {
                PoolUtils.checkRethrow(t);
                validationThrowable = t;
            }
            if (!validate) {
                try {
                    destroy(p);
                    destroyedByBorrowValidationCount.incrementAndGet();
                } catch (final Exception e) {
                    // Ignore - validation failure is more important
                }
                p = null;
                if (create) {
                    final NoSuchElementException nsee = new NoSuchElementException(
                            "Unable to validate object");
                    nsee.initCause(validationThrowable);
                    throw nsee;
                }
            }
        }
    }
}

updateStatsBorrow(p, System.currentTimeMillis() - waitTime);

return p.getObject();

```

獲取連線的大致流程如下:

> 是否有空閒連線，有空閒連線就直接返回，沒有就建立；

> 建立時如果超出最大連線數，則判斷是否有其他執行緒在建立連線，如果沒則直接返回，如果有則等待maxWaitMis時間（其他執行緒可能建立失敗），如果未超出最大連線，則執行建立連線操作（此時獲取連線等待時間可能會大於maxWaitMs）。

> 如果建立不成功，則判斷是否是阻塞獲取連線，如果不是則直接丟擲異常，連線池不夠用，如果是則判斷maxWaitMillis是否小於0，如果小於0則阻塞等待，如果大於0則阻塞等待maxWaitMillis。

> 後續就是根據引數來判斷是否需要做連線check等。

根據以上流程分析，maxWaitMills目前設定的為200，以上流程加起來最大阻塞時間為400MS，大部分情況為200MS，不應該出現超出400MS的突刺。

此時問題可能出現在建立連線上，因為建立連線比較耗時，且建立時間不定，重點分析是否有這個場景，透過DB後臺監控Redis連線情況。

**DB後臺監控Redis服務連線**

![](https://static001.geekbang.org/infoq/5a/5a7758cfdc0bc6acfd957975957eb91c.png)

分析上圖發現，確實在幾個時間點（9:00,12:00，19:00...），redis連線數存在上漲情況，跟Redis突刺時間基本吻合。感覺（之前的各種嘗試後，已經不敢用確定了）問題到此定位清晰（在突增流量過來時，連線池可用連線滿足不了需求，會建立連線，造成請求等待）。

此時的想法是在服務啟動時就進行連線池的建立，儘量減少新連線的建立，修改連線池引數vivo.cache.depend.common.poolConfig.minIdle，結果竟然無效？？？

啥都不說了，開始擼原始碼，jedis底層使用的是commons-poll2來管理連線的，檢視專案中使用的commons-pool2-2.6.2.jar部分原始碼；

**CommonPool2原始碼**

```java
public GenericObjectPool(final PooledObjectFactory<t> factory,
        final GenericObjectPoolConfig<t> config) {
 
    super(config, ONAME_BASE, config.getJmxNamePrefix());
 
    if (factory == null) {
        jmxUnregister(); // tidy up
        throw new IllegalArgumentException("factory may not be null");
    }
    this.factory = factory;
 
    idleObjects = new LinkedBlockingDeque<>(config.getFairness());
 
    setConfig(config);
}

```

竟然發現沒有初始化連線的地方，開始諮詢中介軟體團隊，中介軟體團隊給出的原始碼（commons-pool2-2.4.2.jar）如下，方法執行後多了一次startEvictor方法的呼叫？

```java
1、初始化連線池
public GenericObjectPool(PooledObjectFactory<t> factory,
            GenericObjectPoolConfig config) {
super(config, ONAME_BASE, config.getJmxNamePrefix());
if (factory == null) {
            jmxUnregister(); // tidy up
throw new IllegalArgumentException("factory may not be null");
        }
this.factory = factory;
        idleObjects = new LinkedBlockingDeque<pooledobject>>(config.getFairness());
        setConfig(config);
        startEvictor(getTimeBetweenEvictionRunsMillis());
    }

```

為啥不一樣？？？開始檢查Jar包，版本不一樣，中介軟體給出的版本是在V2.4.2，專案實際使用的是V2.6.2，分析startEvictor有一步邏輯正是處理連線池預熱邏輯。

**Jedis連線池預熱**

```java
1、final void startEvictor(long delay) {
        synchronized (evictionLock) {
            if (null != evictor) {
                EvictionTimer.cancel(evictor);
                evictor = null;
                evictionIterator = null;
            }
            if (delay > 0) {
                evictor = new Evictor();
                EvictionTimer.schedule(evictor, delay, delay);
            }
        }
    }
2、class Evictor extends TimerTask {
       /**
         * Run pool maintenance.  Evict objects qualifying for eviction and then
         * ensure that the minimum number of idle instances are available.
         * Since the Timer that invokes Evictors is shared for all Pools but
         * pools may exist in different class loaders, the Evictor ensures that
         * any actions taken are under the class loader of the factory
         * associated with the pool.
         */
        @Override
        public void run() {
            ClassLoader savedClassLoader =
                    Thread.currentThread().getContextClassLoader();
            try {
                if (factoryClassLoader != null) {
                    // Set the class loader for the factory
                    ClassLoader cl = factoryClassLoader.get();
                    if (cl == null) {
                        // The pool has been dereferenced and the class loader
                        // GC'd. Cancel this timer so the pool can be GC'd as
                        // well.
                        cancel();
                        return;
                    }
                    Thread.currentThread().setContextClassLoader(cl);
                }
 
                // Evict from the pool
                try {
                    evict();
                } catch(Exception e) {
                    swallowException(e);
                } catch(OutOfMemoryError oome) {
                    // Log problem but give evictor thread a chance to continue
                    // in case error is recoverable
                    oome.printStackTrace(System.err);
                }
                // Re-create idle instances.
                try {
                    ensureMinIdle();
                } catch (Exception e) {
                    swallowException(e);
                }
            } finally {
                // Restore the previous CCL
                Thread.currentThread().setContextClassLoader(savedClassLoader);
            }
        }
    }
3、 void ensureMinIdle() throws Exception {
        ensureIdle(getMinIdle(), true);
    }
4、 private void ensureIdle(int idleCount, boolean always) throws Exception {
        if (idleCount < 1 || isClosed() || (!always && !idleObjects.hasTakeWaiters())) {
            return;
        }
 
        while (idleObjects.size() < idleCount) {
            PooledObject<t> p = create();
            if (p == null) {
                // Can't create objects, no reason to think another call to
                // create will work. Give up.
                break;
            }
            if (getLifo()) {
                idleObjects.addFirst(p);
            } else {
                idleObjects.addLast(p);
            }
        }
        if (isClosed()) {
            // Pool closed while object was being added to idle objects.
            // Make sure the returned object is destroyed rather than left
            // in the idle object pool (which would effectively be a leak)
            clear();
        }
    }

```

修改Jar版本，配置中心增加vivo.cache.depend.common.poolConfig.timeBetweenEvictionRunsMillis（檢查一次連線池中空閒的連線，把空閒時間超過minEvictableIdleTimeMillis毫秒的連線斷開,直到連線池中的連線數到minIdle為止）。

vivo.cache.depend.common.poolConfig.minEvictableIdleTimeMillis（連線池中連線可空閒的時間,毫秒）兩個引數，重啟服務後，連線池正常預熱，最終從Redis層面上解決問題。

最佳化結果如下，效能問題基本得到解決；

**Redis響應時間（最佳化前）**

![](https://static001.geekbang.org/infoq/c8/c86644c5436a2c5d01ebd9bf47d6e1ce.png)

**Redis響應時間（最佳化後）**

![](https://static001.geekbang.org/infoq/6d/6d48f2593b278d12f1666ffb9179e920.png)

**介面99線（最佳化前）**

![](https://static001.geekbang.org/infoq/ff/ffdfc17960caedcf2e1f7a40683c5ef9.png)

**介面99線（最佳化後）**

![](https://static001.geekbang.org/infoq/f5/f5064391a33cddc219f94fea7191f6c5.png)

# 五、總結

出現線上問題時，首先要考慮的還是快速恢復線上業務，將業務的影響度降到最低，所以針對線上的業務，要提前做好限流、熔斷、降級等策略，線上上出現問題時能快速找到恢復方案。對公司各監控平臺的熟練使用程度，決定了定位問題的速度，每個開發都要把熟練使用監控平臺（機器、服務、介面、DB等）作為一個基本能力。

Redis出現響應慢時，可以優先從Redis叢集服務端（機器負載、服務是否有慢查詢）、業務程式碼（是否有BUG）、客戶端（連線池配置是否合理）三個方面去排查，基本上能排查出大部分Redis慢響應問題。

Redis連線池在系統冷啟動時，對連線池的預熱，不同commons-pool2的版本，冷啟動的策略也不同，但都需要配置minEvictableIdleTimeMillis引數才會生效，可以看下common-pool2官方文件，對常用引數都做到心中有數，在問題出現時能快速定位。

連線池預設引數在解決大流量的業務上稍顯乏力，需要針對大流量場景進行調優處理，如果業務上流量不是很大直接使用預設引數即可。

具體問題要具體分析，不能解決問題的時候要變通思路，透過各種方法去嘗試解決問題。

> 作者：vivo網際網路伺服器團隊-Wang Shaodong</t></pooledobject></t></t></t></t></string>

十億級流量下，我與Redis時延小突刺的戰鬥史

相關文章