問(wèn)題描述

我司某產(chǎn)品線有指定業(yè)務(wù)接口customQuery在線上環(huán)境中，與首頁(yè)一起打開(kāi)時(shí)下載數(shù)據(jù)的時(shí)間明顯過(guò)長(zhǎng)（平均可以達(dá)到2s）

注：

• “與首頁(yè)一起打開(kāi)” 的含義是指用戶進(jìn)入WEB系統(tǒng)后會(huì)首次加載的主頁(yè)面，該主頁(yè)會(huì)提前請(qǐng)求customQuery數(shù)據(jù)，以用于顯示首頁(yè)中的列表數(shù)據(jù)。
• 正常的想法會(huì)第一時(shí)間認(rèn)為是剛進(jìn)入首頁(yè)請(qǐng)求多，導(dǎo)致的下載速度慢，這個(gè)自然不是這個(gè)原因，要不然也不會(huì)專門寫(xiě)這些內(nèi)容，后面會(huì)講到。
• 下文中我會(huì)盡量?jī)H針對(duì)問(wèn)題本身，不摻雜業(yè)務(wù)邏輯進(jìn)行表述，并盡可能的做到描述清晰，準(zhǔn)確。不過(guò)個(gè)人表達(dá)力及知識(shí)儲(chǔ)備難免會(huì)有盲區(qū)，下文如有描述不當(dāng)或有事實(shí)錯(cuò)誤的地方，希望大家可以直接悉心指出。
• 這里需要單獨(dú)說(shuō)明下因?yàn)橹耙呀?jīng)發(fā)過(guò)一篇關(guān)于customQuery請(qǐng)求gzip壓縮的帖子，而這里講的是2個(gè)沒(méi)有關(guān)系的東西，不用聯(lián)系在一起。

先直接上問(wèn)題請(qǐng)求的截圖

如上圖323K的數(shù)據(jù)下載用了近2s，明顯是出問(wèn)題了。

 

該接口有在數(shù)據(jù)翻頁(yè)時(shí)也會(huì)觸發(fā)，不過(guò)下載時(shí)間表現(xiàn)正常。（如下圖，同樣的軟硬件條件，在其他場(chǎng)景下，同樣的參數(shù)拉取同一個(gè)接口的情況）

上圖是翻頁(yè)的場(chǎng)景（因?yàn)槭橇斜頂?shù)據(jù)，默認(rèn)進(jìn)入打開(kāi)第一頁(yè)，也可以自己觸發(fā)翻頁(yè)到其他頁(yè)或回到第一頁(yè)），也就是說(shuō)只有在首頁(yè)中被調(diào)用時(shí)下載時(shí)間異常，在正常TAB頁(yè)中切換翻頁(yè)數(shù)據(jù)下載表現(xiàn)都很正常。

還有一個(gè)細(xì)節(jié)，這個(gè)接口在測(cè)試或預(yù)發(fā)環(huán)境表現(xiàn)都是正常的，沒(méi)有出現(xiàn)下載時(shí)間過(guò)長(zhǎng)的問(wèn)題，這也從側(cè)面證明了并不是因?yàn)槭醉?yè)數(shù)據(jù)量大導(dǎo)致下載慢，通過(guò)查看各個(gè)整個(gè)過(guò)程的請(qǐng)求時(shí)間線也能明顯看出，在出問(wèn)題的時(shí)間斷，并沒(méi)有很多數(shù)據(jù)資源正在傳輸。

排除服務(wù)端問(wèn)題

為了排除服務(wù)端的問(wèn)題，自己構(gòu)建了測(cè)試程序簡(jiǎn)單模擬了下面場(chǎng)景。

• 同一請(qǐng)求順序發(fā)送10次，結(jié)果如下（下載時(shí)間全部保持在300ms以下）

• 以下是5個(gè)一組一起發(fā)送的情況，可以看到下載時(shí)間基本上也是維持在了500ms以下（因?yàn)樵撜?qǐng)求其實(shí)很大，一個(gè)response有超過(guò)300kb，5個(gè)會(huì)有近2Mb，這個(gè)時(shí)候已經(jīng)對(duì)帶寬有一定的壓力了，下載速度下降是正常的，而在首頁(yè)加載的場(chǎng)景下不會(huì)有這么大的帶寬壓力）

 

 

