前往小程序,Get更优阅读体验!
立即前往
首页
学习
活动
专区
工具
TVP
发布
社区首页 >专栏 >一次网络超时的排查

一次网络超时的排查

作者头像
米开朗基杨
发布2021-10-27 14:57:43
1.1K0
发布2021-10-27 14:57:43
举报
文章被收录于专栏:云原生实验室

最近在测试一个分布式组件的时候,发现节点之间会频繁的出现网络传输超时的情况。组件的工作原理如下

  1. 节点 1 向节点 2 发送心跳包,发送之后等待节点 2 的回应
  2. 节点 2 在收到心跳包之后做一些处理,随后发送回复报文给节点 1
  3. 节点 1 收到节点 2 回复的报文并退出等待,一次数据传输结束
  4. 节点 1 如果一段时间内没有收到节点 2 的回应就会发生超时异常

我们遇到的问题就是节点 1 总是在运行一段时间之后(很短,大约几秒钟),发送给节点 2 的数据就无法及时的得到回应,随后节点 1 报出超时异常。问题在于我们用于测试的机器应该都在同一个机房,而我们设置的超时时间为 50ms,同一个机房的节点延迟怎么会超过 50ms 呢?

日志

因为是分布式系统,并且涉及到网络传输,我们基本上没有办法使用 DEBUG 来进行调试,所以日志成为了排解问题的唯一线索。顺便说一句,在写代码的时候日志应该越详细越好,日志除了打印变量数据,还应该附带好详细的上下文信息。

我们在发送数据和接收数据的地方都打上日志,此外应该对所使用的节点的时间进行校对,我们在分析问题时很依赖于日志中记录的时间信息。

我们执行程序获取日志如下

发送端

代码语言:javascript
复制
2019/08/14 15:18:45.703679 node.go:233: 202(me) send AppendEntries to 92
2019/08/14 15:18:45.753927 node.go:259: 202(me) to 92 AppendEntries timeout and retry
2019/08/14 15:18:45.763991 node.go:233: 202(me) send AppendEntries to 92
2019/08/14 15:18:45.814221 node.go:259: 202(me) to 92 AppendEntries timeout and retry
2019/08/14 15:18:45.824193 node.go:233: 202(me) send AppendEntries to 92
2019/08/14 15:18:45.874455 node.go:259: 202(me) to 92 AppendEntries timeout and retry

我们观察以上日志发现确实发送端在发送了心跳 50ms 后因为没有收到响应随即超时了,接下来我们再观察接收端的日志。根据上面的日志我们已经知道了异常发生在 703ms ~ 874ms 之间,所以我们在观察接收端的日志时应该重点关注 703、763、824 这三个发送了心跳的时间点,接收端有如下日志信息:

代码语言:javascript
复制
2019/08/14 15:18:45.655403 connection.go:387: AppendEntries

2019/08/14 15:18:45.655477 connection.go:95: Read Start
2019/08/14 15:18:45.895077 connection.go:99: Read End
2019/08/14 15:18:45.895112 connection.go:100: Read 1 bytes and cost 239ms 239574218ns
2019/08/14 15:18:45.895379 connection.go:387: AppendEntries

2019/08/14 15:18:45.895439 connection.go:95: Read Start
2019/08/14 15:18:45.895452 connection.go:99: Read End
2019/08/14 15:18:45.895464 connection.go:100: Read 1 bytes and cost 0ms 4203ns
2019/08/14 15:18:45.895711 connection.go:387: AppendEntries

2019/08/14 15:18:45.895766 connection.go:95: Read Start
2019/08/14 15:18:45.895779 connection.go:99: Read End
2019/08/14 15:18:45.895791 connection.go:100: Read 1 bytes and cost 0ms 3862ns
2019/08/14 15:18:45.896082 connection.go:387: AppendEntries

观察接收端的日志我们发现在 655ms 的时候接收端接收到最后一次正常的心跳,随后就被阻塞在 read 调用上,下一次读取到心跳信息则是在 895ms,并且随后很快的就读完了三次心跳的数据。很显然,895 远大于 703、763、824,那么是什么原因导致了发送端在这三个时间点发送的报文一直到 200 多毫秒之后才被接收端成功的读取到呢?

tcpdump

我们使用 tcpdump 工具来获取网络报文信息,从而了解数据的传输情况。因为我们的组件使用 6300 端口进行数据传输,所以在两个节点上面都要执行如下命令来抓取通过 6300 端口的报文

代码语言:javascript
复制
$ tcpdump tcp port 6300

我在上一步执行程序的时候已经打开了 tcpdump 命令,所以现在我们已经可以观察 tcpdump 的输出信息了。首先观察发送端发送的信息,同样我们只关注 703ms ~ 874ms 之间的信息。该时间段的信息如下,需要注意有一些网络数据报文与我们要关注的内容无关,直接忽略即可。

