redis超时问题排查

通过查询线上redis的耗时,发现已经严重超出预期了,竟然有10%的耗时超过了3ms。作为redis,每个请求都应该在1ms以下。10ms、20ms已经严重影响用户体验了。接下来我来一步一步追踪我们的redis导致怎么了?该怎么解决这个问题?

一、查询问题思路

根据这个现象,一次操作,说明在业务到组件+组件到redis都有可能产生延迟,所以我们的排查步骤应该是从上到下的每个步骤

二、proxy慢日志查询

通过在业务日志中提供的一个慢查询的key。我们去redisproxy的慢日志中grep,发现是有慢日志的,说明步骤1排除,业务到proxy之间是没有延迟的。

2.1、解读:

根据慢日志,可以看到这个请求anti: alipayip:182.46.167.176 key的操作,一共使用了25.918ms。其中达到proxy的时间戳为1496289351, 559282,发往redis的时间戳为1496289351, 559291,从redis接到结果的时间戳为1496289351, 585080,返回给业务的时间戳为1496289351, 585200.

2.2、分析:

经过时间戳分析:

  • proxy将请求处理发给redis过程用了0.009ms,
  • redis处理过程+中间网络一共用了25.789ms,
  • proxy将请求发回给业务用了0.12ms。

2.3、总结

  • 业务到redisproxy的网络延迟没有问题
  • proxy处理消息延迟没有问题
  • 问题出在redis和proxy到redis中间网络上

三、lantency主从延迟分析

3.1、通过latency命令,在proxy机器上分别去查看redis的主从机器延迟情况:

3.2、然后在redis主库通过latency去查看机器延迟情况:

3.3、解读

  • proxy到主库最大的延时是28ms
  • proxy到从库最大的延时是1ms
  • 主库自身latency发现最大的延时是28ms

3.3、分析

  • 只有主库才会出现延时的现象,从库是不会出现的
  • 那些超时的请求,应该都是打到主库了
  • 主库不仅有写请求,同时也有读请求
  • 主库自身latenxy最大的延时跟proxy到redis的最大延时一样->之间的网络没问题

3.4、总结

  • proxy到redis之间的网络层没有问题
  • 问题出在主库的redis中。

四、主库redis慢日志查询

既然排除了其他所有的步骤,只剩下主库redis处理有问题。那么我们首先就应该查询redis的慢日志呀!

4.1、解读

通过慢日志查询,发现超过10ms的一共才3个,并且都没有关于业务的key。接着把10ms调整为1ms,发现同样也没有关于业务的key。

4.2、结论

  • 业务的key->value并没有不合理的情况
  • redis并没有因为文件事件不合理而产生阻塞

五、问题追查到这里,似乎问题已经被追死了,感觉4个可能出现问题的地方,都没有出现问题呀???处理到这里,不得不去恶补一下redis的底层知识啦。

5.1、恶补知识

  • 1、redis的时间日志,其实是从接收到事件处理开始记录。
  • 2、而我们知道redis底层使用的是epoll模型,接收到socket后,会发送给一个文件事件分派器
  • 3、epoll模型对待有消息的套接字是使用一个队列记录的。

5.2、猜想

  • 套接字已经到了redis队列,redis还没有来得及处理。
  • 可能是因为业务访问量太大,导致后面请求在队列等待
  • 主从同步,大量写流量导致redis资源消耗严重

六、主库与其他主库对比

找一个写操作差不多的、访问量差不多的集群主库,同一时间查看延时情况

6.1、分析

通过查看,写入量差不多的两个库,反作弊的库明显耗时高,另一个库无耗时。

6.2、结论

  • 排查业务访问大,导致后面请求等待的问题
  • 排除主从同步导致队列等待的问题

七、看见输光:latency与monitor配合查询

7.1、使用latency开始redis检测延时,机制为每10ms给redis发送ping的请求,get到结果后会记录时间。检测的同时,开发monitor,打印主库上所有的请求。通过分析ping请求,查看是否有中断、延时的过程。

7.2、解读

通过上述步骤,我们发现,

  • ping的请求是每10ms一次的,
  • 经常出现30ms左右的空档期
  • 出现30ms的空档期周期是100ms

7.3、结论

  • redis有一个以100ms为周期的机制导致这次事件的发生

八、redis时间事件

8.1、redis架构

我们知道redis包含文件事件外,还包含时间事件。我们的所有请求,都属于文件时间。而redis是属于单线程单进程,所以当你的redis正在处理时间事件的时候,文件事件是属于阻塞状态。