通過(guò)上面的測(cè)試不難看出無(wú)論是順序發(fā)送，或同一個(gè)客戶端同時(shí)并行請(qǐng)求該請(qǐng)求資源的情況下，下載速度都不會(huì)下降到超過(guò)1s的水平。
Chrome DevTools 里可以看到當(dāng)前瀏覽器默認(rèn)同一個(gè)域名雖也是同時(shí)維持著6個(gè)http1.1鏈接，但除了目標(biāo)接口，其他5個(gè)請(qǐng)求都會(huì)非常快的完成（其他響應(yīng)大多小于1kb,不會(huì)占用太多帶寬）

雖然這樣想，但是現(xiàn)在也只能暫時(shí)懷疑是網(wǎng)絡(luò)方面的問(wèn)題了，為了證實(shí)自己的猜想，需要分析TCP原始報(bào)文。

注：本文并不闡述如何解決問(wèn)題，主要通過(guò)各種事實(shí)數(shù)據(jù)證明問(wèn)題出現(xiàn)在哪一個(gè)點(diǎn)，從而將問(wèn)題轉(zhuǎn)到正確的責(zé)任人。因?yàn)橐话惚容^詭異的問(wèn)題如果不能確認(rèn)是問(wèn)題具體是出在哪一塊（服務(wù)端，運(yùn)維，前端，嵌入式），那任何一方在工作壓力已經(jīng)如此大的情況下難免會(huì)本能的認(rèn)為是其他人的問(wèn)題，最后的結(jié)果就是，問(wèn)題長(zhǎng)時(shí)間都得不到解決。不過(guò)如果有充足是事實(shí)證據(jù)證明問(wèn)題出在哪里，那通常負(fù)責(zé)那一塊的同學(xué)還是會(huì)盡力去解決的。

 

排查網(wǎng)絡(luò)問(wèn)題

準(zhǔn)備工作

為了配合Wireshark分析TCP報(bào)文我們需要使用Chrome的【Capture Network Log】直接在chrome中訪問(wèn) chrome://net-export/  即可以打開(kāi)。

（Capture Network Log 的使用見(jiàn) https://support.google.com/chrome/a/answer/3293821?hl=en 僅僅是用還是比較容易的）

如下圖，在把Capture Network Log啟動(dòng)后，再次觸發(fā)首頁(yè)加載，DevTools顯示下載時(shí)間依然很長(zhǎng)。

 

剛剛network logs里的數(shù)據(jù)我們可以在netlog viewer里打開(kāi)（https://netlog-viewer.appspot.com/   這是官方的在線日志分析器，訪問(wèn)這個(gè)鏈接您可能需要“梯子”）

如上圖我們通過(guò)Sockets及Events里的記錄定位到我們請(qǐng)求的鏈路。

主要是要獲得這個(gè)鏈路的本地端口號(hào)，在Wireshark里我們需要通過(guò)這個(gè)端口號(hào)跟蹤我們的tcp流（因?yàn)閷?shí)際一次場(chǎng)景發(fā)給目標(biāo)域名/ip的請(qǐng)求可能多達(dá)幾十個(gè)，靠盲猜是很難準(zhǔn)確定位到目標(biāo)請(qǐng)求的流量的）

當(dāng)然還可以得到這個(gè)鏈路的開(kāi)始時(shí)間，及耗時(shí) （需要明確一點(diǎn)這個(gè)開(kāi)始時(shí)間是握手開(kāi)始時(shí)間，不完全等于這個(gè)請(qǐng)求的開(kāi)始時(shí)間，而且這個(gè)鏈接其實(shí)也會(huì)發(fā)好幾個(gè)請(qǐng)求，后面會(huì)提到）

根據(jù)netlog viewer里的信息找到指定端口，如上圖追蹤目標(biāo)流（本質(zhì)是對(duì)網(wǎng)卡數(shù)據(jù)包進(jìn)行過(guò)濾篩選，更容易定位問(wèn)題）

 

