Consul 健康检查异常、丢包与 Linux 网络问题排查

775 阅读9分钟

一、问题现场

业务上反馈部分应用软件有几分钟频繁发生故障,甚至影响到了用户登录。线上问题无小事,二话不说,立马投入问题排查中。(不是系统开发者,这次依然是从性能分析视角来看待系统。)

这是一个集群超过八十台服务器的软件系统,除 GPU 外全部部署在中心云虚拟机中,并运行在运营商的专用网络里,所有物理机使用专线连接。系统也是一个庞大的微服务体系,所有组件的注册与发现都要经过注册中心,包括登录组件、门户组件、用户权限认证组件、运营日志组件和各种应用组件等。

经过历史故障记录分析,可以发现服务中断固定发生在最近每天上午的十点多的几分钟内,也是处在每天业务开始上升的高峰期中,但是每次都没有经过任何处置就会自行恢复。因为问题发生时间短,同时缺少底层的自动监控,前几次都没有抓到问题现场,事后观察系统都是稳定如一。

下面就来回溯下问题排查过程,逐步进行,逐层深入,通过寻找规律蹲守问题现场最终找到根因并解决。

二、问题排查

1、维护记录回溯

得益于良好的监控系统设计,系统中所有组件的安装、卸载、补丁维护等操作都会被记录。通过查看故障组件的维护记录可知,近期并没有对这些组件做维护,先排除了人为干扰的可能性。

如果出现问题也好办,先回滚,再查问题。线上环境找变更优先于找 bug,bug 不是在线上查找的,恢复业务高于一切。

2、应用组件日志检查

接着来看下发生故障的组件日志,得益于部门推行的组件打包与部署规范设计,所有组件都按照相同的目录结构打包,可以按照相同的路径快速找到组件运行日志。

从故障发生时间段来看,应用组件有大量服务调用报错:

java.lang.RuntimeException: com.netflix.client.ClientException: Load balancer does not have available server for client: xxx

和调用链日志相吻合,都是在服务发现这块出现了问题,目标转移到了注册中心 Consul 上。

3、Consul 日志检查

从 Consul 控制台可以找到许多健康检查失败掉线的服务,进一步查找 Consul 日志,发现有大量 context deadline exceeded (Client.Timeout exceeded while awaiting headers) 异常记录,和应用发生问题时间重合:

agent: Check "service:xxx" HTTP request failed: Get "http://xxx/health": context deadline exceeded (Client.Timeout exceeded while awaiting headers)

统计下当天的异常数量:

cat consul.log | grep "context deadline exceeded (Client.Timeout exceeded while awaiting headers)" | wc -l

好家伙,几分钟内就发生了 13575 次。

看样子是大量应用组件健康检查连接超时,导致服务不在线,FeignClient 等 HTTP 客户端调用失败。因为波及了众多组件,怀疑是 Consul 出现故障。

4、缺陷库检索

按照该系统稳定性维护经验,应用出现问题先自顶向下排查。因为 Consul 组件也是基于开源版本为了满足技术架构要求做了二次开发,首先查下是不是 Consul 已知 bug,于是翻一下 Consul 的 Issues。

可以看到 context deadline exceeded 相关的问题全部都是 closed,要么是这种没有复现的,要么是这种网络延迟大或者抖动多不稳定的问题造成的,后者居多。

公司的缺陷库也没有找到历史案例,可以先暂时排除应用故障,转向系统资源问题排查。

5、网络延迟测试

抓到一次服务可能有故障的时间段,在服务不可用组件服务器和 Consul 服务器之间 ping 一下,发现了问题:

166 packets transmitted, 105 received, 36% packet loss, time 165037ms
rtt min/avg/max/mdev = 0.129/0.290/2.849/0.410 ms

网络延迟小,跳数也稳定,但是存在丢包现象,也就是 ICMP 报文有序号间隔。

这么严重的网络丢包没有监控预警,看样子是要手动来排查了,接下来就按照 Linux 网络协议栈来逐一分析。

三、问题分析

1、Ring Buffer 溢出检查

查看网卡信息:

