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線上異常排查問題解決記錄分析的詳細內容,更多關於j2Cache線上異常排查問題解決的資料請關註WalkonNet其它相關文章!
推薦閱讀:
- SpringBoot集成Redis並實現主從架構的實踐
- redis使用不當導致應用卡死bug的過程解析
- redis 獲取 list 中的所有元素操作
- Java連接Redis全過程講解
- Java使用Redis及其優化詳解