代码语言:javascript
复制
15:18:45.643425 IP lin-21-34-202.bmc-grx > 172.21.3.92.57619: Flags [P.], seq 525:546, ack 164, win 114, options [nop,nop,TS val 3450638986 ecr 3259647687], length 21
15:18:45.664930 IP 172.21.3.92.57619 > lin-21-34-202.bmc-grx: Flags [P.], seq 164:170, ack 546, win 115, options [nop,nop,TS val 3259647744 ecr 3450638986], length 6
15:18:45.703607 IP lin-21-34-202.bmc-grx > 172.21.3.92.57619: Flags [P.], seq 546:567, ack 170, win 114, options [nop,nop,TS val 3450639047 ecr 3259647744], length 21
15:18:45.763909 IP lin-21-34-202.bmc-grx > 172.21.3.92.57619: Flags [P.], seq 567:588, ack 170, win 114, options [nop,nop,TS val 3450639107 ecr 3259647744], length 21
15:18:45.784473 IP 172.21.3.92.57619 > lin-21-34-202.bmc-grx: Flags [.], ack 546, win 115, options [nop,nop,TS val 3259647863 ecr 3450638986,nop,nop,sack 1 {567:588}], length 0
15:18:45.824084 IP lin-21-34-202.bmc-grx > 172.21.3.92.57619: Flags [P.], seq 588:609, ack 170, win 114, options [nop,nop,TS val 3450639167 ecr 3259647863], length 21
15:18:45.840677 IP 172.21.3.92.57619 > lin-21-34-202.bmc-grx: Flags [.], ack 546, win 115, options [nop,nop,TS val 3259647920 ecr 3450638986,nop,nop,sack 1 {567:609}], length 0
15:18:45.869809 IP 172.21.3.92.57619 > lin-21-34-202.bmc-grx: Flags [P.], seq 170:183, ack 546, win 115, options [nop,nop,TS val 3259647948 ecr 3450638986,nop,nop,sack 1 {567:609}], length 13
15:18:45.870435 IP lin-21-34-202.bmc-grx > 172.21.3.92.57619: Flags [P.], seq 609:615, ack 183, win 114, options [nop,nop,TS val 3450639213 ecr 3259647948], length 6
15:18:45.884354 IP lin-21-34-202.bmc-grx > 172.21.3.92.57619: Flags [P.], seq 615:636, ack 183, win 114, options [nop,nop,TS val 3450639227 ecr 3259647948], length 21
15:18:45.886702 IP 172.21.3.92.57619 > lin-21-34-202.bmc-grx: Flags [.], ack 546, win 115, options [nop,nop,TS val 3259647966 ecr 3450638986,nop,nop,sack 1 {567:615}], length 0
15:18:45.886732 IP lin-21-34-202.bmc-grx > 172.21.3.92.57619: Flags [P.], seq 546:567, ack 183, win 114, options [nop,nop,TS val 3450639230 ecr 3259647948], length 21
15:18:45.902699 IP 172.21.3.92.57619 > lin-21-34-202.bmc-grx: Flags [.], ack 546, win 115, options [nop,nop,TS val 3259647981 ecr 3450638986,nop,nop,sack 1 {567:636}], length 0
15:18:45.903892 IP 172.21.3.92.57619 > lin-21-34-202.bmc-grx: Flags [.], ack 636, win 115, options [nop,nop,TS val 3259647983 ecr 3450639230], length 0

其中 lin-21-34-202 是节点 1,172.21.3.92.57619 是节点 2,即心跳是由 lin-21-34-202 发送给 172.21.3.92 的。Flags 中的 P 代表 PUSH, . 代表 ACK。

已知我们心跳的长度为 12,由上面的报文以及前面的日志我们可以推测出来,第一行的信息代表了最后一次节点 1 给节点 2 发送的正常心跳信息。

随后节点 1 发送了 seq 为 546:567567:588 的两条心跳包,这就是第 3 第 4 行的信息。奇怪的是在第 5 行所代表的节点 2 回复的 ACK 中,只表示收到了 567:588 的的数据包,没有 546:567。第 6 第 7 行表示了发送的第三个心跳包 588:609 以及相应的 ACK 567:609

节点 1 发现节点 2 迟迟不回复 546:567 的 ACK,就对 546:567 进行了重发,这就是第 12 行的信息。这一次节点 2 终于回复了 ACK(第 14 行),我们可以认为 546:567 确定被发送到节点 2 了。

随后我们再看一下接收端的报文信息