如上圖，通過(guò)查看netlog viewer 里的SOCKET_BYTES_SENT記錄我們不難發(fā)現(xiàn)這個(gè)鏈接其實(shí)一共發(fā)送了4次HTTP應(yīng)用層請(qǐng)求（分別在第26ms，第119ms，第153ms，第184ms 注意這里使用的是相對(duì)時(shí)間）
通過(guò)計(jì)算保留到秒的絕對(duì)時(shí)間分別為35.528；35.621；35.655；35.686 (實(shí)際是最后一個(gè)才是我們的目標(biāo)請(qǐng)求，通過(guò)chrome時(shí)間線或響應(yīng)的大小可以很容易的確認(rèn)這個(gè)點(diǎn))

如上圖，通過(guò)在指定流篩選由客戶端發(fā)出去的大小合適的數(shù)據(jù)，可以看到發(fā)送的時(shí)間點(diǎn)基本上是跟前面Chrome的netlog viewer對(duì)的上去的（因?yàn)檎?qǐng)求實(shí)際上都很小，一個(gè)報(bào)文長(zhǎng)度內(nèi)就能發(fā)完）

 

目標(biāo)流量確認(rèn)了，現(xiàn)在我們可以安心的去分析TCP報(bào)文了

我們只需要關(guān)注No 968 后面的報(bào)文（因?yàn)槲覀兊哪繕?biāo)請(qǐng)求是從這里開(kāi)始的），可以看到其實(shí)第一個(gè)數(shù)據(jù)回包在No 1031 （時(shí)間為：35.875）
與發(fā)出請(qǐng)求的那個(gè)包的時(shí)間差為189ms，這個(gè)其實(shí)就是TTFB （與chrome里計(jì)算出的198ms也是接近的）
逐條查看后面下載的包，看起來(lái)都很正常。
下面列出最開(kāi)始在網(wǎng)絡(luò)方向懷疑的幾個(gè)可能的點(diǎn)，并逐個(gè)嘗試排查。 （下一段內(nèi)容主要是逐個(gè)排除自己猜測(cè)，且過(guò)程與網(wǎng)絡(luò)傳輸強(qiáng)相關(guān)，如果實(shí)在不感興趣可以跳過(guò)直接看結(jié)論 ）

1:首先懷疑滑動(dòng)窗持續(xù)收縮，導(dǎo)致后面接收效率急劇下降

 通過(guò)Wireshark提供的流圖形我們可以直觀的看到滑動(dòng)窗口在整個(gè)TCP數(shù)據(jù)流里的變化趨勢(shì)（當(dāng)然在外面報(bào)文列表里也能直接看出來(lái)）

 不過(guò)看起來(lái)當(dāng)前流最差的情況滑動(dòng)窗口也還有100kb （完全是夠用，事實(shí)上只要紅框處tcptrace的2條線不重合即表示滑動(dòng)窗口還沒(méi)有滿）

 

2:而后是擁塞窗口cwnd，會(huì)不會(huì)是發(fā)送端因?yàn)閬y序或超時(shí)導(dǎo)致服務(wù)器當(dāng)前鏈路的cwnd下降而主動(dòng)降速

因?yàn)閏wnd是發(fā)送端本地維護(hù)的，我們無(wú)法像Win窗口一樣在Wireshark里直接看到，不過(guò)我們可以通過(guò)觀察流量包的狀態(tài)得出初步的判斷。（分析在沒(méi)有ACK確認(rèn)的情況下可以發(fā)送多少數(shù)據(jù)）
目標(biāo)請(qǐng)求response一共323KB（服務(wù)端回我們的包一個(gè)為1460字節(jié)）理論一共大概會(huì)回復(fù)我們200多個(gè)包(通過(guò)過(guò)濾器我們可以準(zhǔn)確統(tǒng)計(jì)出229個(gè)含有有效數(shù)據(jù)的回包，當(dāng)然包括少量的TLS握手及前3個(gè)請(qǐng)求的回包)
如果按默認(rèn)擁塞窗口閥值ssthresh取65532，最差會(huì)在第45個(gè)包左右（每個(gè)報(bào)文段都充滿的情況下）就會(huì)完成慢啟動(dòng)進(jìn)入擁塞避免狀態(tài)。

