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

问题背景

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

以下是我的排查思路。

排查思路

查阅 redis 慢查询日志

既然是 redis 超时，首先想到的还是 对于 redis 的操作命令存在慢查询导致的。

redis 的慢查询阈值是 10ms,唯一的慢查询是备份时的 bgrewriteaof 语句，并不是业务命令，既然从慢查询很日志看不出端倪，那就从 redis 服务器本身查找问题，所以我又去看了 redis 服务机器的各项硬件指标。

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

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

既然服务端看不出毛病，那是不是客户端的问题，于是我又去检查了我们 ecs 服务器这边机器的情况。

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

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

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

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

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

那么有没有办法监控到 redis 的延迟呢?如何才能知道 redis 的命令慢不是因为执行慢，而是这个过程当中的其他流程慢导致的呢?

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

CONFIG SET latency-monitor-threshold 100

查阅延迟原因

latency latest

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

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

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

客户端发出去了命令，然后阻塞等待 redis 服务端读的结果，如果没有结果返回，就会触发读超时发生。在 go 里面代码是如何实现的。

我们用的 redis 客户端是 go-redis

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:303for !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 里进行了展示。

超时期间，grafana 里的 协程调度延迟只有几毫秒。而超时时间设置的 200ms，显然也不是协程调度延迟的问题。

用上终极武器-抓包

以上的思路都行不通了，所以只能用上终极武器，抓包。 看看触发 200ms 超时时 究竟是哪些包没有到达。因为只能在客户端测抓包，所以接下来的抓包文件都是客户端测的抓包。

很对时候抓包都是解决问题特别是网络问题的最终手段，你能通过抓包清楚的看到客户端，服务端在做什么事情。

为了百分百确认并且定位问题，我一共抓取了 3 个文件，首先来看下第一个文件。

6379 端口号是目的端口，也就是 redis 的端口，36846 是我客户端的端口。

从抓包文件中，发现 760054 号报文发生了超时重传，如果客户端发了包，但是服务端没有回应 ack 消息就会触发超时重传，重传之后，客户端也没有收到服务端的消息，并且可以看到发送挥手信号和前一个正常发送的包之间刚好是隔了差不多 200ms，而 200ms 正是客户端设置的超时时间，应用层触发超时后，将调用 close 方法关闭链接，所以在 760055 号包里 客户端发送了一个 fin 挥手信号代表客户端要关闭链接了。 客户端发送 fin 信号挥手之后呢，服务端才发来携带数据的 ack 消息，不过由于此时客户端已经处于要关闭状态，所以直接发送 rst 信号了。

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

接着来看第二个抓包文件。

抓包中出现大量 TCP Dup Ack 的消息，客户端一直在向端口为 6379 的服务端发送 ack 的序号为 13364573,代表客户端已经接收到服务端序号 13364573 之前的包了,然而服务端连续发送的包序号 seq 都大于了 13364573 ，所以客户端认为服务端序号 seq 是 13364573 的包丢了，所以随着服务端每一次发送消息过来，都告诉服务端，我应该接收序号是 13364573 开始的包，赶紧发送过来。

最终在 1777232 号包，客户端又一次发送了 TCP Dup Ack 消息，催促服务端赶紧把丢掉的包发过来，不过这次服务端连回应都不回应了，最终触发了客户端应用层 200ms 的超时时间，调用 close 方法关闭了连接。所以在 1778166 号包里，可以看到客户端发送 fin 挥手信号，1778166 号包的发送时间和 1777232 号包的发送时间正式相隔了 200ms。

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

再来看第三个抓包文件，第三个抓包文件是我将客户端超时时间设置为 500ms 后出现超时情况时抓到的。

首先看第一个红色箭头处，也就是 911752 号包，它被 wireshark 标记为 Tcp Previous segment not captured，表示这个包之前的包没有被捕获到，说明这个包 seq 序号之前的包存在丢包情况。发现它前一个包也就是 911751 号包也是服务端发来的包，并且 next seq 是 18428124，说明 911751 号包下一个包的 seq 应该是 18428124，但是 911752 的 seq 是 18429584，进一步说明 来自服务端的包序号在 18428124 到 18429584 之间的包存在丢包情况。

接着是客户端对 911751 号包的 ack 消息，说明序号是 18428124 之前的包已经全部接收到。然后接受到了 911754 号这个来自服务端的包，并且这包的开始 seq 序号是 18433964，而最近一次来自服务端的 911752 号包的 next seq 是 18432504，说明在 18432504 和 18433964 之间，也存在服务端的丢包情况，所以 911754 号包也被标记为了 Tcp Previous segment not captured。

接下来就是服务端重传包，客户端继续回应 Ack 的过程，但是这个过程直到 914025 号时就停止了，因为整个读取服务端响应的过程从开始读 到当前时间已经达到了应用层设置的 500ms，所以在应用层直接就关闭掉了这个链接了。

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

提工单，云服务商的排查支持

圆满解决