网络问题排查

在遇到服务网络超时时,一般会通过 监控平台、Metric、Trace、ErrorLog来观察系统状态;

可能会看到不少可疑现象,比如:监控上延迟变高、错误数变多、日志里耗时变长、线程Block、GC频率变高、CPU抖动较严重等等,

那么在这些现象中,哪些是表象,哪些是诱因,哪个是根本原因呢?如果不能定位根本原因,而是聚焦于某个表象进行优化,优化后往往发现效果并不明显;

在走过一些解决网络问题的弯路后,本系列的文章会尝试总结在面对网络问题时,我们需要哪些思考问题的思维方法与分析定位问题的视角;

但是实际排查时,难度会比较大。因为网络可能会涉及前端域名解析网关负载均衡业务服务等。

在分布式场景下,针对网络问题,一般会先着手分析网络链路,通过分析链路的阻塞情况与耗时分布,从而定位到某个模块、某些模块交互间的问题;然后在模块内部依据资源使用情况进行技术方案等方面的调整。因此网络问题的分析阶段分为链路分析与模块分析这两个阶段:(1) 链路分析; (2) 模块分析;


(1) 调用链路分析

微信小程序/web/Android/IOS -> 域名解析 -> 网关 -> 路由 -> 服务 -> 存储

调用链路

 实际的调用链路会比这个更详细、更复杂一些,实际的调用链路大概如下:

前端 -> 域名解析 -> 外网网关 -> 机房 -> 内网网关 -> 负载均衡 -> 服务发现 -> docker容器 -> side-car -> 业务网关业务服务web容器业务服务


(1.1) 域名解析

域名解析(Domain Name System)是把域名解析成IP地址,让人们通过域名即可访问到您网站的一种服务。
比如把 weikeqin.com 解析成 76.76.21.21

域名的解析工作由DNS服务器完成。解析流程如下
域名解析流程

DNS缺点:在做出调度策略改变以后,由于DNS各级节点的缓存并不会及时的在客户端生效


(1.2) 网关

GW 全称Gateway。是一套实现四层网络(tcp udp)统一接入的集群,支持自动负载均衡的系统。GW具有可靠性高,扩展性强,性能高,抗攻击等特点。

四层负载均衡通过LVS(Linux virtual server)和Nginx组成的。

(1.2.1) 转发模式

四层负载均衡做的主要工作是转发,那就存在一个转发模式的问题,目前主要有四种转发模式:DR模式、NAT模式、TUNNEL模式、FULLNAT模式。
转发模式

(1.2.2) FULLNAT模式

FULLNAT模式是在NAT模式的基础上做一次源地址转换(即SNAT),做SNAT的好处是可以让应答流量经过正常的三层路由回到负载均衡上,这样负载均衡就不需要以网关的形式存在于网络中了,对网络环境要求比较低,缺点是由于做了SNAT,应用服务器会丢失客户端的真实IP地址。
FULLNAT模式

(1.2.3) 四层负载的原理

四层负载的原理是替换client的数据包的IP包头和tcp+udp包头内容后把数据包转发给rs,gw不和rs建立链接,真实的tcp udp链接协商还是client↔server

四元组是:源IP地址、源端口、目的IP地址、目的端口
五元组是:源IP地址、源端口、协议号、目的IP地址、目的端口
七元组是:源IP地址、源端口、协议号、目的IP地址、目的端口、服务类型、接口索引

(1.2.4) GW部署

1.在同机房按照公网出口不同分别对每个出口部署公网GW,提供公网vip使用。
2.每个机房一套内网GW,原则上本机房内的服务器使用本机房的内网gw,内网gw不分业务,所有使用vip的业务都是同一套gw集群。


(2) 模块分析

Linux网络发包流程

发包流程
1、业务服务调用send()方法发送数据。
2、调用send()方法后从用户态切到内核态,用户数据被拷贝到内核态
3、然后经过协议栈处理,这里对应tcp协议。
4、协议栈处理后进入到了环形队列RingBuffer中。
5、随后网卡驱动真正将数据发送了出去。
6、数据发送完成的时候,通过硬中断来通知CPU。
7、然后清理 RingBuffer。

(2.2) TCP中包类型

(3) 机房路由优化切流-导致的网络问题