如上圖，通過(guò)查看建立鏈接握手時(shí)收到ACK的時(shí)間點(diǎn)，可以大致推斷出客戶端到服務(wù)器的RTT大概是10ms （因?yàn)槲帐值腁CK一般不會(huì)延遲發(fā)送）

 

通過(guò)觀察服務(wù)端發(fā)送數(shù)據(jù)包序列號(hào)新增的圖表我們可以發(fā)現(xiàn)，以10ms為間隔基本上都是15個(gè)包一組一起發(fā)送。

幾乎大部分時(shí)間都是是一次發(fā)15個(gè)包（21900字節(jié)），雖然沒(méi)有達(dá)到65K（服務(wù)端cwnd應(yīng)該是能達(dá)到64K甚至更高，可能是鏈路中的其他網(wǎng)絡(luò)設(shè)備的窗口限制住了，畢竟這個(gè)速度運(yùn)營(yíng)商是要控制的），不過(guò)其實(shí)20K的cwnd也還是不錯(cuò)的，不應(yīng)該會(huì)成為瓶頸 。

不同的網(wǎng)絡(luò)狀態(tài)cwnd的穩(wěn)定峰值可能有差異，多的時(shí)候能會(huì)超過(guò)40K。其實(shí)這個(gè)一次發(fā)送的量直接受帶寬影響。

 

3:后面想到的就是數(shù)據(jù)包亂序，或丟包

因?yàn)闊o(wú)論是丟包還是亂序，最終都會(huì)反應(yīng)到cwnd下降，發(fā)送效率降低，不過(guò)從數(shù)據(jù)包列圖表來(lái)看并沒(méi)有發(fā)生這些情況。
為了分析丟包及亂序?qū)Y源下載的影響，實(shí)際測(cè)試的時(shí)候有意創(chuàng)造了較差網(wǎng)絡(luò)，分析了這些有很多亂序及重傳的情況，如下圖是一次有亂序的流量。（與前文中的截圖不是同一個(gè)流量數(shù)據(jù)，該圖是專門選取的網(wǎng)絡(luò)條件較差的情況）

可以明顯看出來(lái)，即使發(fā)生了丟包及亂序，TCP恢復(fù)的都非常的快，絕不會(huì)把下載速度拖到超過(guò)1s。

收多次2481的亂序包后，馬上就來(lái)了重傳包（當(dāng)然這里很可能只是遲到了的包，因?yàn)槲覀兛吹綇牡?個(gè)亂序ACK從發(fā)出到收到“重傳”只有5ms，不到一個(gè)RTT。一般發(fā)送端會(huì)在收到3個(gè)以上的重傳包以后才會(huì)認(rèn)為發(fā)生丟包，上圖中遠(yuǎn)不到一個(gè)RTT，是來(lái)不及收到第3個(gè)dup，然后再把重傳包發(fā)送到接收方的）

而且看后面報(bào)文發(fā)送的情況，而且這些亂序并沒(méi)有導(dǎo)致服務(wù)端發(fā)包的量及速率并沒(méi)有明顯下降（上面也提到了理論上cwnd應(yīng)該已經(jīng)到達(dá)了65k以上，不過(guò)實(shí)際上一次發(fā)送的量因?yàn)槠渌拗埔恢北豢刂圃?0K內(nèi)，所以即使服務(wù)端認(rèn)為自己確實(shí)發(fā)生亂序而降低cwnd，也不會(huì)影響到現(xiàn)在的發(fā)送速率）

 

確認(rèn)問(wèn)題

明確原因

反復(fù)查看了多組測(cè)試數(shù)據(jù)包，怎么看都覺(jué)得流量是正常的，鏈路上的數(shù)據(jù)包及他們的確認(rèn)包，還包括他們從異常狀態(tài)中的恢復(fù)過(guò)程都很正常，完全看不不同尋常的東西。
有的時(shí)候陷進(jìn)去了是很難拔出來(lái)的，之前一直認(rèn)為是運(yùn)維的問(wèn)題，所以竭盡全力的去尋找網(wǎng)絡(luò)上的問(wèn)題。

