性能文章>一次 Redis Unexpected end of stream 的除错分析记录>

一次 Redis Unexpected end of stream 的除错分析记录原创

213815

这几天线上出现了偶发性jedis的异常,堆栈如下

redis.clients.jedis.exceptions.JedisConnectionException: Unexpected end of stream.
at redis.clients.util.RedisInputStream.ensureFill(RedisInputStream.java:199)
at redis.clients.util.RedisInputStream.readByte(RedisInputStream.java:40)
at redis.clients.jedis.Protocol.process(Protocol.java:151)
at redis.clients.jedis.Protocol.read(Protocol.java:215)
at redis.clients.jedis.Connection.readProtocolWithCheckingBroken(Connection.java:340)
at redis.clients.jedis.Connection.getBinaryBulkReply(Connection.java:259)
at redis.clients.jedis.Connection.getBulkReply(Connection.java:248)
at redis.clients.jedis.Jedis.get(Jedis.java:153)

看jedis的源码如下:

private void ensureFill() throws JedisConnectionException {
if (count >= limit) {
try {
limit = in.read(buf);
count = 0;
if (limit == -1) {
// 这里抛了异常
throw new JedisConnectionException("Unexpected end of stream.");
}
} catch (IOException e) {
throw new JedisConnectionException(e);
}
}
}

看起来是连接关闭的问题,但是为什么会出现呢?
我们看了当时出问题的时间点附近的redis连接数,发现了点东西

对应业务告警如下

时间点上比较接近

但是又不完全对的上时间

也就是峰值过后的第十分钟才出现,查看了jedis的配置文件如下:

redis.maxTotal = 5000000  // 值的合理性先不管他
redis.maxIdle = 1000 // 值的合理性先不管他
redis.minEvictableIdleTimeMillis = 300000 // 连接空闲大于5min的
redis.numTestsPerEvictionRun = 3 // 每次检查3个连接
redis.timeBetweenEvictionRunsMillis = 60000 // 每60s执行一次
redis.hostName = redis-master-1.gz.cvte.cn
redis.port = 6379
redis.timeout = 2147483647
redis.usePool = true

一开始,我们是怀疑jedis使用的commons-pool的空闲连接回收策略导致的,按上面的配置文件
每60s执行一次,每次检查3个连接,检查的条件是存活了5min

那我就是写代码模拟一下这种情况,连接暴涨之后,因为回收策略的问题,导致的连接使用的问题,但是我不管怎么配置,都不能模拟出Unexpected end of stream的情况,那我就怀疑到底是不是因为回收的问题,因为上面的回收配置来看,10分钟也释放不了那么多空闲连接(1次/min 10min 3 = 30)

那十分钟这个到底怎么来的,困扰了我几个小时,后来我去查看了一些redis的配置,好像想起来了什么
我们redis的配置文件设置的是600s超时,也就是10分钟

127.0.0.1:6379> config get timeout
1) "timeout"
2) "600"
127.0.0.1:6379>

看起来非常像了,那我再模拟一下,我把本地的redis的超时时间设置成2s,然后,我来试一下

fun main(args: Array<String>) {
val jedis = RedisHelper.getInstance().get()
try {
jedis.get("helo")
Thread.sleep(3000)
jedis.get("hello")
} catch (ex: Exception) {
ex.printStackTrace()
}
System.`in`.read()
}

果然复现

redis.clients.jedis.exceptions.JedisConnectionException: Unexpected end of stream.
at redis.clients.util.RedisInputStream.ensureFill(RedisInputStream.java:199)
at redis.clients.util.RedisInputStream.readByte(RedisInputStream.java:40)
at redis.clients.jedis.Protocol.process(Protocol.java:151)
at redis.clients.jedis.Protocol.read(Protocol.java:215)
at redis.clients.jedis.Connection.readProtocolWithCheckingBroken(Connection.java:340)
at redis.clients.jedis.Connection.getBinaryBulkReply(Connection.java:259)
at redis.clients.jedis.Connection.getBulkReply(Connection.java:248)
at redis.clients.jedis.Jedis.get(Jedis.java:153)

2s 连接空闲,redis 回了一个fin包,来关闭这个连接

那我们再拿来用,就抛了JedisConnectionException: Unexpected end of stream的异常

当然你会说,我们实际使用的例子,用完一次就会换回去池子里,不会拿了连接,发一次命令,过一会再发

其实这个不是个什么问题,本质上是一样的,不信我们来试一下,这次我们把连接池大小设置的小一点,比如1

fun main(args: Array<String>) {
val context = ClassPathXmlApplicationContext("classpath:*.xml")
context.start()
val redisTemplate: RedisTemplate<Serializable, Serializable> = context.getBean(RedisTemplate::class.java) as RedisTemplate<Serializable, Serializable>
redisTemplate.opsForValue().get("hallo")
Thread.sleep(3000)
redisTemplate.opsForValue().get("hallo")
System.`in`.read()
}

嗯,出现了跟线上一模一样的堆栈

