背景
系统原来是使用(HAProxy+Sentinel+redis)做的高可用方案,该方案HAProxy无法感知到主从切换,导致写操作失败。具体可参考之前的文章。
为了解决这个问题,拿掉了HAProxy,然后使用Jedis的Sentinel模式。
# 代码有删减
RedisSentinelConfiguration redisSentinelConfiguration = new RedisSentinelConfiguration(sentinel.getMaster(), sentinelHostAndPorts);
JedisPoolConfig jedisPoolConfig = new JedisPoolConfig();
JedisConnectionFactory jedisConnectionFactory = new JedisConnectionFactory(redisSentinelConfiguration, jedisPoolConfig);
jedisConnectionFactory.afterPropertiesSet();
切换新方案上线后,白天业务高峰期,redis报错:
org.springframework.data.redis.RedisConnectionFailureException: Cannot get Jedis connection; nested exception is redis.clients.jedis.exceptions.JedisConnectionException: open to many files.
定位思路
1.解决open to many files
open to many files一般是超过了系统打开文件数限制。linux一切皆文件,包括网络连接。因此猜测是网络高峰期网络请求太多导致。
解决方法
通过ulimit命令查看当前限制,并通过lsof -p pid查看进程当前已打开文件数。发现系统限制为4096,当前已打开文件数已达到这个限制。
因此先使用ulimit提高这个限制。
结果
当提高系统文件限制数量后,观测打开文件数仍在不断增长。对比以往业务量,这个现象明显有异常,因此分析连接的分布,发现大部分都是redis的连接。
2.定位为什么redis的连接数会不断增长
对比之前版本,本版本只是修改的redis连接方式,运维这边怀疑是哨兵模式本身有问题。个人觉得redis哨兵模式几年前就发布了,要是有BUG,早报到开源社区修复了。之前分析哨兵模式源码时,主从切换jedis会清理连接池,而且redis本身没有事务(具备完整的acid特性,此处表达不够准确),访问完后就会释放连接,本身不应该有问题。
连接数不断增长有可能的原因应该就2点:
1.redis连接有泄漏,未回收 --测试环境没有复现问题,此原因存疑。
2.现网就是有这么大访问量,导致redis连接需求有这么高。 --由于系统配置原因,无法使用jstack查看线程堆栈来确认这一点。(因为redis没有事务,执行完查询后,连接直接释放,所以一个线程理论上最多只会持有一个redis连接,所以可以通过线程堆栈来确认)
尝试一:确认redis连接释放是否存在失败的可能
经过源码排查(源码分析见另外一篇文章),不太有可能。
- 如果释放失败,会抛异常打日志。
- 如上jedis这个包已经在全球现网经受了考验,不太可能有这方面的bug。
尝试二:系统原班开发人员提供了一个疑点
执行multi命令后,未执行exec()方法。
stringRedisTemplate.multi();
stringRedisTemplate.boundHashOps(hkey).put(vkey, vval);
stringRedisTemplate.expireAt(hkey, TimeUtil.startDate(incre));
multi指令是为redis事务准备的,虽然无法进行回退,但是他能保证指令的原子性(redis是单线程的,通过multi包装的指令,redis一次性全部执行完,中间不会插入其他连接发过来的指令)。
为了保证指令的原子性,redis连接肯定是需要被绑定的(执行multi后,当前连接需要跟线程绑定,这样在执行exec前都需要从ThreadLocal去获取同一个连接),不然上面3行代码都是用不同的连接,是无法实现multi指令的。
初步看上述代码嫌疑很大。
结果,验证失败
本地按照现网的模式,写了一个测试代码,并使用redis客户端,通过info clients发现连接数并不如预期会不断增长。
String prefix = "test";
for (int i = 0; i < 100; i++) {
String key = prefix + String.valueOf(i);
new Thread(() -> {
while (true) {
stringRedisTemplate.multi();
stringRedisTemplate.boundHashOps(key).put("a", "vval");
stringRedisTemplate.expireAt(key, TimeUtil.startDate(1));
try {
Thread.sleep(2000);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}).start();
}
通过阅读源码发现,redistemplate只有启用enableTransactionSupport后,才会开启事务功能。
此配置未开启的情况下,即使是执行multi方法,执行完后释放连接的时候,会立即执行exec方法,进行自动提交。
大家可以执行跟踪muti方法的执行,主方法在Redistemplate#execute(RedisCallback action, boolean exposeConnection, boolean pipeline)
public <T> T execute(RedisCallback<T> action, boolean exposeConnection, boolean pipeline) {
RedisConnectionFactory factory = getRequiredConnectionFactory();
RedisConnection conn = null;
try {
if (enableTransactionSupport) {
# 如果开启事务,会对将Redis连接绑定到线程的上下文,方便后面执行获取到的是同一个连接。
# 同时会对RedisConnection进行包装,因为需要拦截close方法,防止连接被回收到连接池
conn = RedisConnectionUtils.bindConnection(factory, enableTransactionSupport);
} else {
# 走这个分支
conn = RedisConnectionUtils.getConnection(factory);
}
boolean existingConnection = TransactionSynchronizationManager.hasResource(factory);
T result = action.doInRedis(connToExpose);
return postProcessResult(result, connToUse, existingConnection);
} finally {
# 执行完命令后,需要释放连接。这就是为啥之前强调一个线程最多只用使用一个redis连接。因为一般的指令执行完后,连接会立即释放
# 线程里面的执行都是串行执行的,所以不可能一个线程同时执行2个Redis方法,来持有2条redis连接
RedisConnectionUtils.releaseConnection(conn, factory, enableTransactionSupport);
}
}
到此已经没有办法分析下去了。
尝试三:只能通过dump线程及内存去分析当前线程情况及内存对象。
之前现网jdk的命令执行不成功,因此准备在测试环境捣鼓一下,顺便看看测试环境是不是确实没问题。
准备工作:
- 使用命令dump内存,jmap -dump:format=b,file=xxx.bin pid
- 使用visualvm导入内存文件
通过分析dump文件发现,redis连接确实存在泄漏。
如图:Redis的连接状态是ALLOCATED,但是除了连接池,却没有其他对象持有它。这个说明之前确实有使用到这个连接,而且使用这个连接的对象已经被回收了。
所以有2个方面的原因:
- 要么回收连接的时候,抛了异常导致状态没有修改成功。 --貌似不太可能,全球大量使用的库不可能有这种低级错误,而且自身排查源码也没发现什么疑点。
- 代码中是否用到了某个redis特性,开启了事务,同时未提交事务,导致连接未释放
- 有地方没有释放资源 --需要全面排查代码
对于第二点,如果开启了事务,会绑定连接到线程上下文的。可以追踪到TransactionSynchronizationManager#resources字段。被绑定的连接都是存在这个里面,因此想通过dump出来的内存,去查找这种对象的信息。遗憾的是,visualvm查找起来太麻烦,遂放弃。
于是找原班人马分析一下用到的redis高阶功能,这样可以快速缩小范围。
根据提供的范围,快速锁定了下面的代码。因为游标类似滑动窗口,一般都会保持与服务端的连接,这样可以实现分批次找服务端查询数据,防止单次查询数据量过大,内存溢出。这里代码又没有显示的关闭游标,泄漏很可能是这里导致。 (ps:要是还不是这个原因,真滴就脑壳疼了,已经快没招了,只能头铁去验证第二点了)
public Map<String, String> hscan(final String key, int count) {
ScanOptions scanOptions = ScanOptions.scanOptions().count(count).match("xxxx").build();
Cursor<Map.Entry<Object, Object>> cursor = stringRedisTemplate.opsForHash().scan(key, scanOptions);
while (cursor.hasNext()){
Map.Entry<Object,Object> entry = cursor.next();
result.put(entry.getKey().toString(),entry.getValue().toString());
}
return result;
}
根据scan方法定位到RedisTemplate的executeWithStickyConnection方法,很惊喜的发现这里没有关闭连接。
@Override
public <T extends Closeable> T executeWithStickyConnection(RedisCallback<T> callback) {
Assert.isTrue(initialized, "template not initialized; call afterPropertiesSet() before using it");
Assert.notNull(callback, "Callback object must not be null");
RedisConnectionFactory factory = getRequiredConnectionFactory();
RedisConnection connection = preProcessConnection(RedisConnectionUtils.doGetConnection(factory, true, false, false),
false);
return callback.doInRedis(connection);
}
理论上上面的分析已经能够解释Redis连接泄漏的问题了,剩的就是本地复现。
答疑
为啥切换之前没有这个问题,切换之前,没有启用连接池。当Curse对象被GC回收后,RedisConection也会被GC被回收,从而释放连接。
切换后,RedisConection除了被Curse持有,还会被连接池持有。Curse回收后,RedisConection仍然在内存中,然后状态还是ALLOCATED无法被复用,这样新连接会不断的被创建,最终达到ulimit的限制。
补充-对“RedisConection也会被GC被回收,从而释放连接”的解释
jvm回收对象的时候,不会自动调用close方法,但是会调用finalize()方法清理资源。
RedisConection本身不占有系统资源,而是其持有的socket占有资源。通过代码跟踪可以看到,RedisConection不显示调用close,gc后也能关闭连接,是因为其持有的socket实现了finalize,并在gc的时候关闭了连接。
Jedis jedis = new Jedis("10.21.22.175",6381);
jedis.connect();
redis.clients.jedis.BinaryJedis#connect
public void connect() {
this.client.connect();
}
redis.clients.jedis.Connection#connect
public void connect() {
if (!this.isConnected()) {
try {
this.socket = this.jedisSocketFactory.createSocket();
this.outputStream = new RedisOutputStream(this.socket.getOutputStream());
this.inputStream = new RedisInputStream(this.socket.getInputStream());
}
}
}
redis.clients.jedis.DefaultJedisSocketFactory#createSocket
public Socket createSocket() throws IOException {
Socket socket = null;
try {
socket = new Socket();
socket.setReuseAddress(true);
socket.setKeepAlive(true);
socket.setTcpNoDelay(true);
socket.setSoLinger(true, 0);
socket.connect(new InetSocketAddress(this.getHost(), this.getPort()), this.getConnectionTimeout());
socket.setSoTimeout(this.getSoTimeout());
# 代码有删减
}
java.net.Socket#setImpl
void setImpl() {
if (factory != null) {
impl = factory.createSocketImpl();
checkOldImpl();
} else {
# 实际走的是这个分支
impl = new SocksSocketImpl();
}
if (impl != null)
impl.setSocket(this);
}
SocksSocketImpl的父类AbstractPlainSocketImpl实现了finalize,并进行了连接关闭
java.net.AbstractPlainSocketImpl#finalize
protected void finalize() throws IOException {
close();
}
测试方法
在java.net.AbstractPlainSocketImpl#finalize方法打一个断点,并观察该代码是否会被执行。
public class DemoApplication {
public static void main(String[] args) {
Jedis jedis = new Jedis("xx.xx.xx.xx",6379);
jedis.connect();
jedis = null;
byte[] tmp;
# 创建大量垃圾,触发gc
for (int i = 0; i < 10000; i++) {
tmp = new byte[1024000];
}
while (true) {
;
}
}
}