2021-01-21 00:25 线上报警
2021-01-21 00:27 用户中心两个应用都出现了接口抖动,error日志显示数据库连接超时
2021-01-21 00:28 xms全面无法登录,系统无法作业

2021-01-21 00:32 操作维护理论业务是无感知的
2021-01-21 00:33 仓配中台的刚才各接口抖了一下,现在都恢复正常了
2021-01-21 00:36 业务影响描述 在流量切换时间前,client访问内网gw-vip(10.85.128.*)已经建立的tcp会话(例如:长链接业务),需要client端断开重新建立一次tcp会话,否则gw会将此流量丢弃。流量切换后新建的tcp连接不会有影响。
2021-01-21 00:36 商品中台17分左右有接口抖动,最大毛刺2000ms,影响时间1分钟。
mms刚好在发版,但没有发布的机器也有大的毛刺,其他发版时间毛刺正常

这个操作是有损的 需要client重连
2021-01-21 00:40 是的,发现17分左右有很多次异常请求Broken pipe,且proc_time>2000ms

org.springframework.dao.InvalidDataAccessApiUsageException: Unable to send command! Try to increase 'nettyThreads' and/or connection pool size settings xxx after 3 retry attempts;
    nested exception is org.redisson.client.RedisTimeoutException: Unable to send command! Try to increase 'nettyThreads' and/or connection pool size settings xxx after 3 retry attempts

2021-01-21 00:41 redis也连接不上
2021-01-21 00:41 redis前面也有proxy也过负载均衡设备。。。所以也会受影响
2021-01-21 00:48 刚刚和网络部同事沟通了下,这个操作会影响所有通过inrouter,弹性云vip及redis(通过vip暴露) ,如果db也用vip暴露,也会导致之前已有的tcp链接断开重新连接

业务影响描述 在流量切换时间前,client访问番禺内网gw-vip(10.85.128.*)已经建立的tcp会话(例如:长链接业务),需要client端断开重新建立一次tcp会话,否则gw会将此流量丢弃。流量切换后新建的tcp连接不会有影响。

否则gw会将此流量丢弃,需要client端断开重新建立一次tcp会话

这个可能和底层库有关,看能否及时感知到链接断开了
现在应该是超时触发的重连

已经建立的连接要等超时重连了,并且有连接池的话可能还会重试到其他废弃连接上。所以有超时抖动吧

2021-01-21 01:17 看获取商品详情影响了7.5分钟,可能要优化下
仓库高峰期

2021-01-21 02:24 负载均衡应该是能平滑切换的吧,长链接没办法,应该不影响短链接吧
2021-01-21 02:29 都影响 短链接你超时重试 也会新建立tcp连接
这个就是做不到无损切换,才在低峰期操作
长链接好多 超时重试都是业务层面的,不新建立tcp 连接,影响大

2021-01-21 02:38 切流
2021-01-21 02:45 数据库抖了一下
2021-01-21 02:45 Redis连接超时
2021-01-21 02:47 tms服务链接超时 两次报警

2021-01-21 03:01 今天的操作都完事了,辛苦大家。
不够后续还是希望业务配合下增加一下client访问vip超时 ,重新建立tcp连接的能力,我们vip 这块做不到无损,变更肯定都是凌晨,提前告知,但是设备故障也会产生同样的影响,这个时间无法预知。

思考

本地模拟

在tcp连接出问题之后,watchdog发现连接无效之后,然后打印了一个警告日志之后,就没法有自动重连了,导致继续使用该连接的时候出问题
Redis升降配后Redisson出错:Unable to send command!

其他人也发现了这个问题,在github上提了issues,在 Fixed - connection is not reconnected #1811 中解决了这个问题

redisson分布式锁:Redis分布式锁报错,Redisson出错:Unable to send command!

(4) 网络超时案例-网关调支付服务二次支付接口超时

背景 农历腊月十二,快年底了,运营疯狂搞活动,冲业绩,产品和研发也疯狂叠需求,每天的单量都刷新历史记录。
在一个风平浪静的周末早上,交易系统-下单服务 支付服务的一台机器被干躺了
现象 从服务接口监控看,交易系统的QPS暴涨,每天都刷新记录。
从容器监控看,有一台机器CPU idle掉底。
从日志看,发现有一条耗时特别高的日志。

