一个JedisConnectionException的异常跟踪调查

1. 问题缘起

有一个web服务应用一直在稳定运行，直到最近一个月，陆续三次在晚上出现了JedisConnectionException的异常，服务集群几乎在同一时间段都报同一错误，无法正常运行，重启后一切正常。

redis.clients.jedis.exceptions.JedisConnectionException: Could not get a resource from the pool
   at redis.clients.util.Pool.getResource(Pool.java:50)
   at redis.clients.jedis.JedisPool.getResource(JedisPool.java:86)
    …
Caused by: java.util.NoSuchElementException: Timeout waiting for idle object
    at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:449)

2. 现场处理和初步调查结论

• JedisConnectionException异常所报告的问题是，无法正常获取连接，通过查看redis连接池配置（maxTotal=200）和当时的并发流量（并发数小于5），没有发现不对和特别的地方。
• 通过netstat查看网络TCP连接，redis连接数也不多（小于20），正常连接中，在redis服务器端可以观察到有连接正在陆续正常地新建和关闭，网络没有问题。
• 查看zabbix和pinpoint监控，主站应用的CPU使用率有升高，不过在正常范围内，但响应时间有飙高（长达6秒），预计是获取redis连接阻塞的原因（在redis客户端设置阻塞时间为6秒）。
• 为了能够保证主站恢复使用，调查一段时间后，决定重启应用，然后检查所有服务，一切恢复正常使用。

3. 调查方向

根据现象，确定如下几个调查方向，

1. 查看redis的访问代码实现，是否有redis连接泄漏？并尝试是否可以本地开发环境重现同样问题。
2. 查看线上配置，是否配置不正确或者未加载的情况？
3. 查看网络原因，是否由于因为防火墙导致单机连接有限制？
   • 查看iptables
   • 使用tcpdump查看TCP流量
4. 查看主站应用的请求访问日志和运行日志，查看异常前后有无特别的请求访问？
   • 请求访问日志 localhost_access_log.2018-12-28
   • 运行日志 catalina.out-20181228

4. 定位问题

通过查看代码时，发现有段代码在获取redis连接后，没有在方法退出时执行close()方法，

public void leakRedisConn() {
  Jedis jedis = null;
    try {
        jedis = jedisPool.getResource();
        jedis.ping();
    } catch (Exception ignored) {
    } finally {
        // 没有归还redis连接到空闲资源池
        // if (jedis != null) jedis.close();
    }
}

查看服务集群的请求访问日志和运行日志，发现在JedisConnectionException异常出现前，都有对该方法的调用，印证此方法和异常的出现有强关联性，因此上述方法应该就是异常发生的罪魁祸首。

该方法在获取连接后，并没有执行close()方法，使得redis连接无法回收到空闲资源池，每一次调用，都会泄漏一个连接，直到整个连接池队列达到上限，从而出现异常。具体原因见对JedisPool的代码分析。

5. 异常出现的原因和JedisPool代码分析

通过分析JedisPool的实现代码，可以看到里面有两个内部对象allObjects和idleObjects，一个是保存着所有连接对象，一个是保存着所有空闲连接对象，

public class JedisPool extends Pool<Jedis> {
  protected GenericObjectPool<T> internalPool;
}

// JedisPool里通过GenericObjectPool维护着所创建的连接池对象，实现Jedis连接的创建、获取和回收，
class GenericObjectPool{
    private final Map<T, PooledObject<T>> allObjects; // 保存着所有连接对象，上限通过maxTotal控制
    private final LinkedBlockingDeque<PooledObject<T>> idleObjects; // 保存着所有空闲连接对象，上限通过maxIdle控制
}

每次创建时，新建的连接会放入allObjects列表中，在close()方法调用时，空闲的连接会存放入idleObjects，以待后续重复利用。

方法jedisPool.getResource()会先尝试从空闲队列中获取连接，若获取不到，则尝试新建一个连接。一旦获取到的连接没有执行close()方法，则无法被回收到空闲队列，于是每一次方法调用，allObjects连接池中会增加一个，一旦数量超过maxTotal，则不再允许创建，请见下面的代码，

class GenericObjectPool{

  public T borrowObject(long borrowMaxWaitMillis) throws Exception {
     ...
     boolean create;
     p = (PooledObject)this.idleObjects.pollFirst();
     if(p == null) {
         p = this.create();
         if(p != null) {
            create = true;
         }
     }
     ...
  }

  private PooledObject<T> create() throws Exception {
        int localMaxTotal = this.getMaxTotal();
        long newCreateCount = this.createCount.incrementAndGet();

        // 当创建的个数大于maxTotal时，则不再允许创建，直接返回null
        if((localMaxTotal <= -1 || newCreateCount <= (long)localMaxTotal) && newCreateCount <= 2147483647L) {
            PooledObject p;
            try {
                p = this.factory.makeObject();
            } catch (Exception var6) {
            }
            ...
            return p;
        } else {
            this.createCount.decrementAndGet();
            return null;
        }
  }

}

注意的是，泄漏的连接在redis服务器端在超时后会被关闭，但在客户端则一直占着位置不会被释放，从而报JedisConnectionException异常，直到重启。

5. 后记

对这个JedisConnectionException的异常泄漏问题解决后，后来想了想，还有两个事情可以总结下，以待未来改进。

5.1 保留问题第一现场

在发生问题时，可以通过如下jmap命令保存下Java内存快照，保留第一现场，这样能够为后续查看发生问题，分析JedisPool对象的内部数据提供方便。

jmap -dump:format=b,file=jmap.dump <pid>

下图是通过Eclipse的MemoryAnalyzer工具分析的JedisPool对象，

若当时有上面的内存快照，可以看到minIdle/maxIdle的配置情况，也可以看到createCount的变量值，这样会更加容易发现redis泄漏问题。

5.2 一颗老鼠屎，坏了一锅粥

对于Jedis连接池这种全局有限资源，必须严控管理，规范使用，不然一个地方出现泄漏，就会导致整个应用崩溃，本案例是一个活生生的例子。