Login
网站首页 > 文章中心 > 其它

太坑了吧!一次某某云上的redis读超时排查经历

作者:小编 更新时间:2023-09-14 15:04:47 浏览量:421人看过

一次排查某某云上的redis读超时经历

一次排查某某云上的redis读超时经历

性能排查,服务监控方面的知识往往涉及量广且比较零散,如何较为系统化的分析和解决问题,建立其对性能排查,性能优化的思路,我将在这个系列里给出我的答案.

问题背景

最近一两天线上老是偶现的redis读超时报警,并且是业务低峰期间,甚是不解,于是开始着手排查.

以下是我的排查思路.

排查思路

查阅 redis 慢查询日志

太坑了吧!一次某某云上的redis读超时排查经历

检查 报警期间 redis 各项负载指标

看了下各项监控指标,cpu,内存,qps等等,毫无意外的正常.(这里就不放图了,应为太正常了,分析意义不大)

检查报警期间 ecs服务器的各项指标数据

cpu,内存,带宽等等也是正常且处于较低水平.

排查到这里,重新思考慢查询日志究竟是什么?

慢查询记录的真的是redis命令执行的所有时间吗?redis命令完整的执行过程究竟是怎样的?慢查询日志仅仅是记录了命令的执行时间,而整个redis命令的生命周期是这样.


客户端命令发送->redis服务器接收到命令,放入队列排队执行->命令执行->返回给客户端结果


redis 提供了监控延迟的工具开启延迟,设置延迟阀值


CONFIG SET latency-monitor-threshold 100


查阅延迟原因


latency latest


但是这个工具真正实践起来的效果并不能让我满意,因为似乎他并不能把网络因素考虑其中,实践起来的效果它应该是只能将命令执行过程中可能导致延迟的原因分析出来,但是执行前以及执行后的命令生命周期的阶段并没有考虑进去.

当我开启这个工具监控线上redis情况,当又有读超时出现时,latency latest 并没有返回任何延迟异常.

再思考究竟读超时是个什么问题?


func (c *baseClient) pipelineProcessCmds(cn *pool.Conn, cmds []Cmder) (bool, error) {
err := cn.WithWriter(c.opt.WriteTimeout, func(wr *proto.Writer) error {
return writeCmd(wr, cmds...)
})
if err != nil {
setCmdsErr(cmds, err)
return true, err
}
// 看到将读取操作用WithReader装饰了一下
err = cn.WithReader(c.opt.ReadTimeout, func(rd *proto.Reader) error {
return pipelineReadCmds(rd, cmds)
})
return true, err
}


读取redis服务端响应的方法 是用cn.WithReader进行了装饰.


// 读取之前设置了超时时间
func (cn *Conn) WithReader(timeout time.Duration, fn func(rd *proto.Reader) error) error {
_ = cn.setReadTimeout(timeout)
return fn(cn.rd)
}


而cn.WithReader 里,首先便是设置此次读取的超时时间.如果在规定的超时时间内,需要读取的结果没有全部返回也会导致读超时的发生,那么会不会是由于返回结果过多导致读取耗时验证呢?

具体的分析了下报警出错的命令,有些命令比如set命令不需要返回结果都有超时的情况,所以排除掉了返回结果过大的问题.

再次深入思考golang 里的读超时触发过程

go协程在碰到网络读取时,协程会挂起,等待网络包到达后,由go runtime唤醒协程,然后协程继续进行读取操作,当唤醒时会检查超时时间,如果到达了超时限制,那么将直接报读超时错误.(有机会可以详细分析下golang的netpoll源码) 源码如下,


src/runtime/netpoll.go:303
for !netpollblock(pd, int32(mode), false) {
errcode = netpollcheckerr(pd, int32(mode))
if errcode != pollNoError {
return errcode
}
// Can happen if timeout has fired and unblocked us,
// but before we had a chance to run, timeout has been reset.
// Pretend it has not happened and retry.
}


netpollblock 不阻塞协程时,首先执行了netpollcheckerr,netpollcheckerr检查是否有超时情况发生.

从唤醒到协程被调度执行的这个时间称为协程的调度延迟,如果这个延迟过高,那么是有可能发生读超时的.于是我又看了go进程中协程的调度延迟,在golang里 内置了一个/sched/latencies:seconds 指标,代表协程调度延迟,目前的prometheus client 已经对这个指标进行了兼容,所以我们是直接利用它 将延迟耗时在grafana里进行了展示.

用上终极武器-抓包

太坑了吧!一次某某云上的redis读超时排查经历

整个发包和接包流程可以用下面的流程图来展示.

太坑了吧!一次某某云上的redis读超时排查经历

太坑了吧!一次某某云上的redis读超时排查经历

太坑了吧!一次某某云上的redis读超时排查经历

太坑了吧!一次某某云上的redis读超时排查经历

看到现在,我有了充足的理由相信,是云服务提供商那边的问题,中间由于网络丢包的原因,且延迟较大导致了redis的读超时.拿着这些证据也说服了他们,并最终圆满解决.

太坑了吧!一次某某云上的redis读超时排查经历

圆满解决

以上就是土嘎嘎小编为大家整理的太坑了吧!一次某某云上的redis读超时排查经历相关主题介绍,如果您觉得小编更新的文章只要能对粉丝们有用,就是我们最大的鼓励和动力,不要忘记讲本站分享给您身边的朋友哦!!

版权声明:倡导尊重与保护知识产权。未经许可,任何人不得复制、转载、或以其他方式使用本站《原创》内容,违者将追究其法律责任。本站文章内容,部分图片来源于网络,如有侵权,请联系我们修改或者删除处理。

编辑推荐

热门文章