一次網(wǎng)絡(luò)超時(shí)的排查

最近在測(cè)試一個(gè)分布式組件的時(shí)候，發(fā)現(xiàn)節(jié)點(diǎn)之間會(huì)頻繁的出現(xiàn)網(wǎng)絡(luò)傳輸超時(shí)的情況。組件的工作原理如下

1. 節(jié)點(diǎn) 1 向節(jié)點(diǎn) 2 發(fā)送心跳包，發(fā)送之后等待節(jié)點(diǎn) 2 的回應(yīng)
2. 節(jié)點(diǎn) 2 在收到心跳包之后做一些處理，隨后發(fā)送回復(fù)報(bào)文給節(jié)點(diǎn) 1
3. 節(jié)點(diǎn) 1 收到節(jié)點(diǎn) 2 回復(fù)的報(bào)文并退出等待，一次數(shù)據(jù)傳輸結(jié)束
4. 節(jié)點(diǎn) 1 如果一段時(shí)間內(nèi)沒有收到節(jié)點(diǎn) 2 的回應(yīng)就會(huì)發(fā)生超時(shí)異常

我們遇到的問題就是節(jié)點(diǎn) 1 總是在運(yùn)行一段時(shí)間之后（很短，大約幾秒鐘），發(fā)送給節(jié)點(diǎn) 2 的數(shù)據(jù)就無法及時(shí)的得到回應(yīng)，隨后節(jié)點(diǎn) 1 ?報(bào)出超時(shí)異常。問題在于我們用于測(cè)試的機(jī)器應(yīng)該都在同一個(gè)機(jī)房，而我們?cè)O(shè)置的超時(shí)時(shí)間為 50ms，同一個(gè)機(jī)房的節(jié)點(diǎn)延遲怎么會(huì)超過 50ms 呢？

日志

因?yàn)槭欠植际较到y(tǒng)，并且涉及到網(wǎng)絡(luò)傳輸，我們基本上沒有辦法使用 DEBUG 來進(jìn)行調(diào)試，所以日志成為了排解問題的唯一線索。順便說一句，在寫代碼的時(shí)候日志應(yīng)該越詳細(xì)越好，日志除了打印變量數(shù)據(jù)，還應(yīng)該附帶好詳細(xì)的上下文信息。

我們?cè)诎l(fā)送數(shù)據(jù)和接收數(shù)據(jù)的地方都打上日志，此外應(yīng)該對(duì)所使用的節(jié)點(diǎn)的時(shí)間進(jìn)行校對(duì)，我們?cè)诜治鰡栴}時(shí)很依賴于日志中記錄的時(shí)間信息。

我們執(zhí)行程序獲取日志如下

發(fā)送端

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

我們觀察以上日志發(fā)現(xiàn)確實(shí)發(fā)送端在發(fā)送了心跳 50ms 后因?yàn)闆]有收到響應(yīng)隨即超時(shí)了，接下來我們?cè)儆^察接收端的日志。根據(jù)上面的日志我們已經(jīng)知道了異常發(fā)生在 703ms ~ 874ms ?之間，所以我們?cè)谟^察接收端的日志時(shí)應(yīng)該重點(diǎn)關(guān)注 703、763、824 這三個(gè)發(fā)送了心跳的時(shí)間點(diǎn)，接收端有如下日志信息：

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

觀察接收端的日志我們發(fā)現(xiàn)在 655ms 的時(shí)候接收端接收到最后一次正常的心跳，隨后就被阻塞在 read 調(diào)用上，下一次讀取到心跳信息則是在 ?895ms，并且隨后很快的就讀完了三次心跳的數(shù)據(jù)。很顯然，895 遠(yuǎn)大于 ?703、763、824，那么是什么原因?qū)е铝税l(fā)送端在這三個(gè)時(shí)間點(diǎn)發(fā)送的報(bào)文一直到 200 多毫秒之后才被接收端成功的讀取到呢？

tcpdump

我們使用 tcpdump 工具來獲取網(wǎng)絡(luò)報(bào)文信息，從而了解數(shù)據(jù)的傳輸情況。因?yàn)槲覀兊慕M件使用 6300 端口進(jìn)行數(shù)據(jù)傳輸，所以在兩個(gè)節(jié)點(diǎn)上面都要執(zhí)行如下命令來抓取通過 6300 端口的報(bào)文

$?tcpdump?tcp?port?6300

我在上一步執(zhí)行程序的時(shí)候已經(jīng)打開了 tcpdump 命令，所以現(xiàn)在我們已經(jīng)可以觀察 tcpdump ?的輸出信息了。首先觀察發(fā)送端發(fā)送的信息，同樣我們只關(guān)注 703ms ~ 874ms ?之間的信息。該時(shí)間段的信息如下，需要注意有一些網(wǎng)絡(luò)數(shù)據(jù)報(bào)文與我們要關(guān)注的內(nèi)容無關(guān)，直接忽略即可。

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 是節(jié)點(diǎn) 1，172.21.3.92.57619 是節(jié)點(diǎn) 2，即心跳是由 lin-21-34-202 發(fā)送給 172.21.3.92 的。Flags 中的 P 代表 PUSH， . 代表 ACK。