ifconfig
eth0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        ......
        RX packets 47500287650  bytes 61576875354965 (56.0 TiB)
        RX errors 0  dropped 223  overruns 0  frame 0
        TX packets 46729289243  bytes 91481437885177 (83.2 TiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

再查看网卡的 ring buffer:

ethtool -g eth0
Ring parameters for eth0:
Pre-set maximums:
RX:             256
RX Mini:        0
RX Jumbo:       0
TX:             256
Current hardware settings:
RX:             256
RX Mini:        0
RX Jumbo:       0
TX:             256

ring buffer 收发队列都已经设置成网卡支持的最大值,overruns 为 0 说明不存在 ring buffer 满而丢弃的包,也就是数据正常进入 ring buffer,可以确定物理链路和网卡驱动正常,没有发生网络断线、拥塞等问题。

而 dropped 不为 0 说明有丢包,可以继续往上层排查。

检查网卡驱动数据统计还可以通过 /proc 或者 /sys 来完成,效果都是一样的,比如:

cat /proc/net/dev

或者:

cd /sys/class/net/eth0/statistics
grep . * | grep rx

2、TCP 连接队列溢出检查

监视下端口连接:

watch 'netstat -s | grep overflowed'

有打印结果,说明有 TCP 全连接队列溢出了:

5455104 times the listen queue of a socket overflowed

检查一下系统配置 /proc/sys/net/ipv4/tcp_abort_on_overflow,发现是 0,也就是代表着全连接队列满了之后数据将会被丢弃。如果是 1 的话,客户端连接将重新开始握手,出现 connection reset by peer 或 timeout 异常。

同时检查一下 /etc/sysctl.conf 中的内核参数 tcp_syncookies,发现已经是 1,说明不存在半连接队列满的问题。

再检查一下 TCP 全连接队列配置项,不同 Linux 发行版本会有不同,比如 CentOS 默认值是 128:

sysctl net.core.somaxconn

结合 LISTEN 状态下的端口连接数比较一下:

ss -lnt

因为每个端口允许的最大 TCP 全连接队列大小是 min(backlog, somaxconn),backlog 就是应用服务传入的值,比如 Nginx 默认 511,Redis 默认 511,Tomcat 默认 100。两者取最小值,就知道 TCP 最大全连接数了。

3、抓包验证

由于工具的差异性,排查系统问题最好采用交叉验证的方式。

tcpdump 抓包分析下网络情况,看到出现了大量 TCP Dup ACK 异常,可以验证上一步的判断。

tcpdump.png

至于是不是还有其他原因导致还不确定,按照网络协议栈逐层分析即可,可以先解决眼下问题。

四、修复建议

1、应用组件

服务调用,FeignClient 可以使用 ErrorDecoder 或者 Fallback 来处理异常,避免异常逃逸。

2、Ring Buffer 队列加长

可以通过调大增加缓冲队列长度,比如将 eth0 网卡的发送队列调整到最大值(Pre-set maximums):

ethtool -G eth0 rx 256

这里已经没有调整余地了,再看下其他方面。

3、网卡多队列调优

如果网卡支持 RSS(Receive Side Scaling)就可以通过增加队列使得多个 CPU 来接收数据,检查方法是:

ethtool -l eth0

Pre-set maximums Combined 大于 1,可以将 Current hardware settings Combined 相应调大:

ethtool -L eth0 combined 32

这里网卡也不支持多队列,继续看其他部分。

4、调大 TCP 全连接队列

调整内核参数最大全连接队列长度,并立即生效:

echo 1024 > /proc/sys/net/core/somaxconn
sysctl -p

还有一种不受操作系统重启影响的方式是添加到 /etc/sysctl.conf 中:

net.core.somaxconn = 1024
sysctl -p

检查是否生效,结果打印为刚刚修改的过的值就对了:

sysctl net.core.somaxconn

五、结果验证

1、模拟 TCP 全连接队列溢出

从上面已经分析除了当前的问题原因,就近解决,先验证下 TCP 全连接队列溢出。

这里使用两台虚拟机,一台用作服务端,比如部署一个 Nginx 服务,并主动降低 TCP 全连接队列大小:

echo 'net.core.somaxconn = 10' > /etc/sysctl.conf
sysctl -p

Nginx 默认 TCP 最大全连接数是 511,这里突出模拟效果配置了很低的 somaxconn,最后得到的连接数就是 10。

另一台用作客户端,比如使用 wrk(需要下载源码,然后 make 编译安装),一个用于 HTTP 性能测试工具,主动发起连接测试:

./wrk -t 100 -c 10000 -d 60s http://192.168.0.3:8888/

在服务端监听端口请求异常:

netstat -s | grep listen
21914 times the listen queue of a socket overflowed

可以看到压测之前没有打印,压测之后没一会儿就有两万多条请求因为队列满而丢弃了。

打印服务端被压测端口:

ss -lnt | grep 8888

可以看到第二列 Recv-Q 的值只比第三列 Send-Q 的值大一,这是连接占满的表现,也就是 LISTEN 状态下当前的连接数达到了最大连接数(内核实现逻辑是当前最大值就是连接最大值 +1):

LISTEN     11      10         :::8888                    :::*    

客户端的打印结果是这样的,出现大量 timeout 也是连接被丢弃的表现:

Running 1m test @ http://192.168.0.3:8888/
  100 threads and 10000 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   181.02ms  357.43ms   2.00s    85.59%
    Req/Sec   253.77    134.31     2.34k    71.69%
  1496715 requests in 1.00m, 523.79MB read
  Socket errors: connect 0, read 0, write 0, timeout 26204
Requests/sec:  24903.37
Transfer/sec:      8.72MB

停止压测,服务端的异常次数也可能有缓慢增长,这取决于服务器上是否有其他网络连接。然后修改 somaxconn 回默认值,发现异常次数不再增长了。说明验证成功。

2、问题回顾

同样,线上问题也就如此解决掉了,也没有需要进一步向上排查。最后解决方法很简单,适当调大系统 TCP 最大全连接数,要么是 somaxconn,要么是应用组件的 backlog。

丢包过程排查经历了 Linux 网络协议栈,还好有各种统计指标和工具可以方便跟踪。再之前,系统资源包括 CPU、内存、网络 IO 等没有发生大的抖动或超限时谁能第一时间想到是因为丢包引起的呢。

线上问题无小事,业务压力也是一种软件系统迭代的驱动力,面向用户友好,也要面向运维友好,缺少诸多面向生产环境监测跟踪的设计就容易给故障问题带来恢复隐患。