會(huì)不會(huì)是最開(kāi)始判斷錯(cuò)了，恍然大悟，如果網(wǎng)絡(luò)都是正常的那不可能是超過(guò)1s的傳輸時(shí)間啊，200多個(gè)包一次15個(gè)間隔大概10ms，那發(fā)送及確認(rèn)的時(shí)間絕不會(huì)超過(guò)200ms才對(duì)！
這個(gè)時(shí)候我才開(kāi)始懷疑chrome的數(shù)據(jù)（因?yàn)橹坝?jì)算TTFB的時(shí)間chrome與wireshark的時(shí)間一致，后面就再也沒(méi)有懷疑過(guò)chrome的時(shí)間，也沒(méi)有特意去對(duì)比后面的時(shí)間點(diǎn)）

如上圖是這個(gè)response最后的報(bào)文段，從最開(kāi)始發(fā)送response的第一個(gè)包（響應(yīng)的首字節(jié)）的No 1031（35.875692），到上圖的No 1374（36.045216）客戶端確認(rèn)最后一個(gè)服務(wù)端發(fā)來(lái)的數(shù)據(jù)包的時(shí)間差分明只有170ms。

其實(shí)前面的流量圖表上也有體現(xiàn)序列號(hào)都是在200ms內(nèi)加上去的，只是當(dāng)時(shí)沒(méi)有關(guān)注到 （陷入先入為主的思維里了，一開(kāi)始自己就認(rèn)定是網(wǎng)絡(luò)問(wèn)題，加上最開(kāi)始核對(duì)chrome的開(kāi)始時(shí)間及TTFB都是對(duì)的，就放松了對(duì)chrome本身的警惕）
現(xiàn)在基本上已經(jīng)可以判斷就是客戶端（chrome）方面有問(wèn)題。

 

驗(yàn)證問(wèn)題

為了驗(yàn)證這個(gè)的結(jié)論可以使用使用了常用的代理軟件（charles及fiddler）他們都會(huì)有獨(dú)立的時(shí)間線統(tǒng)計(jì)功能。

 可以看到代理上的時(shí)間明顯比chrome上顯示的時(shí)間少很多（一個(gè)162ms，一個(gè)2200ms）

 

其實(shí)到現(xiàn)在已經(jīng)可以下結(jié)論是客戶端的的問(wèn)題（前端）。不過(guò)因?yàn)檫@個(gè)請(qǐng)求其實(shí)在瀏覽器除首頁(yè)的其他場(chǎng)景或著使用其他客戶端直接請(qǐng)求下載速度都是正常的，出問(wèn)題的那次請(qǐng)求又是預(yù)加載的請(qǐng)求（同時(shí)還會(huì)有好幾個(gè)請(qǐng)求會(huì)被一起發(fā)送），所以乍一看總會(huì)覺(jué)得是網(wǎng)絡(luò)方面的問(wèn)題，當(dāng)然這個(gè)上文中的內(nèi)容已經(jīng)證明了，完全不是網(wǎng)絡(luò)的問(wèn)題。不過(guò)要讓前端同學(xué)“誠(chéng)懇”的接受這個(gè)是自己的問(wèn)題并想辦法修復(fù)它，可能還需要我們進(jìn)一步指出問(wèn)題出在了什么地方（萬(wàn)一有同學(xué)把問(wèn)題直接推給chrome那不就無(wú)解了么）。

 

通過(guò)上文的描述我們可以發(fā)現(xiàn)響應(yīng)回包已經(jīng)在200ms內(nèi)全部被客戶端socket確認(rèn)，但是chrome似乎認(rèn)為是1，2s。

通過(guò)觀察多個(gè)被chrome統(tǒng)計(jì)稱2s的流量的滑動(dòng)窗口win數(shù)值的變化，發(fā)現(xiàn)了一個(gè)共性，那就是在接受該請(qǐng)求時(shí)客戶端win的大小呈現(xiàn)出趨勢(shì)性的下降（而正常的下載時(shí)間的場(chǎng)景沒(méi)有這個(gè)趨勢(shì)）
開(kāi)始因?yàn)檫@個(gè)窗口最低也只將到了200kb，實(shí)際發(fā)送方一直在以20kb的量在傳輸，200kb的win根本不會(huì)阻塞流量，所以自己也一直沒(méi)有覺(jué)得有什么問(wèn)題，而這個(gè)趨勢(shì)實(shí)際上是不正常的，因?yàn)槠鋵?shí)數(shù)據(jù)的ACK其實(shí)很快就回復(fù)了。