已知我們心跳的長(zhǎng)度為 12，由上面的報(bào)文以及前面的日志我們可以推測(cè)出來，第一行的信息代表了最后一次節(jié)點(diǎn) 1 給節(jié)點(diǎn) 2 發(fā)送的正常心跳信息。

隨后節(jié)點(diǎn) 1 發(fā)送了 seq 為 546:567 和 567:588 的兩條心跳包，這就是第 3 第 4 行的信息。奇怪的是在第 5 行所代表的節(jié)點(diǎn) 2 回復(fù)的 ACK 中，只表示收到了 567:588 的的數(shù)據(jù)包，沒有 546:567。第 6 第 7 行表示了發(fā)送的第三個(gè)心跳包 588:609 以及相應(yīng)的 ACK 567:609。

節(jié)點(diǎn) 1 發(fā)現(xiàn)節(jié)點(diǎn) 2 遲遲不回復(fù) 546:567 的 ACK，就對(duì) 546:567 進(jìn)行了重發(fā)，這就是第 12 行的信息。這一次節(jié)點(diǎn) 2 終于回復(fù)了 ACK（第 14 行），我們可以認(rèn)為 546:567 確定被發(fā)送到節(jié)點(diǎn) 2 了。

隨后我們?cè)倏匆幌陆邮斩说膱?bào)文信息

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

接收端的報(bào)文基本上就是發(fā)送端的鏡像，但是有趣的是接收端的報(bào)文只有 13 條，而發(fā)送端則發(fā)送了 14 條報(bào)文。仔細(xì)對(duì)比就發(fā)現(xiàn)發(fā)送端的 seq 546:567 在接收端不存在，看來這個(gè)報(bào)文在網(wǎng)絡(luò)傳輸中丟失了沒能成功到達(dá)節(jié)點(diǎn) 2。節(jié)點(diǎn) 2 在節(jié)點(diǎn) 1 再次重傳后才最終獲取了 546:567 的報(bào)文信息，即接收端的第 12 行，此時(shí)時(shí)間點(diǎn)為 15:18:45.894971，最后節(jié)點(diǎn) 2 返回給節(jié)點(diǎn) 1 ACK。

分析

觀察上面接收端收到重傳數(shù)據(jù)的時(shí)間為 15:18:45.894971，日志中接收端用戶態(tài)成功讀取到報(bào)文的時(shí)間為 15:18:45.895077，那結(jié)果就明顯了。

節(jié)點(diǎn) 1 發(fā)送給節(jié)點(diǎn) 2 的第一個(gè)心跳包丟失了，因?yàn)?TCP ?協(xié)議中數(shù)據(jù)的有序性，所以雖然后面的數(shù)據(jù)成功到達(dá)也不能將這些數(shù)據(jù)返回給用戶態(tài)程序。一直到節(jié)點(diǎn) 1 因?yàn)闆]能得到 ACK 而進(jìn)行超時(shí)重傳，節(jié)點(diǎn) 2 ?最終獲取了心跳包 1，此時(shí)數(shù)據(jù)已經(jīng)完整可以返回給用戶態(tài)程序。這一頓操作也導(dǎo)致這部分?jǐn)?shù)據(jù)從節(jié)點(diǎn) 1 的用戶態(tài)到節(jié)點(diǎn) 2 的用戶態(tài)之間產(chǎn)生了 894 - 703 約 200ms 的延遲，因而節(jié)點(diǎn) 1 產(chǎn)生了超時(shí)。

解決

咦，為什么同一個(gè)機(jī)房的兩個(gè)機(jī)器之間會(huì)丟包呢，難道路由器出問題了？經(jīng)過檢查之后發(fā)現(xiàn)是我們自己搞錯(cuò)了，在申請(qǐng)機(jī)器的時(shí)候我們第一次申請(qǐng)的機(jī)器在南京，第二次申請(qǐng)的機(jī)器在杭州，所以這兩個(gè)機(jī)器其實(shí)并不是在一個(gè)機(jī)房并且之間隔了接近 ?300km，產(chǎn)生丟包的現(xiàn)象也就可以理解了。雖然問題產(chǎn)生的原因很囧，但是這次耗時(shí)兩天的問題排查還是讓我很有收獲的，切換了負(fù)載之后問題也就成功解決了。

你可能還喜歡

點(diǎn)擊下方圖片即可閱讀

云原生是一種信仰???

關(guān)注公眾號(hào)

后臺(tái)回復(fù)?k8s?獲取史上最方便快捷的 Kubernetes 高可用部署工具，只需一條命令，連 ssh 都不需要！