Jedis 连接异常分析

·  阅读 2006

问题背景

线上的应用告警邮件告警显示频繁出现 : redis.clients.jedis.exceptions.JedisConnectionException: Unexpected end of stream.

堆栈如下图:

image-20200424223318810

频率和出错时间点如下图---看出错的时间点的频率图看起来还是有一定规律可寻,差不多每10分钟就会有8次

image-20200424223854657

###排查步骤

1. 没有遇见过这个错,也不知道为什么,先谷歌下可能的原因如下:
1.输出缓冲区满
2.长时间闲置连接被服务端主动断开,可以查询timeout配置的设置以及自身连接池配置是否需要做空闲检测。
3.不正常并发读写:Jedis对象同时被多个线程并发操作,可能会出现上述异常。(每个线程一个jedis对象)

分析了这三个原因和出错的代码片段:
排除可能原因1. 线上的redis都是运维统一配置的,项目中也只有这个片段会出错,对redis操作输入输出的key和value很小,应该不会是缓冲区满的问题
排除可能原因3. 代码的使用场景很低频,是加锁的逻辑,但是这段代码并发的调用可能很少,几乎可以忽略

所以最大的可能原因就是2
2. 根据怀疑的原因找运维大佬看下redis服务端的保活参数配置,发现 timeOut和tcp_keepalive都是600s,10分钟
3.再对比上面报错的时间点比对,刚和redis服务端的保活参数能匹配上,估计没啥幺蛾子问题都出现在这了
4. jmap -dump:format=b,file=out.hprof 1 分析线上的连接池配置,发现线上没有保活配置

image-20200426170002549

4.分析代码-报错的代码片段和redis连接池的配置

image-20200424225620789

用的lockTemplate是公司内部封装的

@Data
public class RedisProperties extends GenericObjectPoolConfig {
    private String host;
    private int port;
    private String password;
}

/**
 *org.apache.commons.pool2.impl.GenericObjectPoolConfig 的默认保活参数都是false
 */  
class GenericObjectPoolConfig{
    .......
    .......
  	private boolean testOnCreate = DEFAULT_TEST_ON_CREATE; // false

    private boolean testOnBorrow = DEFAULT_TEST_ON_BORROW; // false

    private boolean testOnReturn = DEFAULT_TEST_ON_RETURN; // false

    private boolean testWhileIdle = DEFAULT_TEST_WHILE_IDLE; // false
  
		.......
    .......
}

/**
 * 由于GenericObjectPoolConfig默认的保活参数都是false
 */
private ConnectionFactory buildConnectionFactory(RedisProperties redisProperties) {
  if (redisProperties == null) {
    //没有配置锁的redis,则从项目中查找已有的JedisPool
    Pool<Jedis> jedisPool = lookupJediPoolFromSpring();
    return new JedisConnectionFactory(jedisPool);

  } else {
    return new JedisConnectionFactory(
      redisProperties.getHost(), redisProperties.getPort(),
      redisProperties.getPassword(), redisProperties);
  }
}
    
5. 由于GenericObjectPoolConfig默认的保活参数都是false,而且组件中并未特殊设置,导致lockTemplate的连接 池没有保活策略,如果连接长时间不用,超过了 redis-server的timeOut时间,就会被服务端主动关闭掉,但是连接池,并无感知,所以关闭掉的连接一直没有释放

其实上边分析连接池配置的参数和代码,由于不是很了解redis的组件,其实还是花了点时间的,但是找到之后还是很容易理解的

为什么测试环境没有出现?(打自己脸,狠狠打)

test:

spring.redis.host = *.*.*.*
spring.redis.port = 6379
spring.redis.data.expire = 3600
spring.redis.data.max.time = 2592000
spring.redis.jedis.pool.maxActive = 30
spring.redis.jedis.pool.maxWait = 3000
spring.redis.jedis.pool.maxIdle = 8
spring.redis.jedis.pool.minIdle = 0

pro:

spring.redis.host = *.*.*.*
spring.redis.port = 6384
spring.redis.data.expire = 3600
spring.redis.data.max.time = 2592000
spring.redis.jedis.pool.maxActive = 8
spring.redis.jedis.pool.maxWait = 3000
spring.redis.jedis.pool.maxIdle = 8
spring.redis.jedis.pool.minIdle = 0

# 锁相关的配置,这里给出的是默认的配置
lock.lockWaitMillis = 5000
lock.lockExpireMillis = 600000
lock.retryMillis = 100

# redis连接和连接池相关配置,如果本身项目配置了spring data redis的配置,则下面的配置建议去掉,组件可以直接使用项目的连接池
lock.redis.host = *.*.*.*
lock.redis.port = 6379
lock.redis.max-idle = 8
lock.redis.min-idle = 4
lock.redis.max-active = 8
lock.redis.max-wait = 10000
测试环境和线上环境唯一的差异就是,只配了spring data redis的连接池,也就是说,测试环境,加锁的组件和正常的redis操作都是使用的spring data redis,我们看下spring data redis的数据库连接池是怎么设置的
org.springframework.boot.autoconfigure.data.redis.JedisConnectionConfiguration