时间线

2021-01-24 10:00:45:345 router网关
2021-01-24 10:00:45:347 流量网关服务收到请求
?
2021-01-24 10:00:49.062 交易系统-支付服务收到请求

2021-01-24 10:00:49.373 交易系统-支付服务请求处理完成 总耗时311ms

问题分析过程

虽然支付服务耗时是311ms,但是在2021-01-24 10:00:45:347 ~ 2021-01-24 10:00:49.062 差了将近4s的时间。


(5) 网络超时案例-下单调自提点服务网络超时

背景:
现象:

(5.1) 时间线

(5.2) 问题分析过程

曾经有一次,负责的交易系统-下单模块调用下游的开城服务判断自提点是否在开城范围内,通过日志发现调他们超时了。

从日志监控概览看,有大量超时
日志dltag监控

从日志看,调运营单元确实超时了
日志监控-下单校验运营单元异常

但是他们却告诉我,他们接口耗时只有3ms,而且日志有记录,日志里确实只有3ms
运营单元服务日志

2021-02-05 00:40:48.694 请求到网关
2021-02-05 00:40:49:022 开始请求开城服务
2021-02-05 00:40:49:156 开城服务业务服务接收到请求,打印日志
2021-02-05 00:40:49:159 开城服务业务服务处理完成,打印日志,耗时3ms

这个问题由多个原因导致,但是当时由于时间紧迫,通过一个治标不治本办法快速解决了,后来在思考,如果再遇到了怎么去排查并且定位问题?


(6) 异常场景下httpClientPool配置导致的超时问题

2021-03-12
maxConnectionPerRoute

(7) 交换机问题导致的网络超时问题

背景 2021-03-20 10:31:24 ~ 2021-03-20 10:31:30 交换机遇到一个问题,xx原因,网络丢包6s。
现象


(8) 网络超时案例-弹性云容器竞争资源异常导致网络超时问题

背景: 风控团队提出了一个优化需求,需要下单服务调风控的老接口迁移到新接口

现象: (1) 通过监控发现调风控新接口的错误数会随服务qps增大而变多
(2) 通过日志发现有很多xxx timed out after 200ms,是下单调风控新接口达到200ms的超时时间报错

Operation timed out after 200 milliseconds with 0 bytes received
Connection timed out after 200 milliseconds

(8.1) 下单调风控网络超时问题-时间线

2022-11-18 上线 小流量灰度 没有问题
2022-11-19 全量 没有问题
2022-11-20 报警 发现调风控接口有很多超时
2022-11-20 研发一起排查 是否是风控服务web容器tomcat耗时导致
2022-11-20 配置access.log后,通过日志时间看tomcat耗时几乎和风控接口耗时一样,不是tomcat容器问题
2022-11-20 通过日志发现时间对不上,猜测两台机器的时间不同步
2022-11-20 SRE通过 clockddiff + ip命令查看了一下两个容器,容器所在宿主之间时间差别为0ms,两台机器的时间是同步的
2022-11-20 猜测服务发现可能有问题,概率比较小,排除。
2022-11-20 下单发出请求的时间和风控接收到请求的时间有gap
2022-11-20 发现超时的每次都是某台机器或者某几台机器,超时的机器有聚集性
2022-11-20 容器更换后通过监控看报错数变少了
2022-11-20 发现一条trace风控接口耗时930ms,通过监控发现有YoungGC,YoungGC耗时90ms左右 (整体耗时不正常 YoungGC耗时也不正常)
2022-11-21 询问服务发现研发,询问后在当前场景下排除服务发现出错的可能。
2022-11-21 拉弹性云研发
2022-11-22 排查问题缺乏方向
2022-11-22 初步决定下单通过vip调用风控新接口,vip有nginx.log,可以对比nginx.log时间和access.log时间
2022-11-23 下单服务修改配置调风控使用vip,上线一半容器,一半使用vip调风控新接口,一半使用服务发现ip直连
2022-11-24 对比vip和服务发现,发现问题依然存在。不是服务发现问题
2022-11-24 发现无论在vip组容器还是服务发现直连容器组,下游(风控)超时的容器都存在聚集性,怀疑是容器问题
2022-11-24 找一条trace,对比下单trade.log时间、 vip走nginx.log的时间、风控web容器access.log的时间
2022-11-24 通过nginx.log里的时间对比发现,上游发出请求后200ms后超时主动断开连接,确认网络耗时主要在风控服务这边
2022-11-24 找弹性云研发排查网络问题
2022-11-24 换了容器后确实超时确实减少了大部分
2022-11-24 经过排查发现是容器CPU竞争资源异常,导致容器等待CPU时间片过长,再叠加gc,最终导致的服务超时。

