j2Cache線上異常排查問題解決記錄分析

2022-02-25 19:01:26

問題背景

開發反饋，線上有個服務在執行一段時間後，就會拋異常導致redis快取不可用。專案使用了j2Caceh，異常是j2Cache的RedisCacheProvider丟擲來的，如：

Exception in thread "main" redis.clients.jedis.exceptions.JedisException: Could not get a resource from the pool
	at redis.clients.util.Pool.getResource(Pool.java:51)
	at redis.clients.jedis.JedisPool.getResource(JedisPool.java:99)
	at net.oschina.j2cache.redis.RedisCacheProvider.getResource(RedisCacheProvider.java:51)
	at com.xczysoft.ltl.core.support.j2cache.J2CacheRedisCacheChannel.main(J2CacheRedisCacheChannel.java:66)
Caused by: java.util.NoSuchElementException: Timeout waiting for idle object
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:447)
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:361)
	at redis.clients.util.Pool.getResource(Pool.java:49)
	... 3 more

j2Cache:紅薯開源的2階段快取框架：https://gitee.com/ld/J2Cache

問題分析

從異常紀錄檔表象上看，很明顯是由於jedis pool中沒有資源了。當jedis pool沒有資源，而使用者端去申請連線時，框架預留了一個由使用者控制的策略來處理，具體策略如下：

連線池引數： blockWhenExhausted，有如下兩種策略

