我又和 redis 超时杠上了

服务监控系列文章

服务监控系列视频

背景

经过上次 redis 超时排查https://xie.infoq.cn/article/ce0e922c1f3fc09ec94028e71，并联系云服务商解决之后，redis 超时的现象好了一阵子，但是最近又有超时现象报出，但与上次不同的是，这次超时的现象发生在业务高峰期，在简单看过服务器的各项指标以后，发现只有 cpu 的使用率在高峰期略高，我们是 8 核 cpu，高峰期能达到 90%的使用率，其余指标都相对正常。

但究竟是不是 cpu 占比高的问题导致 redis 超时的呢？还有待商榷，因为 cpu 调度程序慢本质上也是个概率性事件。

解决思路

略带侥幸的联系云服务商

有了上次的经验过后，我也是联系了云服务商那边也排查下是否还存在上次超时的原因，但其实还是有直觉，这次的原因和上次超时是不一样的（备注：上次超时是由于云服务商那边对集群的流量隔离做的不够好，导致其他企业机器流量影响到了我们的机器，且发生在业务低峰期），这次发生在业务高峰期。

果然，云服务商得出的结论也是之前出问题的机器以及迁移走了，并且他们也和我同时展开排查。

抓包分析

在 ecs 服务器上进行抓包，当出现超时时，关闭 tcpdump 进行分析。

tcpdump 漏包了？

在 dump 下抓包文件后，经过 wireshark 分析，并没有发现丢包信息，想着应该是 tcpdump 漏包了。

tcpdump 出现漏包的情况

[webserver@hw-sg1-test-0001 ~]$ sudo tcpdump -i eth0 tcp  port 6379   -w p.cap -W 2 -G 3600 -C 2000tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 262144 bytes

可以看到默认的抓包大小 262144 bytes，在业务高峰期如果每个包最大长度都在这个值，很可能就导致缓冲区满了，而之前一次抓包分析为什么就没有这个问题呢，因为那是在业务低峰期，tcpdump 丢包概率比较小。

sudo tcpdump -i eth0 tcp  port 6379   -w p5.cap -W 2 -G 3600 -C 2000tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 262144 bytes^C147940 packets captured468554 packets received by filter318544 packets dropped by kernel

packets dropped by kernel 说明 tcpdump 丢弃了某些包，因为 tcpdump 在处理包时，是先将包放到一个缓冲区进行分析，当缓冲区满的时候会直接进行丢弃，这样导致我在用 wireshark 分析包的时候，就会出现有些包找不到的情况。

在缩小抓取的包大小和去掉域名解析后，不再漏包了。

[webserver@hw-sg1-backend-0003 ~]$ sudo tcpdump -i eth0 tcp  port 6379   -w p5.cap -W 2 -G 3600 -C 2000 -n -s 1520tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 1520 bytes^C21334 packets captured21454 packets received by filter0 packets dropped by kernel

抓包分析超时情况

redis 客户端超时时间设置的 200ms，可以看到 2894687 号包是 redis 服务器发送给客户端的包，然后 2897927 是客户端发送给 redis 服务端的 rst，正常情况客户端收到 redis 服务端的 psh 信号的包应该会回复一个 ack 的，但是客户端却在 200ms 以后回复了一个 rst，说明了什么问题？

我们的客户端是 golang 写的，可以想到的情况是，客户端程序在读取包过程协程会有切换上下文操作，当客户端发现有可读包时并切回 go 协程的时候，会首先判断当前读操作是否超时，如果超时，则直接调用 close 方法关闭连接了。

那么 close 方法是发送 rst 信号吗，正常不应该是 fin 信号？非也，close 方法如果关闭的时候，连接读缓冲区的数据还有未被应用程序读取的话，那么此时 close 方法的调用会发送 rst 信号。

可见，问题的确是出在客户端了，并且看上去像是客户端来不及读取服务端的消息。看到这里，其实我心里已经百分之八九十确定是 cpu 的使用率达到瓶颈了。

云服务商来信了

在分析到上一个步骤的时候，云服务商告诉我，他们知道原因了，是 ecs 服务的磁盘吞吐量达到瞬时上线，说故障点是和超时的故障点是吻合的。

我知道这个后，第一时间的疑惑是，为啥磁盘吞吐会影响到网络传输，云服务商给的解释是磁盘吞吐达到瞬时上线后，对服务整体是有影响的，我又看了下 ecs 的监控图标，发现监控图标显示的磁盘吞吐远远没有云服务商提到的那么多。

尽管云服务商坚持是磁盘 iops 达到了上限，但还是不能说服我 磁盘的 iops 瞬时上限会那么大影响到网络传输。

于是有了接下来第二天的抓包分析。

第二天的抓包分析

基于对昨天的分析，我怀疑到了 cpu 头上，如果 cpu 切换进程缓慢，协程调度缓慢，那么的确是有可能发生超时的。由于目前的监控缺少对协程调度延迟的监控，所以决定加上这一指标。

golang1.17 后 runtime 包提供了协程调度延迟的直方图统计信息,而 go prometheus 的 client 其实以已经支持将这个信息转换为 prometheus 内置的指标类型，metric 名称是 go_sched_latencies_seconds，而我们之前试用 prometheus 的 client 包注册的 collector 是兼容到 go1.16 以及之前的版本，所以没有当改用到最新的 collector 后，client 如期返回了 go_sched_latencies_seconds 直方图信息。

将这个信息展示在 grafana 里。于是有了第二天协程调度延迟的信息。p999 在业务高峰期间达到了 100ms，也是与超时时间吻合的。协程调度延迟指的是协程变为可运行状态后到被真正执行这段时间等待被调度的时间，这里都高达 100ms 了，如果加上 cpu 线程，进程切换上下文时间，很有可能是超过了 redis client 端设置的 200ms 超时上限。

为了排除掉是磁盘原因引起的超时。我在 7 点又进行了抓包分析，发现和昨天抓到包的情况是一致的，客户端最后来不及回应服务端的包最后发送 rst 了。

然后看了下此时机器磁盘吞吐情况，发现图中箭头处也处于高峰期，但是磁盘吞吐量并未上去，而升上去的点正是抓包带来的，怀疑是抓包写入文件导致磁盘吞吐量涨上去了。于是又问了服务商要磁盘达到瞬时峰值的日志。

发现报瞬时峰值的日志也和抓包时间吻合，所以已经确认磁盘吞吐达到上限是抓包导致的，网络超时是和磁盘吞吐无关的，反而应该是 cpu 使用率达到上限了，虽然没有 100%，也是 8 核，但毕竟 cpu 某个核达到上限是概率性事件，而对于 redis 这种时延敏感性应用，一但发生，那么超时是有可能的。

完美解决

于是，在业务低峰期将我们三台 ecs 服务进行了 cpu 配置提升，提升后效果很明显，超时在高峰期不见了，协程调度延迟也大大减少。

总结

1，对于抓包分析，还是疏忽了，加上包限制大小，能很好的防止 tcpdump 抓包时丢包的情况。2，对于任何第三方的说法要有自己的判断力，像这次如果中途去将磁盘扩容显然是不能解决问题的。3，性能问题分析真是像一个侦探破案的过程，不断列出证据，不断排除掉干扰因素，不断论证的过程也是性能分析的魅力所在吧，就像这次看到 cpu 的确比较高了，但是究竟是不是客户端问题呢？我又抓包论证了的确是客户端问题，那究竟是不是协程调度问题呢？我又列出协程调度延迟。