Redis一次Read time out引发的过期key删除策略分析

原创

elontian田凌翔

修改于 2019-11-12 11:06:08

5.7K3

修改于 2019-11-12 11:06:08

文章被收录于专栏：elon带你死磕技术elon带你死磕技术

背景

一台业务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

本地超时的配置是1s

我们都知道Redis是对内存进行操作，通常认知速度至少是毫秒级（特殊情况除外），为什么会出现如此现象呢？

分析

腾讯云上从CVM请求Redis服务器，完整的请求过程如下

通常来说出现Timeout报错，表明连接已经建立，但是获取命令返回结果超时

Redis server是单线程执行所有连接发送过来的命令的，也就是说不管并发中有多少个client在发送命令，Redis server都是单线程处理的，并按照默认的FIFO方式处理请求

而且当时从Proxy上记录的超长命令耗时的情况来看，时间点是完全吻合的

从调用过程可以推导出，导致耗时Timeout的三种可能 1. 从CVM到Redis Server这段网络造成时延 2. 命令执行过长（慢查询） 3. 排队耗时过长

我们一步一步来看

1. 从CVM到Redis Server这段网络造成时延

1.1 网络质量不好引起的这个通过ping -t（云Redis禁ping了）或者抓包是比较容易进行判别的。因为异常出现比较频繁，复现后抓包发现无明显异常，所以排除网络异常 1.2 流量负责过高，引起阻塞从监控看到流量负载并不高，而且异常时间点11:20 11:50 12:19 等也不是高峰时间点

2. 命令执行过长

这个通过slowlog可以很快的进行判别。异常时间点，未抓到任何slowlog记录（配置为1ms） 要注意：slowlog记录的时间，不包括像是客户端响应、发送回复等 IO 操作，而单单是执行一个命令所耗费的时间

3. 排队耗时过长

似乎只剩下这一个原因了，但是前面我们通过slowlog未有任何记录。那么问题来了，这个排队耗时从何而来呢？

会不会是Redis压力较大，但从QPS等来看压力并不高。而且异常时间点也不是峰值时间点

有经验的同学可能已经猜到另外一种可能，过期key淘汰导致命令阻塞

那么是不是这个原因呢？

Redis的过期key删除实现策略

通常我们通过expire、setex 等命令将一个key设置了过期时间后，这个key在到期后肯定不会马上被自动删除（废话），Redis目前是通过两种模式进行淘汰

lazy策略（定义在db.c/expireIfNeeded）：每次从键空间中获取键时，都检查取得的键是否过期，如果过期的话，就删除该键；如果没有过期，就返回该键。这种方式对CPU是友好的，因为只会在必须执行的时候执行。但是对内存不友好
active策略（定义在redis.c/activeExpireCycle）：每隔一段时间，程序就对数据库进行一次检查，删除里面的过期键。这个周期通常是100毫秒（10次/s），每次进行如下操作： a. 从数据库的expires字典中，根据 REDIS_EXPIRELOOKUPS_PER_CRON 的值（一般这个值默认为10），查找固定数量的key。然后删除其中过期的键 b. 假如过期键总数超过总量的25%，则一直重复a过程，直到低于25%。通常来说这种模式是自适应的，只有当积压了超量的key，才会导致redis一直阻塞直到过期key的比例下降到25%以下

做个粗略的估算，侧面验证一下

这个数据库的key总量在600W左右。可以看到这个库的setex调用平均在4W/min，而active模式通常的消耗速度是0.6W/min。过期键的生产速度，远远高于一般的消耗速度。恰好又有大量的expire设置，在同一时间（1s内）有超量的key积压，导致redis会一直处理过期key，直到过期key低于总量的25%，诱发了阻塞