那這個(gè)變化趨勢(shì)的產(chǎn)生的原因可能也是chrome里下載時(shí)間明顯變長(zhǎng)的原因。
我們知道win的窗口大小是用來(lái)告知對(duì)方當(dāng)前鏈接自己還能接受多少數(shù)據(jù)的一個(gè)標(biāo)記，服務(wù)端發(fā)送過(guò)來(lái)的數(shù)據(jù)會(huì)占用這個(gè)win，客戶端在回復(fù)ACK的時(shí)候會(huì)告知對(duì)方當(dāng)前自己的win大小，通常socket收到的數(shù)據(jù)被確認(rèn)后會(huì)馬上被應(yīng)用程序讀取，這個(gè)win會(huì)迅速恢復(fù)，不會(huì)持續(xù)下降。這里的持續(xù)下降大概率就是數(shù)據(jù)沒(méi)有被應(yīng)用層讀取。通常應(yīng)用層讀取本地socket接收緩存的速度比包在廣域網(wǎng)絡(luò)里傳輸?shù)乃俣瓤鞄讉€(gè)量級(jí)，這里大量數(shù)據(jù)沒(méi)有及時(shí)被應(yīng)用讀取，那就極可能是應(yīng)用程序自己遇到了“非常”的情況。

 

排除其他因素

到這一步可以說(shuō)是前端應(yīng)用的鍋已經(jīng)穩(wěn)了,不過(guò)為了嚴(yán)謹(jǐn)我們還要排除是統(tǒng)計(jì)問(wèn)題，會(huì)不會(huì)只是是chrome算時(shí)間算錯(cuò)了。
其實(shí)這個(gè)還是比較好確認(rèn)的，最簡(jiǎn)單的就是錄屏逐幀查看是不是要等2s的下載完成后才加載數(shù)據(jù)，當(dāng)然其實(shí)chrome的DevTools里的Performance工具可以幫我們完成分析（同時(shí)也會(huì)錄屏）

通過(guò)Performance可以看出下載那段時(shí)間是沒(méi)有渲染出數(shù)據(jù)的（其實(shí)下載完成后也還需要一段時(shí)間才能展示出數(shù)據(jù)）
chrome看起來(lái)統(tǒng)計(jì)下載時(shí)間是按應(yīng)用自己讀取時(shí)間來(lái)的，因?yàn)椤澳承碑惓?dǎo)致讀取明顯滯后，最終表現(xiàn)在網(wǎng)頁(yè)上就是下載時(shí)間超長(zhǎng)。

 

總結(jié)

應(yīng)該是前端應(yīng)用在預(yù)加載請(qǐng)求上的寫(xiě)法給chrome的執(zhí)行照成了問(wèn)題，整體上肯定是應(yīng)用代碼的問(wèn)題跑不掉了。
現(xiàn)在就需要前端同學(xué)去確定具體是什么“異常”了。

還有一個(gè)細(xì)節(jié)，因?yàn)橄螺d時(shí)間變長(zhǎng)在測(cè)試或預(yù)發(fā)環(huán)境表現(xiàn)正常，因此一開(kāi)始我按自己的經(jīng)驗(yàn)認(rèn)為是運(yùn)維的問(wèn)題（服務(wù)器，網(wǎng)絡(luò)，nginx）所以一直在試圖證明自己的錯(cuò)誤的想法，偏執(zhí)的去找數(shù)據(jù)流量的茬，同時(shí)也沒(méi)有懷疑過(guò)chrome統(tǒng)計(jì)的數(shù)據(jù)可能不是真實(shí)的網(wǎng)絡(luò)時(shí)間，導(dǎo)致整個(gè)過(guò)程花了很長(zhǎng)時(shí)間。