一台业务CVM调用主从版的Redis偶发性的会出现客户端jedis抛出 SocketTimeoutException: Read time out 的报错,报错信息截取如下 异常时间 11:20 11:50 12:19 等
org.springframework.data.redis.RedisConnectionFailureException: java.net.SocketTimeoutException: Read timed out; nested exception is redis.clients.jedis.exceptions.JedisConnectionException: java.net.SocketTimeoutException: Read timed out
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
Caused by: redis.clients.jedis.exceptions.JedisConnectionException: java.net.SocketTimeoutException: Read timed out
at redis.clients.util.RedisInputStream.ensureFill(RedisInputStream.java:201)
at redis.clients.util.RedisInputStream.readByte(RedisInputStream.java:40)
at redis.clients.jedis.Protocol.process(Protocol.java:132)
at redis.clients.jedis.Protocol.read(Protocol.java:196)
at redis.clients.jedis.Connection.readProtocolWithCheckingBroken(Connection.java:288)
at redis.clients.jedis.Connection.getBinaryBulkReply(Connection.java:207)
at redis.clients.jedis.BinaryJedis.get(BinaryJedis.java:157)
at org.springframework.data.redis.connection.jedis.JedisConnection.get(JedisConnection.java:1120)
... 49 more
Caused by: java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:152)
at java.net.SocketInputStream.read(SocketInputStream.java:122)
at java.net.SocketInputStream.read(SocketInputStream.java:108)
at redis.clients.util.RedisInputStream.ensureFill(RedisInputStream.java:195)
... 56 more
我们都知道Redis是对内存进行操作,通常认知速度至少是毫秒级(特殊情况除外),为什么会出现如此现象呢?
通常来说出现Timeout报错,表明连接已经建立,但是获取命令返回结果超时
Redis server是单线程执行所有连接发送过来的命令的,也就是说不管并发中有多少个client在发送命令,Redis server都是单线程处理的,并按照默认的FIFO方式处理请求
而且当时从Proxy上记录的超长命令耗时的情况来看,时间点是完全吻合的
从调用过程可以推导出,导致耗时Timeout的三种可能 1. 从CVM到Redis Server这段网络造成时延 2. 命令执行过长(慢查询) 3. 排队耗时过长
我们一步一步来看
1.1 网络质量不好引起的 这个通过ping -t(云Redis禁ping了) 或者抓包是比较容易进行判别的。因为异常出现比较频繁,复现后抓包发现无明显异常,所以排除网络异常 1.2 流量负责过高,引起阻塞 从监控看到流量负载并不高,而且异常时间点11:20 11:50 12:19 等也不是高峰时间点
这个通过slowlog可以很快的进行判别。异常时间点,未抓到任何slowlog记录(配置为1ms) 要注意:slowlog记录的时间,不包括像是客户端响应、发送回复等 IO 操作,而单单是执行一个命令所耗费的时间
似乎只剩下这一个原因了,但是前面我们通过slowlog未有任何记录。那么问题来了,这个排队耗时从何而来呢?
会不会是Redis压力较大,但从QPS等来看压力并不高。而且异常时间点也不是峰值时间点
有经验的同学可能已经猜到另外一种可能,过期key淘汰导致命令阻塞
那么是不是这个原因呢?
通常我们通过expire、setex 等命令将一个key设置了过期时间后,这个key在到期后肯定不会马上被自动删除(废话),Redis目前是通过两种模式进行淘汰
这个数据库的key总量在600W左右。可以看到这个库的setex调用平均在4W/min,而active模式通常的消耗速度是0.6W/min。过期键的生产速度,远远高于一般的消耗速度。恰好又有大量的expire设置,在同一时间(1s内)有超量的key积压,导致redis会一直处理过期key,直到过期key低于总量的25%,诱发了阻塞
原创声明:本文系作者授权腾讯云开发者社区发表,未经许可,不得转载。
如有侵权,请联系 cloudcommunity@tencent.com 删除。
原创声明:本文系作者授权腾讯云开发者社区发表,未经许可,不得转载。
如有侵权,请联系 cloudcommunity@tencent.com 删除。