一个JedisConnectionException的异常跟踪调查

图片来自pixabay.com的spencerlikestorun会员

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对象,

jedis连接池

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

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

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