如何解決j2Cache線上異常排查問題

這篇文章主要為大家展示了“如何解決j2Cache線上異常排查問題”，內容簡而易懂，條理清晰，希望能夠幫助大家解決疑惑，下面讓小編帶領大家一起研究并學習一下“如何解決j2Cache線上異常排查問題”這篇文章吧。

問題背景

開發反饋，線上有個服務在運行一段時間后，就會拋異常導致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 <= 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線上異常排查問題”這篇文章的所有內容，感謝各位的閱讀！相信大家都有了一定的了解，希望分享的內容對大家有所幫助，如果還想學習更多知識，歡迎關注億速云行業資訊頻道！