j2Cache 線上異常問(wèn)題排查記錄
問(wèn)題背景
開(kāi)發(fā)反饋，線上有個(gè)服務(wù)在運(yùn)行一段時(shí)間后，就會(huì)拋異常導(dǎo)致redis緩存不可用。項(xiàng)目使用了j2Caceh，異常是j2Cache的RedisCacheProvider拋出來(lái)的，如：
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問(wèn)題分析
從異常日志表象上看，很明顯是由于jedis pool中沒(méi)有資源了。當(dāng)jedis pool沒(méi)有資源，而客戶端去申請(qǐng)連接時(shí)，框架預(yù)留了一個(gè)由用戶控制的策略來(lái)處理，具體策略如下：
連接池參數(shù) ：blockWhenExhausted，有如下兩種策略
- true：阻塞等待maxWaitMillis時(shí)間(默認(rèn)）， 這個(gè)是默認(rèn)的策略，當(dāng)pool沒(méi)有可用資源時(shí)，阻塞等待maxWaitMillis時(shí)間，這個(gè)值默認(rèn)時(shí)間無(wú)限長(zhǎng)的，連接池應(yīng)該設(shè)置一個(gè)適當(dāng)?shù)牡却龝r(shí)間
- false：當(dāng)無(wú)可用連接時(shí)，立即失敗。
我們的服務(wù)并沒(méi)有設(shè)置whenExhaustedAction 的參數(shù)，maxWait設(shè)置的是1500。也就是說(shuō)當(dāng)jedis pool沒(méi)有可用資源時(shí)，獲取連接的線程等待了1.5秒，1.5秒后還沒(méi)有可用資源就拋異常了。
回到上面的問(wèn)題，導(dǎo)致jedis pool原因有哪些呢？無(wú)外乎兩點(diǎn)，如下：
假設(shè)問(wèn)題
結(jié)合上面對(duì)jedis pool的分析，而我們的服務(wù)并發(fā)度不高，默認(rèn)連接池最大連接有8個(gè)，而且獲取連接的線程在等待1.5秒后還是沒(méi)有獲取到線程，最重要的一點(diǎn)是，當(dāng)程序跑到最后，獲取不到連接的異常不在是偶發(fā)性的，變成了必然性的事件了，那么根據(jù)上面這些分析，先假設(shè)問(wèn)題就是由于程序中連接池使用不當(dāng)導(dǎo)致的問(wèn)題。程序使用jedis的地方是j2Cache，紅薯開(kāi)源的一個(gè)2階緩存框架，很可能是紅薯的鍋。
小心求證
通過(guò)對(duì)問(wèn)題的假設(shè)，我們需要在程序中找到從jedis pool中獲取資源的代碼，那首先需要找到初始化連接池的地方，j2Cache里是通過(guò)RedisCacheProvider來(lái)維護(hù)jedis pool的。下面是j2Cache里通過(guò)jedis pool的連接操作redis的代碼，可以看到，非常規(guī)范，通過(guò)try，catch，finally將資源操作包起來(lái)了，并且在finally中釋放了資源，保證資源一定會(huì)被釋放。
紅薯表示這個(gè)鍋我不背，肯定不是j2Cache的毛病了。可以看到RedisCacheProvider初始化連接池后，提供了一個(gè)靜態(tài)方法getResource()用于獲取連接，很可能是業(yè)務(wù)層面通過(guò)這個(gè)入口，拿到RedisCacheProvider里的連接了。后面繼續(xù)找，定位到了一個(gè)非常有嫌疑的方法，代碼如下：
/**
?????* 發(fā)送清除緩存的廣播命令
?????*
?????* @param?region: Cache region name
?????*/
????private?void _sendClearCmd(String region) {
????????// 發(fā)送廣播
????????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相關(guān)的代碼，但是不是紅薯的框架內(nèi)的，是我們開(kāi)發(fā)在接入j2Cache時(shí)配置的一個(gè)緩存通道內(nèi)的一段代碼。問(wèn)題就出在通過(guò)
RedisCacheProvider.getResource() 拿到j(luò)edis對(duì)象后，使用完，并沒(méi)有釋放。
問(wèn)題重現(xiàn)
上面基本定位到問(wèn)題了，下面我們模擬下發(fā)生的問(wèn)題的場(chǎng)景，代碼邏輯和上面的類似，我們初始化一個(gè)連接池后，在一個(gè)for循環(huán)中，模擬多次獲取連接但是不釋放，如：
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 + "次運(yùn)行");
????????}
????}上面代碼的運(yùn)行效果如：
而且是必然出現(xiàn)的，在第八次的時(shí)候，因?yàn)闆](méi)有可用的連接，導(dǎo)致程序在等待1.5秒后拋出了異常。
問(wèn)題解決
綜上，我們可以肯定是由于這里的代碼使用不規(guī)范，導(dǎo)致的連接池連接泄漏了。代碼修改也非常簡(jiǎn)單，在finally中判斷下jeids對(duì)象是否為null，不為null則調(diào)用其close方法，將資源回收即可。
上文所述場(chǎng)景中有個(gè)地方埋了一個(gè)小彩蛋，感興趣的小伙伴可以找下，在下方留言交流。
問(wèn)題后記-下面才是真正的原因
你以為就上面的就這么完了，還沒(méi)呢，待續(xù)ing
其實(shí)上面獲取jedis資源的代碼是沒(méi)有問(wèn)題，剛開(kāi)始忽略了一個(gè)細(xì)節(jié)，try (Jedis jedis = RedisCacheProvider.getResource()) 。獲取資源的動(dòng)作是放在try（）里的，java1.7引入了try-with-resources語(yǔ)義，我們使用的jedis版本已經(jīng)實(shí)現(xiàn)了JDK的AutoCloseable接口。所以，上面這段代碼在編譯器編譯后會(huì)變成如下的樣子：
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);
????}
?
}可以看到，編譯器自動(dòng)幫我們織入了想要在finally代碼塊內(nèi)關(guān)閉連接的動(dòng)作。
重新假設(shè)
如果不是連接泄漏導(dǎo)致的，那么肯定是并發(fā)問(wèn)題了，最終的異常是j2Cache拋出來(lái)的，從j2Cache里獲取連接的地方如下：
可以看到最上面紅框里的是之前說(shuō)的有問(wèn)題，其實(shí)沒(méi)有問(wèn)題，他們都被包在了try里面了。中間的是紅薯框架內(nèi)部用的，都手動(dòng)釋放連接了。最后一個(gè)連接有點(diǎn)小問(wèn)題，SeqServiceImpl是spring管理的一個(gè)實(shí)例，因?yàn)槭菃卫膶?shí)例，所以這里只會(huì)長(zhǎng)期占用一個(gè)連接。除了這里占用了一個(gè)連接，上面三個(gè)在try里的連接，其中一個(gè)是訂閱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")));
????????}
????}
});注意這個(gè)jedis.subscribe()。其實(shí)是個(gè)阻塞操作。也就是說(shuō)即使編輯器給這個(gè)地方加上了資源釋放的代碼，在訂閱不出問(wèn)題的情況下，也跑不到資源釋放的地方。所以這里也會(huì)長(zhǎng)期占用一個(gè)連接。
那么我們?cè)诔绦蚶锟捎玫倪B接數(shù)=（最大連接數(shù)-兩個(gè)長(zhǎng)期占用連接）=（8-2）=6個(gè)
從異常信息獲取點(diǎn)有用信息，最終發(fā)現(xiàn)，拋出連接不可用的代碼有共性，都指向了一個(gè)類，但是是兩個(gè)方法，如：
最終跟蹤代碼發(fā)現(xiàn)，這個(gè)兩個(gè)方法是給鑒權(quán)攔截器調(diào)用的，攔截器會(huì)攔截每個(gè)請(qǐng)求，代碼語(yǔ)義類似下面，
@Override
public?boolean?preHandle(HttpServletRequest request, HttpServletResponse response,
?????????????????????????Object handler)?throws?Exception {
????RunResult runResult = sysApiService.auth(null);
????sysApiService.update("", runResult.getData(), request);
????return?super.preHandle(request, response, handler);
} 也就是每個(gè)請(qǐng)求都至少會(huì)對(duì)redis操作兩次，在沒(méi)有完成之前都不會(huì)釋放資源。
在看看拋異常的時(shí)間點(diǎn)的服務(wù)訪問(wèn)情況，在日志平臺(tái)將時(shí)間限定在2019-06-03 17:45~2019-06-03 17:46 ，搜索結(jié)果如下：
從06-03 17:45:49 到 06-03 17:45:56 日志總條數(shù)299條。每秒請(qǐng)求數(shù)=（299/56-49）=42 。omygad的，連接池只有6個(gè)可用連接完全不夠用。這回真的石錘了。
最終解決
設(shè)置連接池的maxTotal參數(shù)即可，但是有個(gè)問(wèn)題是，這個(gè)項(xiàng)目使用的j2Cache的版本比較老，代碼的配置信息限定死了就那么個(gè)幾個(gè)，而且沒(méi)有預(yù)留maxTotal的設(shè)置。紅薯的初始化連接池的代碼如下：
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的黑科技反射解決問(wèn)題，不走尋常路，不使用start方法初始化連接池，直接自己初始化一個(gè)連接池設(shè)置給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);關(guān)注GitHub今日熱榜，專注挖掘好用的開(kāi)發(fā)工具，致力于分享優(yōu)質(zhì)高效的工具、資源、插件等，助力開(kāi)發(fā)者成長(zhǎng)！
點(diǎn)個(gè)在看 你最好看
