背景
公司系统在昨晚升级之后,一晚上基本没睡觉的我一大早7点被运维打电话叫醒,并告诉了我一个噩耗:线上Redis连接过载!连接数是未升级之前的2-3倍!!cpu被打到90%!!系统处于奔溃的边缘,或者说,已经奔溃了!
问题排查
此时的我也是奔溃的,来不及去公司,直接开电脑开始排查,好
冷静一下,排查思路要明确:
- 连接数这么高,那这么多连接现在在做什么!
- 连接数高是某个应用单独连接数高导致,还是每个应用连接都比之前高2-3倍导致。
- 是否有连接泄漏,回想昨晚升级的点是否有地方导致应用连接泄漏。
关于第一点:
client list 命令在Redis服务器上执行看下这么多连接都在做什么:
结果发现大量的ping请求打在Redis服务器上,而且大多数ping请求的idle空闲时间不长,如下截图:
再让运维看下消耗cpu的命令排行榜:ping命令占用50%cpu
马上确认第二个问题,是具体哪个服务发起的ping还是每个服务都有ping:
运维采样几个服务上的Redis连接数,发现每个服务连接数都很高。也就是每个服务都在执行大量的ping命令。
关于第三个问题,想想看昨晚修改的代码,哪里可能有连接泄漏风险:
其实不用想了,从现象上看,这个不是连接泄漏,而是应用拿了较多的连接,且这些连接都在执行ping操作,泄漏的话应该会不止2-3倍连接,且连接的idle空闲时间会更长!
再想:现在现象是升级之后有大量的ping命令打到服务器上,这显然不是我们代码导致的,代码不会无缘无故去执行与业务无关的ping命令。但肯定是升级导致的,毕竟升级前后差距太大,那既然不是代码导致,升级前后有什么差异?对了,是不是配置会调整?马上让运维看下升级前后的nacos配置,最终看到不同的点:
太坑了,testOnBorrow配置不小心被人打开为true了!当即让运维修改false关闭并逐个重启几十个涉及到的服务,随着服务重启,redis连接逐渐下降到恢复正常;整个过程历经1小时,线上生产事故大奖已发放。
问题总结
至于testOnBorrow为什么会引起这么多ping命令,这个后面会说。
testOnBorrow配置项其实来自于Apache CommonPools,意思是从连接池中取出是检查连接是否失活,默认都是关闭的,之前mysql数据库因为这个配置项开启会引起性能问题我们是知道的,所以当时发现testOnBorrow被打开,想都不用想为什么会导致ping多,直接让运维关闭再说。
原因分析
公司底层连接Redis客户端用的是Jedis,看下为什么这个配置打开会导致有很多ping。
先来看下Redis配置都有哪些
testOnBorrow配置介绍:
#指明是否在从池中取出对象前进行检验,如果检验失败,则从池中去除连接并尝试取出另一个.
testOnBorrow =false
大家都知道Jedis是Java Redis 连接池,从maxIdle、minIdle、maxTotal等配置可以知道Jedis也是实现了apache common pool连接池的一种,像我们数据库的连接池等原理一样,一定也是实现并重写了apache common pool连接池的,有关apache common pool连接池简单介绍参考:
https://www.jianshu.com/p/2cd47d1e4aee
想想看:
连接池的套路基本都一样的,工厂模式肯定会被用到,Google大致了解一下apache common pool的默认工厂类:PooledObjectFactory
里面方法不多,值得注意的两个方法很快被注意到:
//生产对象的方法
PooledObject<T> makeObject() throws Exception;
//校验对象的方法
boolean validateObject(PooledObject<T> p);
Jedis肯定是实现了它的工厂类,顺着找到Jedis的工厂类JedisFactory,对应看下这两个方法的实现,熟悉的代码找到了,可疑的点也找到了:
//validateObject()方法中:jedis.ping().equals("PONG") !!!在执行命令
@Override
public boolean validateObject(PooledObject<Jedis> pooledJedis) {
final Jedis jedis = pooledJedis.getObject();
try {
// 看看这是在干什么?? jedis.ping()!!!!!!!!!!!!!!!!
return jedis.getConnection().isConnected() && jedis.ping().equals("PONG");
} catch (final Exception e) {
logger.error("Error while validating pooled Jedis object.", e);
return false;
}
}
@Override
public PooledObject<Jedis> makeObject() throws Exception {
Jedis jedis = null;
try {
//这代码是不是很不熟悉
jedis = new Jedis(jedisSocketFactory, clientConfig);
jedis.connect();
return new DefaultPooledObject<>(jedis);
} catch (JedisException je) {
if (jedis != null) {
try {
jedis.quit();
} catch (RuntimeException e) {
logger.debug("Error while QUIT", e);
}
try {
jedis.close();
} catch (RuntimeException e) {
logger.debug("Error while close", e);
}
}
throw je;
}
}
再找找看工厂生产方法是不是会执行validateObject()方法,找一下这个方法会被什么类调用,如图:
打开对应类方法:
破案
Jedis的testOnBorrow配置项实现原理就是从连接池获取连接时,利用Redis提供的PING命令来检查连接是否可用,生产上不小心打开了,至于怎么不小心打开了不重要,重要的是打开了会导致每次获取连接时,向Redis额外执行一下ping命令。
总结
有关连接池的配置,像数据库连接池等,生产环境testOnBorrow配置均需关闭,有兴趣可以看下数据库连接池validateObject()方法做了什么,肯定也会带来较大性能消耗。