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原因有哪些呢？无外乎两点，如下：
- 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 {
RunResult<ApiSession> runResult = 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);作者简介：
陈凯玲，2016年5月加入凯京科技。现任凯京科技研发中心架构&运维部架构组经理，救火队队长。独立博客KL博客（http://www.kailing.pub）博主。