Exception in thread "main" org.springframework.data.redis.RedisConnectionFailureException: Unexpected end of stream.; nested exception is redis.clients.jedis.exceptions.JedisConnectionException: Unexpected end of stream.
at org.springframework.data.redis.connection.jedis.JedisExceptionConverter.convert(JedisExceptionConverter.java:67)
at org.springframework.data.redis.connection.jedis.JedisExceptionConverter.convert(JedisExceptionConverter.java:41)
at org.springframework.data.redis.PassThroughExceptionTranslationStrategy.translate(PassThroughExceptionTranslationStrategy.java:37)
at org.springframework.data.redis.FallbackExceptionTranslationStrategy.translate(FallbackExceptionTranslationStrategy.java:37)
at org.springframework.data.redis.connection.jedis.JedisConnection.convertJedisAccessException(JedisConnection.java:242)
at org.springframework.data.redis.connection.jedis.JedisConnection.get(JedisConnection.java:1220)
at org.springframework.data.redis.core.DefaultValueOperations$1.inRedis(DefaultValueOperations.java:46)
at org.springframework.data.redis.core.AbstractOperations$ValueDeserializingRedisCallback.doInRedis(AbstractOperations.java:57)
at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:207)
at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:169)
at org.springframework.data.redis.core.AbstractOperations.execute(AbstractOperations.java:91)
at org.springframework.data.redis.core.DefaultValueOperations.get(DefaultValueOperations.java:43)
at JedisTest5Kt.main(JedisTest5.kt:24)
Caused by: redis.clients.jedis.exceptions.JedisConnectionException: Unexpected end of stream.
at redis.clients.util.RedisInputStream.ensureFill(RedisInputStream.java:199)
at redis.clients.util.RedisInputStream.readByte(RedisInputStream.java:40)
at redis.clients.jedis.Protocol.process(Protocol.java:151)
at redis.clients.jedis.Protocol.read(Protocol.java:215)
at redis.clients.jedis.Connection.readProtocolWithCheckingBroken(Connection.java:340)
at redis.clients.jedis.Connection.getBinaryBulkReply(Connection.java:259)
at redis.clients.jedis.BinaryJedis.get(BinaryJedis.java:244)
at org.springframework.data.redis.connection.jedis.JedisConnection.get(JedisConnection.java:1218)
... 7 more

那我们线上的原因可能就是:

峰值出现的时候,我们拿了很多的连接,这些连接在峰值过去以后,10min,被redis超时断掉了,但是我们commons-pool没有去检查这些连接的是否可用,导致拿到了断掉的连接

我们怎么避免上面的情况出现呢?
目前来看,牺牲一部分性能开启testOnBorrow是比较稳妥的,就是每次拿连接,都去ping一下,看连接是否可用,不可用就重建连接,我可以试一下,开了以后,程序完全正常

上面配置还有哪些问题呢?

  1. 连接设置的过大,推荐200以下
  2. 空闲连接检查设置的不合理,现在看起来好像没有太大作用
  3. 客户端最大timeout设置的过大
请先登录,再评论

👍👍👍

1月前

为你推荐

Redis进阶:深入解读阿里云Redis开发规范(修订版)
Key命名设计:可读性、可管理性、简介性规范建议使用冒号即:进行分割拼接,因为很多Redis客户端是根据冒号分类的。比如有几个Key:apps:app:1、apps:app:2和apps:app:3。
构建企业级业务高可用的延时消息中台
业务场景剖析公司业务系统(比如:电商系统)中有大量涉及定时任务的业务场景,例如:实现买卖双方在线沟通的IM系统,为了确保接收方能够收到消息,服务端一般都会有重试策略,即服务端在消息发出的一段时间内,如
Redis client链接池配置不当引起的频繁full gc
现象笔者负责的一个RPC服务就是简单的从Redis Cluster中读取数据,然后返回给上游。理论上该服务的对象大部分都应该是朝生夕死的,但是笔者查看gc log 的时候发现 age =2 的对象还真
记一次线上请求偶尔变慢的排查
前言最近解决了个比较棘手的问题,由于排查过程挺有意思,于是就以此为素材写出了本篇文章。 Bug现场这是一个偶发的性能问题。在每天几百万比交易请求中,平均耗时大约为300ms,但总有那么100多笔会超过
空中楼阁之纸上谈兵 redis中hash的思考
思考点:------与jdk中hashmap的区别?(提示从添加元素、扩容这两个行为开始分析)为什么使用这种添加方式?为什么这样扩容?扩容的时机?具体标准是?是否还有缩容呢?若有,则时机和标准呢?hg
RedLock: 看完这篇文章后请不要有任何疑惑了
后台经常会有小伙伴咨询RedLock相关问题,笔者在此再来一篇文章剖析一下RedLock,希望此文能解决你对它所有的疑惑和误解。 为什么需要RedLock这一点很好理解,因为普通的分布式锁算法在加锁时
使用虚线程进行同步网络 IO 的不阻塞原理
使用虚线程进行网络 IOProject Loom 主要目标是在 Java 平台上提供一种易于使用、高吞吐量的轻量级并发性和新的编程模型的 JVM 特性和API。这带来了许多有趣和令人兴奋的前景,其中之
Redis OOM(out of memory)内存占用过高,故障分析过程。
本文正在参加「Java应用线上问题排查经验/工具分享」活动先点赞再看,养成好习惯背景全国最大的短信平台,大家都用过我们的产品。数据量比较大,最多时候一天近7亿条短信。简单介绍一下redis(我们平台用