true：阻塞等待maxWaitMillis時間(預設），這個是預設的策略，當pool沒有可用資源時，阻塞等待maxWaitMillis時間，這個值預設時間無限長的，連線池應該設定一個適當的等待時間
false：當無可用連線時，立即失敗。

我們的服務並沒有設定whenExhaustedAction 的引數，maxWait設定的是1500。也就是說當jedis pool沒有可用資源時，獲取連線的執行緒等待了1.5秒，1.5秒後還沒有可用資源就拋異常了。

回到上面的問題，導致jedis pool原因有哪些呢？無外乎兩點，如下：

1、正常情況：程式並行高，導致偶發性的連線池無可用資源
2、異常情況：連線池使用不當，當從連線池獲取資源後，使用完時沒有正常的釋放資源，導致連線池取一個少一個，最後必然性的會丟擲開頭的異常

假設問題

結合上面對jedis pool的分析，而我們的服務並行度不高，預設連線池最大連線有8個，而且獲取連線的執行緒在等待1.5秒後還是沒有獲取到執行緒，最重要的一點是，當程式跑到最後，獲取不到連線的異常不在是偶發性的，

變成了必然性的事件了，那麼根據上面這些分析，先假設問題就是由於程式中連線池使用不當導致的問題。程式使用jedis的地方是j2Cache，紅薯開源的一個2階快取框架，很可能是紅薯的鍋。

小心求證

通過對問題的假設，我們需要在程式中找到從jedis pool中獲取資源的程式碼，那首先需要找到初始化連線池的地方，j2Cache裡是通過RedisCacheProvider來維護jedis pool的。下面是j2Cache裡通過jedis pool的連線操作redis的程式碼，可以看到，非常規範，通過try，catch，finally將資源操作包起來了，並且在finally中釋放了資源，保證資源一定會被釋放

紅薯表示這個鍋我不背，肯定不是j2Cache的毛病了。可以看到RedisCacheProvider初始化連線池後，提供了一個靜態方法getResource()用於獲取連線，很可能是業務層面通過這個入口，拿到RedisCacheProvider裡的連線了。後面繼續找，定位到了一個非常有嫌疑的方法，程式碼如下：

/**
     * 傳送清除快取的廣播命令
     *
     * @param region: Cache region name
     */
    private void _sendClearCmd(String region) {
        // 傳送廣播
        Command cmd = new Command(Command.OPT_CLEAR_KEY, region, "");
        try (Jedis jedis = RedisCacheProvider.getResource()) {
            jedis.publish(SafeEncoder.encode(config.getProperty("redis.channel_name")), cmd.toBuffers());
        } catch (Exception e) {
            log.error("Unable to clear cache,region=" + region, e);
        }
    }

可以看到，這是一段和j2Cache相關的程式碼，但是不是紅薯的框架內的，是我們開發在接入j2Cache時設定的一個快取通道內的一段程式碼。問題就出在通過

RedisCacheProvider.getResource()拿到jedis物件後，使用完，並沒有釋放。

問題重現

上面基本定位到問題了，下面我們模擬下發生的問題的場景，程式碼邏輯和上面的類似，我們初始化一個連線池後，在一個for迴圈中，模擬多次獲取連線但是不釋放，如：

public static void main(String[] args) throws Exception {
        Properties properties = ResourceUtil.getResourceAsProperties("app.properties", true);
        new J2CacheRedisCacheChannel("j2Cache 666", properties);
        for (int i = 1; i &lt;= 8; i++) {
            Jedis jedis = RedisCacheProvider.getResource();
            try {
                jedis.get("kl");
            } catch (Exception e) {
                log.error("Unable to clear cache,region=" + null, e);
            }
            System.out.println("第" + i + "次執行");
        }
    }

上面程式碼的執行效果如：

而且是必然出現的，在第八次的時候，因為沒有可用的連線，導致程式在等待1.5秒後丟擲了異常

問題解決

綜上，我們可以肯定是由於這裡的程式碼使用不規範，導致的連線池連線洩漏了。程式碼修改也非常簡單，在finally中判斷下jeids物件是否為null，不為null則呼叫其close方法，將資源回收即可。

上文所述場景中有個地方埋了一個小彩蛋，感興趣的小夥伴可以找下，在下方留言交流。

問題後記-下面才是真正的原因

你以為就上面的就這麼完了，還沒呢，待續ing

其實上面獲取jedis資源的程式碼是沒有問題，剛開始忽略了一個細節，try (Jedis jedis = RedisCacheProvider.getResource()) 。獲取資源的動作是放在try（）裡的，java1.7引入了try-with-resources

語意，我們使用的jedis版本已經實現了JDK的AutoCloseable介面。所以，上面這段程式碼在編譯器編譯後會變成如下的樣子：

private void _sendEvictCmd(String region, Object key) {
    Command cmd = new Command((byte)1, region, key);
    try {
        Jedis jedis = RedisCacheProvider.getResource();
        Throwable var5 = null;
 
        try {
            jedis.publish(SafeEncoder.encode(this.config.getProperty("redis.channel_name")), cmd.toBuffers());
        } catch (Throwable var15) {
            var5 = var15;
            throw var15;
        } finally {
            if (jedis != null) {
                if (var5 != null) {
                    try {
                        jedis.close();
                    } catch (Throwable var14) {
                        var5.addSuppressed(var14);
                    }
                } else {
                    jedis.close();
                }
            }
 
        }
    } catch (Exception var17) {
        log.error("Unable to delete cache,region=" + region + ",key=" + key, var17);
    }
}

可以看到，編譯器自動幫我們織入了想要在finally程式碼塊內關閉連線的動作。

重新假設

如果不是連線洩漏導致的，那麼肯定是並行問題了，最終的異常是j2Cache丟擲來的，從j2Cache裡獲取連線的地方如下：

可以看到最上面紅框裡的是之前說的有問題，其實沒有問題，他們都被包在了try裡面了。中間的是紅薯框架內部用的，都手動釋放連線了。最後一個連線有點小問題，SeqServiceImpl是spring管理的一個範例，

因為是單例的範例，所以這裡只會長期佔用一個連線。除了這裡佔用了一個連線，上面三個在try裡的連線，其中一個是訂閱redis訊息的，程式碼如下：

thread_subscribe = new Thread(new Runnable() {
    @Override
    public void run() {
        try (Jedis jedis = RedisCacheProvider.getResource()) {
            jedis.subscribe(J2CacheRedisCacheChannel.this, SafeEncoder.encode(config.getProperty("redis.channel_name")));
        }
    }
});

注意這個jedis.subscribe()。其實是個阻塞操作。也就是說即使編輯器給這個地方加上了資源釋放的程式碼，在訂閱不出問題的情況下，也跑不到資源釋放的地方。所以這裡也會長期佔用一個連線。

那麼我們在程式裡可用的連線數=（最大連線數-兩個長期佔用連線）=（8-2）=6個

從異常資訊獲取點有用資訊，最終發現，丟擲連線不可用的程式碼有共性，都指向了一個類，但是是兩個方法，如：

最終跟蹤程式碼發現，這個兩個方法是給鑑權攔截器呼叫的，攔截器會攔截每個請求，程式碼語意類似下面，

@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response,
                         Object handler) throws Exception {
    RunResultrunResult = sysApiService.auth(null);
    sysApiService.update("", runResult.getData(), request);
    return super.preHandle(request, response, handler);
}