代码语言:javascript
复制
15:18:45.654608 IP 172.21.34.202.bmc-grx > lin-21-3-92.57619: Flags [P.], seq 525:546, ack 164, win 114, options [nop,nop,TS val 3450638986 ecr 3259647687], length 21
15:18:45.655249 IP lin-21-3-92.57619 > 172.21.34.202.bmc-grx: Flags [P.], seq 164:170, ack 546, win 115, options [nop,nop,TS val 3259647744 ecr 3450638986], length 6
15:18:45.774317 IP 172.21.34.202.bmc-grx > lin-21-3-92.57619: Flags [P.], seq 567:588, ack 170, win 114, options [nop,nop,TS val 3450639107 ecr 3259647744], length 21
15:18:45.774348 IP lin-21-3-92.57619 > 172.21.34.202.bmc-grx: Flags [.], ack 546, win 115, options [nop,nop,TS val 3259647863 ecr 3450638986,nop,nop,sack 1 {567:588}], length 0
15:18:45.831770 IP 172.21.34.202.bmc-grx > lin-21-3-92.57619: Flags [P.], seq 588:609, ack 170, win 114, options [nop,nop,TS val 3450639167 ecr 3259647863], length 21
15:18:45.831795 IP lin-21-3-92.57619 > 172.21.34.202.bmc-grx: Flags [.], ack 546, win 115, options [nop,nop,TS val 3259647920 ecr 3450638986,nop,nop,sack 1 {567:609}], length 0
15:18:45.859801 IP lin-21-3-92.57619 > 172.21.34.202.bmc-grx: Flags [P.], seq 170:183, ack 546, win 115, options [nop,nop,TS val 3259647948 ecr 3450638986,nop,nop,sack 1 {567:609}], length 13
15:18:45.877852 IP 172.21.34.202.bmc-grx > lin-21-3-92.57619: Flags [P.], seq 609:615, ack 183, win 114, options [nop,nop,TS val 3450639213 ecr 3259647948], length 6
15:18:45.877870 IP lin-21-3-92.57619 > 172.21.34.202.bmc-grx: Flags [.], ack 546, win 115, options [nop,nop,TS val 3259647966 ecr 3450638986,nop,nop,sack 1 {567:615}], length 0
15:18:45.892884 IP 172.21.34.202.bmc-grx > lin-21-3-92.57619: Flags [P.], seq 615:636, ack 183, win 114, options [nop,nop,TS val 3450639227 ecr 3259647948], length 21
15:18:45.892901 IP lin-21-3-92.57619 > 172.21.34.202.bmc-grx: Flags [.], ack 546, win 115, options [nop,nop,TS val 3259647981 ecr 3450638986,nop,nop,sack 1 {567:636}], length 0
15:18:45.894971 IP 172.21.34.202.bmc-grx > lin-21-3-92.57619: Flags [P.], seq 546:567, ack 183, win 114, options [nop,nop,TS val 3450639230 ecr 3259647948], length 21
15:18:45.894989 IP lin-21-3-92.57619 > 172.21.34.202.bmc-grx: Flags [.], ack 636, win 115, options [nop,nop,TS val 3259647983 ecr 3450639230], length 0

接收端的报文基本上就是发送端的镜像,但是有趣的是接收端的报文只有 13 条,而发送端则发送了 14 条报文。仔细对比就发现发送端的 seq 546:567 在接收端不存在,看来这个报文在网络传输中丢失了没能成功到达节点 2。节点 2 在节点 1 再次重传后才最终获取了 546:567 的报文信息,即接收端的第 12 行,此时时间点为 15:18:45.894971,最后节点 2 返回给节点 1 ACK。

分析

观察上面接收端收到重传数据的时间为 15:18:45.894971,日志中接收端用户态成功读取到报文的时间为 15:18:45.895077,那结果就明显了。

节点 1 发送给节点 2 的第一个心跳包丢失了,因为 TCP 协议中数据的有序性,所以虽然后面的数据成功到达也不能将这些数据返回给用户态程序。一直到节点 1 因为没能得到 ACK 而进行超时重传,节点 2 最终获取了心跳包 1,此时数据已经完整可以返回给用户态程序。这一顿操作也导致这部分数据从节点 1 的用户态到节点 2 的用户态之间产生了 894 - 703 约 200ms 的延迟,因而节点 1 产生了超时。

解决

咦,为什么同一个机房的两个机器之间会丢包呢,难道路由器出问题了?经过检查之后发现是我们自己搞错了,在申请机器的时候我们第一次申请的机器在南京,第二次申请的机器在杭州,所以这两个机器其实并不是在一个机房并且之间隔了接近 300km,产生丢包的现象也就可以理解了。虽然问题产生的原因很囧,但是这次耗时两天的问题排查还是让我很有收获的,切换了负载之后问题也就成功解决了。

原文链接:https://www.nosuchfield.com/2019/08/14/Network-timeout-troubleshooting/

本文参与 腾讯云自媒体同步曝光计划,分享自微信公众号。
原始发表:2021-10-19,如有侵权请联系 cloudcommunity@tencent.com 删除

本文分享自 云原生实验室 微信公众号,前往查看

如有侵权,请联系 cloudcommunity@tencent.com 删除。

本文参与 腾讯云自媒体同步曝光计划  ,欢迎热爱写作的你一起参与!

评论
登录后参与评论
0 条评论
热度
最新
推荐阅读
目录
  • 日志
  • tcpdump
  • 分析
  • 解决
领券
问题归档专栏文章快讯文章归档关键词归档开发者手册归档开发者手册 Section 归档