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

問題分析

從異常日誌表象上看，很明顯是因爲jedis pool中沒有資源了。當jedis pool沒有資源，而客戶端去申請鏈接時，框架預留了一個由用戶控制的策略來處理，具體策略以下：

鏈接池參數 ： blockWhenExhausted，有以下兩種策略

• true：阻塞等待maxWaitMillis時間(默認）， 這個是默認的策略，當pool沒有可用資源時，阻塞等待maxWaitMillis時間，這個值默認時間無限長的，鏈接池應該設置一個適當的等待時間
• false：當無可用鏈接時，當即失敗。

咱們的服務並無設置whenExhaustedAction 的參數，maxWait設置的是1500。也就是說當jedis pool沒有可用資源時，獲取鏈接的線程等待了1.5秒，1.5秒後尚未可用資源就拋異常了。

回到上面的問題，致使jedis pool緣由有哪些呢？無外乎兩點，以下：

• 一、正常狀況：程序併發高，致使偶發性的鏈接池無可用資源
• 二、異常狀況：鏈接池使用不當，當從鏈接池獲取資源後，使用完時沒有正常的釋放資源，致使鏈接池取一個少一個，最後必然性的會拋出開頭的異常

假設問題

結合上面對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)www.qilinchengdl.cn, 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="www.cmyLgw.cn  + 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(www.chengmyuLegw.cn)) { 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 { RunResult<ApiSession> runResult = sysApiService.www.cmylli.com auth(null); sysApiService.update("", runResult.getData(www.xinhezaixia.cn), 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"yuntianyuled.cn, 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, www.yuntianyuL.cn"timeBetweenEvictionRunsMillis", 10)); config.setLifo(getProperty(props, "lifo", www.yuntianyul.com 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);