(8.2) 分析排查过程

(8.2.1) 问题出现

2022-11-18 上线 小流量灰度 没有问题
2022-11-19 全量 没有问题
2022-11-20 报警 发现调风控接口有很多超时

(8.2.2) 问题排查

2022-11-20 研发一起排查
外卖下单研发 从日志看有问题的trace,调风控接口200ms后超时报错
风控研发 反馈 风控接口正常返回了,而且从风控服务的日志看,对应trace耗时只有91ms

(8.2.3) 问题分析-怀疑是web容器线程排队耗时

下单调风控接口超时时间是200ms,风控服务只花费了91ms,为什么会超时? 那109ms的时间去哪里了?

因为下单服务下游有10多个,只有掉风控新接口超时,初步怀疑是风控服务的问题。
而且风控服务是新服务,开发语言用的Java,web容器用的tomcat,而风控同学查看的日志是风控服务的日志,有可能是web容器请求堆积,耗费较多时间。
于是让风控同学开始web容器日志 access.log

(8.2.4) 开启web容器日志-排除web容器耗时

开启web容器日志后继续排查,发现web容器并没有耗费几ms,几乎都是0~1ms
问题来了? 100多ms到底耗费在哪里了?

(8.2.5) 问题分析-怀疑机器时间不同步

对比两台容器时间

SRE通过 clockddiff + ip命令查看了一下两个容器,容器所在宿主之间时间差别为0ms,两台机器的时间是同步的

继续分析

于是梳理调用链路 外卖下单服务 -> 服务发现 -> 获取下游ip和端口 通过ip:port直连下游服务 -> 调用风控接口

怀疑是服务发现的问题,拉了服务发现的研发,他们说只有在启动时服务发现会耗时,后续都是ip和端口直连,不会再走服务发现。

虽然理论上服务发现后是直连,但是不保证服务发现没有问题。

下单使用vip,通过排除法去定位

对比vip和服务发现ip直连

而且由于缺少日志,想了一个办法,外卖下单服务一半走服务发现,一般走vip,对比一下
而且vip是用nginx代理的,还可以看到nginx日志,顺便对比一下日志时间

通过对比三个日志时间,确认问题发生在风控侧。

发现存在聚集性

花了很长时间验证,但是我们没法是上游的问题还是下游的问题。
直到今天切换成vip以后,我们发现和连接的关系不大。
特别是早上芳菁发的这个统计,发现聚集性很大。只在某台机器上有。通过查看机器的gc日志,与运维的沟通。
我们发现是容器的cpu资源存在竞争,某些容器的等待cpu时间片过长,导致有问题的容器的服务的gc时间比平均时间过长,存在毛刺。所以会有部分请求超时,部分请求不超时。

throt_wait_sum

通常一个容器中会有多个线/进程运行, 并且容器有一个quota限(比如8核cpu,这里不考虑内存和其他资源)。那么在运行的过程中可能会出现三个方向的影响:

容器外部 exter_wait_sum: CPU被容器外的进程占用, 容器内的线程需要wait. 简而言之该容器被其它容器干扰。解法:此时建议将容器漂移到其它空闲的物理机或根据实际情况提高服务优先级.
容器内部 throt_wait_sum: 容器达到cpu quota(容器规格)的限制, 内核限制容器的运行时间, 。解法:此时建议扩大容器的规格或扩大容器数量.
容器内部 inner_wait_sum: 业务线程的突发运行, 但未达到容器的cpu quota限制。解法:此时建议优化业务代码,减少大量进程突发.

参考资料

[1] MGW——美团点评高性能四层负载均衡
[2] LVS原理篇:LVS简介、结构、四种模式、十种算法
[3] LVS中文站点
[4] LVS负载均衡之LVS-NAT与LVS-DR模式原理详解
[5] LVS调度方法
[6] cpu throttle原理浅析