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);