一次现网问题定位-Redis连接不断增长

本文主要是介绍一次现网问题定位-Redis连接不断增长，希望对大家解决编程问题提供一定的参考价值，需要的开发者们随着小编来一起学习吧！

背景

系统原来是使用(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的命令执行不成功，因此准备在测试环境捣鼓一下，顺便看看测试环境是不是确实没问题。
准备工作：

1. 使用命令dump内存，jmap -dump:format=b,file=xxx.bin pid
2. 使用visualvm导入内存文件
   通过分析dump文件发现，redis连接确实存在泄漏。
   如图：Redis的连接状态是ALLOCATED，但是除了连接池，却没有其他对象持有它。这个说明之前确实有使用到这个连接，而且使用这个连接的对象已经被回收了。

所以有2个方面的原因：

1. 要么回收连接的时候，抛了异常导致状态没有修改成功。 --貌似不太可能，全球大量使用的库不可能有这种低级错误，而且自身排查源码也没发现什么疑点。
2. 代码中是否用到了某个redis特性，开启了事务，同时未提交事务，导致连接未释放
3. 有地方没有释放资源 --需要全面排查代码

对于第二点，如果开启了事务，会绑定连接到线程上下文的。可以追踪到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方法，很惊喜的发现这里没有关闭连接。

	@Overridepublic <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;# 创建大量垃圾，触发gcfor (int i = 0; i < 10000; i++) {tmp = new byte[1024000];}while (true) {;}}
}

这篇关于一次现网问题定位-Redis连接不断增长的文章就介绍到这儿，希望我们推荐的文章对编程师们有所帮助！

---