8.2、而redis的时间函数serverCron干了什么?

  • 更新服务器的各类统计信息,比如时间、内存占用、数据库占用情况等
  • 清理数据库中的过期键值对
  • 对不合理的数据库进行大小调整
  • 关闭和清理连接失效的客户端
  • 尝试进行 AOF 或 RDB 持久化操作
  • 如果服务器是主节点的话,对附属节点进行定期同步
  • 如果处于集群模式的话,对集群进行定期同步和连接测试

8.3、时间都花哪里了?

  • 空档期一共有30ms。
  • redis定期清理过期数据大概占了25ms。
  • 剩下的工作大概占了5ms。

九、验证猜想

我们知道redis主库会定期轮询一次,获取所有过期的key,然后删除,并发操作给从库进行删除。而这个轮询的操作,官方默认值为100ms,配置参数为hz 10。
每次定期删除必须在一定时间内执行,该时间为time_limit = 1000*25/hz/100 。默认为25ms。我们发现time_limit与hz成反比。

9.1、实验:

我们试着将hz参数调整,先调整为20,再调整为50,实验结果如下:

9.2、结果

经过调整hz参数,延迟明显降下来了。此时业务从每秒2个高延迟访问,变成每3分钟1个,出现延迟频率降低了100倍。
hz的具体意义,定期删除过期数据的具体原理,可以查看前面的博客,传送门

十、解决方案

10.1、把主库的读流量去掉(否决)

主库流量不能去掉,因为一单主库宕机,所有的流量将打到新的主库上,而新的主库却没有读流量,对服务冲击太大。为什么主库必须有读流量

10.2、把hz调大

通过把hz调大后,相当于缩短了每次的延时时间。增加了删除定期数据的频率。

  • 确实可以提升操作的性能,不会轻易的出现超过10ms的操作了。
  • 但是会增加cpu的消耗,会花费更多时间在处理时间事件上。所以不应该是最终的解决方案。
    比如:hz变成50,查询线上机器请求redis耗时top10:

10.3、定时删除过期数据

  • 如果在redis的ops少的时候,比如凌晨,这个时候通过脚本把redis过期数据进行删除,就可以杜绝这种问题。
  • 但是需要保存过期数据的key,而我们一般是不会再去保存这个数据的。

10.4、增加redis分片,减少每个分片的数据内存

通过增加redis分片,让每个分片承担的数据量更少,这样过期的数据删除时间会更短。这个才是最终的解决方案!为什么redis内存不宜过大

文章目录
  1. 1. 一、查询问题思路
  2. 2. 二、proxy慢日志查询
    1. 2.0.1. 2.1、解读:
    2. 2.0.2. 2.2、分析:
    3. 2.0.3. 2.3、总结
  • 3. 三、lantency主从延迟分析
    1. 3.0.1. 3.1、通过latency命令,在proxy机器上分别去查看redis的主从机器延迟情况:
    2. 3.0.2. 3.2、然后在redis主库通过latency去查看机器延迟情况:
    3. 3.0.3. 3.3、解读
    4. 3.0.4. 3.3、分析
    5. 3.0.5. 3.4、总结
  • 4. 四、主库redis慢日志查询
    1. 4.0.1. 4.1、解读
    2. 4.0.2. 4.2、结论
  • 5. 五、问题追查到这里,似乎问题已经被追死了,感觉4个可能出现问题的地方,都没有出现问题呀???处理到这里,不得不去恶补一下redis的底层知识啦。
    1. 5.0.1. 5.1、恶补知识
    2. 5.0.2. 5.2、猜想
  • 6. 六、主库与其他主库对比
    1. 6.0.1. 6.1、分析
    2. 6.0.2. 6.2、结论
  • 7. 七、看见输光:latency与monitor配合查询
    1. 7.0.1. 7.1、使用latency开始redis检测延时,机制为每10ms给redis发送ping的请求,get到结果后会记录时间。检测的同时,开发monitor,打印主库上所有的请求。通过分析ping请求,查看是否有中断、延时的过程。
    2. 7.0.2. 7.2、解读
    3. 7.0.3. 7.3、结论
  • 8. 八、redis时间事件
    1. 8.0.1. 8.1、redis架构
    2. 8.0.2. 8.2、而redis的时间函数serverCron干了什么?
    3. 8.0.3. 8.3、时间都花哪里了?
  • 9. 九、验证猜想
    1. 9.0.1. 9.1、实验:
    2. 9.0.2. 9.2、结果
  • 10. 十、解决方案
    1. 10.0.1. 10.1、把主库的读流量去掉(否决)
    2. 10.0.2. 10.2、把hz调大
    3. 10.0.3. 10.3、定时删除过期数据
    4. 10.0.4. 10.4、增加redis分片,减少每个分片的数据内存
  • ,