@Configuration
@ConditionalOnClass({ GenericObjectPool.class, JedisConnection.class, Jedis.class })
class JedisConnectionConfiguration extends RedisConnectionConfiguration {
	private JedisPoolConfig jedisPoolConfig(RedisProperties.Pool pool) {
    // 注意使用的是JedisPoolConfig
		JedisPoolConfig config = new JedisPoolConfig();
		config.setMaxTotal(pool.getMaxActive());
		config.setMaxIdle(pool.getMaxIdle());
		config.setMinIdle(pool.getMinIdle());
		if (pool.getMaxWait() != null) {
			config.setMaxWaitMillis(pool.getMaxWait().toMillis());
		}
		return config;
}


package redis.clients.jedis;

import org.apache.commons.pool2.impl.GenericObjectPoolConfig;

public class JedisPoolConfig extends GenericObjectPoolConfig {
  public JedisPoolConfig() {
    // defaults to make your life with connection pool easier :)
    setTestWhileIdle(true);
    setMinEvictableIdleTimeMillis(60000);
    setTimeBetweenEvictionRunsMillis(30000);
    setNumTestsPerEvictionRun(-1);
  }
}

结论: spring data redis的jedis连接池配置使用的JedisPoolConfig,虽然JedisPoolConfig 同样使用了 GenericObjectPoolConfig,但是他自己开启了检测空闲链接有效性的配置,所以测试环境的连接是会被保活策略检查的。

复现问题

class JedisTest {
    fun testBatchPool() {
        val config = JedisPoolConfig()
        config.numTestsPerEvictionRun = 3
        config.timeBetweenEvictionRunsMillis = 12000
        config.minIdle = 5
        config.maxTotal = 10
        config.testOnBorrow = false
        config.testWhileIdle = true

        val pool = JedisPool(config, "127.0.0.1", 6379)

        val list: List<Int> = listOf(0, 1, 2, 3, 4, 5, 6, 7, 8, 9)
        // 初始化10个连接
        list.map { pool.resource }.forEach(Jedis::close)

        println("idle: ${pool.numIdle}")
        // 等待14秒
        Thread.sleep(15000)

        println(LocalDateTime.now())
        println("idle: ${pool.numIdle}")
        list.map { pool.resource }
                .forEach {
                    try {
                        it.get("key")
                    } catch (e: java.lang.Exception) {
                        e.printStackTrace()
                    }
                }
    }
}

fun main() {
    JedisTest().testBatchPool()
}

验证结果: 出现了5次 Unexpected end of stream.

image-20200425130620523

再次深究(保活参数的作用):

# 服务端保活参数

# Close the connection after a client is idle for N seconds (0 to disable)
# 此参数为设置客户端空闲超过timeout,服务端会断开连接,为0则服务端不会主动断开连接,不能小于0。
timeout 10

# 此参数为发送Ack包探测客户端是否存活
# TCP keepalive.
#
# If non-zero, use SO_KEEPALIVE to send TCP ACKs to clients in absence
# of communication. This is useful for two reasons:
#
# 1) Detect dead peers.
# 2) Take the connection alive from the point of view of network
#    equipment in the middle.
#
# On Linux, the specified value (in seconds) is the period used to send ACKs.
# Note that to close the connection the double of the time is needed.
# On other kernels the period depends on the kernel configuration.
#
# A reasonable value for this option is 300 seconds, which is the new
# Redis default starting with Redis 3.2.1.
tcp-keepalive 10


客户端保活参数
org.apache.commons.pool2.impl.BaseGenericObjectPool

testOnCreate 从pooledObjectFactory创建对象添加到objectPool时,是否进行有效性验证
testOnBorrow pooledObject获取时,是否进行有效性验证
testOnReturn pooledObject用完了"还"给objectPool时,是否进行有效性验证
testWhileIdle 空闲检测
	timeBetweenEvictionRunsMillis 空闲检测的间隔时间
	numTestsPerEvictionRun 每次检测的个数
	minEvictableIdleTimeMillis 空闲链接存活的最小时间
	
BaseGenericObjectPool 中的检测代码 TimeTask
org.apache.commons.pool2.impl.BaseGenericObjectPool.Evictor

Jedis连接池过期后会调用quit命令

再看下wireshark抓下客户端和redis服务器的包

image-20200425130600011

image-20200425130644813

发现有几个连接是段开始redis客户端发起QUIT,服务端返回OK,但是4次挥手没有完成,导致RST

RST

在TCP协议中,rst段标识复位,用来异常的关闭连接。在TCP的设计中它是不可或缺的,发送rst段关闭连接时,不必等缓冲区的数据都发送出去,直接丢弃缓冲区中的数据。而接收端收到rst段后,也不必发送ack来确认。

向没有监听的端口或者异常的连接发数据,被发送的一方会发送一个RST数据

再去翻了下Jedis的源码,发现Jedis的关闭或者销毁连接时,发送一个QUIT命令,然后就直接断开了,服务端还傻傻的进行4次挥手,但是其实现在连接已经不在了

image-20200425131237152

image-20200425140007393

分类:
后端
标签:
分类:
后端
标签:
收藏成功!
已添加到「」, 点击更改