也就是每個請求都至少會對redis操作兩次，在沒有完成之前都不會釋放資源。

在看看拋異常的時間點的服務存取情況，在紀錄檔平臺將時間限定在2019-06-03 17:45~2019-06-03 17:46 ，搜尋結果如下：

從06-03 17:45:49 到 06-03 17:45:56 紀錄檔總條數299條。每秒請求數=（299/56-49）=42 。omygad的，連線池只有6個可用連線完全不夠用。這回真的石錘了。

最終解決

設定連線池的maxTotal引數即可，但是有個問題是，這個專案使用的j2Cache的版本比較老，程式碼的設定資訊限定死了就那麼個幾個，而且沒有預留maxTotal的設定。紅薯的初始化連線池的程式碼如下：

public void start(Properties props) throws CacheException {
      JedisPoolConfig config = new JedisPoolConfig();
      host = getProperty(props, "host", "127.0.0.1");
      password = props.getProperty("password", null);
      port = getProperty(props, "port", 6379);
      timeout = getProperty(props, "timeout", 2000);
      database = getProperty(props, "database", 0);
      config.setBlockWhenExhausted(getProperty(props, "blockWhenExhausted", true));
      config.setMaxIdle(getProperty(props, "maxIdle", 10));
      config.setMinIdle(getProperty(props, "minIdle", 5));
//    config.setMaxActive(getProperty(props, "maxActive", 50));
      config.setMaxWaitMillis(getProperty(props, "maxWait", 100));
      config.setTestWhileIdle(getProperty(props, "testWhileIdle", false));
      config.setTestOnBorrow(getProperty(props, "testOnBorrow", true));
      config.setTestOnReturn(getProperty(props, "testOnReturn", false));
      config.setNumTestsPerEvictionRun(getProperty(props, "numTestsPerEvictionRun", 10));
      config.setMinEvictableIdleTimeMillis(getProperty(props, "minEvictableIdleTimeMillis", 1000));
      config.setSoftMinEvictableIdleTimeMillis(getProperty(props, "softMinEvictableIdleTimeMillis", 10));
      config.setTimeBetweenEvictionRunsMillis(getProperty(props, "timeBetweenEvictionRunsMillis", 10));
      config.setLifo(getProperty(props, "lifo", false));
      pool = new JedisPool(config, host, port, timeout, password, database);
       
   }

怎麼辦類，元件程式碼不好改啊，java的黑科技反射解決問題，不走尋常路，不使用start方法初始化連線池，直接自己初始化一個連線池設定給pool屬性。虛擬碼如下：

JedisPoolConfig config = new JedisPoolConfig();
config.setMaxTotal(50);
JedisPool pool = new JedisPool(config, host, port, timeout, password, database);
Field field = RedisCacheProvider.class.getDeclaredField("pool");
field.setAccessible(true);
field.set(RedisCacheProvider.class, pool);

以上就是j2Cache線上異常排查問題解決記錄分析的詳細內容，更多關於j2Cache線上異常排查問題解決的資料請關注it145.com其它相關文章！