問題描述

我司某產品線有指定業務介面customQuery在線上環境中，與首頁一起開啟時下載資料的時間明顯過長（平均可以達到2s）

注：

• “與首頁一起開啟” 的含義是指使用者進入WEB系統後會首次載入的主頁面，該主頁會提前請求customQuery資料，以用於顯示首頁中的列表資料。
• 正常的想法會第一時間認為是剛進入首頁請求多，導致的下載速度慢，這個自然不是這個原因，要不然也不會專門寫這些內容，後面會講到。
• 下文中我會盡量僅針對問題本身，不摻雜業務邏輯進行表述，並儘可能的做到描述清晰，準確。不過個人表達力及知識儲備難免會有盲區，下文如有描述不當或有事實錯誤的地方，希望大家可以直接悉心指出。
• 這裡需要單獨說明下因為之前已經發過一篇關於customQuery請求gzip壓縮的帖子，而這裡講的是2個沒有關係的東西，不用聯絡在一起。

先直接上問題請求的截圖

如上圖323K的資料下載用了近2s，明顯是出問題了。

該介面有在資料翻頁時也會觸發，不過下載時間表現正常。（如下圖，同樣的軟硬體條件，在其他場景下，同樣的引數拉取同一個介面的情況）

上圖是翻頁的場景（因為是列表資料，預設進入開啟第一頁，也可以自己觸發翻頁到其他頁或回到第一頁），也就是說只有在首頁中被呼叫時下載時間異常，在正常TAB頁中切換翻頁資料下載表現都很正常。

還有一個細節，這個介面在測試或預發環境表現都是正常的，沒有出現下載時間過長的問題，這也從側面證明了並不是因為首頁資料量大導致下載慢，通過檢視各個整個過程的請求時間線也能明顯看出，在出問題的時間斷，並沒有很多資料資源正在傳輸。

排除服務端問題

為了排除服務端的問題，自己構建了測試程式簡單模擬了下面場景。

• 同一請求順序傳送10次，結果如下（下載時間全部保持在300ms以下）

• 以下是5個一組一起傳送的情況，可以看到下載時間基本上也是維持在了500ms以下（因為該請求其實很大，一個response有超過300kb，5個會有近2Mb，這個時候已經對頻寬有一定的壓力了，下載速度下降是正常的，而在首頁載入的場景下不會有這麼大的頻寬壓力）

通過上面的測試不難看出無論是順序傳送，或同一個客戶端同時並行請求該請求資源的情況下，下載速度都不會下降到超過1s的水平。
Chrome DevTools 裡可以看到當前瀏覽器默認同一個域名雖也是同時維持著6個http1.1連結，但除了目標介面，其他5個請求都會非常快的完成（其他響應大多小於1kb,不會佔用太多頻寬）

雖然這樣想，但是現在也只能暫時懷疑是網路方面的問題了，為了證實自己的猜想，需要分析TCP原始報文。

注：本文並不闡述如何解決問題，主要通過各種事實資料證明問題出現在哪一個點，從而將問題轉到正確的責任人。因為一般比較詭異的問題如果不能確認是問題具體是出在哪一塊（服務端，運維，前端，嵌入式），那任何一方在工作壓力已經如此大的情況下難免會本能的認為是其他人的問題，最後的結果就是，問題長時間都得不到解決。不過如果有充足是事實證據證明問題出在哪裡，那通常負責那一塊的同學還是會盡力去解決的。

排查網路問題

準備工作

為了配合Wireshark分析TCP報文我們需要使用Chrome的【Capture Network Log】直接在chrome中訪問 chrome://net-export/  即可以開啟。

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

如下圖，在把Capture Network Log啟動後，再次觸發首頁載入，DevTools顯示下載時間依然很長。

剛剛network logs裡的資料我們可以在netlog viewer裡開啟（https://netlog-viewer.appspot.com/   這是官方的線上日誌分析器，訪問這個連結您可能需要“梯子”）

如上圖我們通過Sockets及Events裡的記錄定位到我們請求的鏈路。

主要是要獲得這個鏈路的本地埠號（在Wireshark裡我們需要通過這個埠號跟蹤我們的tcp流）

當然還可以得到這個鏈路的開始時間，及耗時 （需要明確一點這個開始時間是握手開始時間，不完全等於這個請求的開始時間，而且這個連結其實也會發好幾個請求，後面會提到）

根據netlog viewer裡的資訊找到指定埠，如上圖追蹤目標流（本質是對網絡卡資料包進行過濾篩選，更容易定位問題）

如上圖，通過檢視netlog viewer 裡的SOCKET_BYTES_SENT記錄我們不難發現這個連結其實一共傳送了4次HTTP應用層請求（分別在第26ms，第119ms，第153ms，第184ms 注意這裡使用的是相對時間）
通過計算保留到秒的絕對時間分別為35.528；35.621；35.655；35.686 (實際是最後一個才是我們的目標請求，通過chrome時間線或響應的大小可以很容易的確認這個點)

如上圖，通過在指定流篩選由客戶端發出去的大小合適的資料，可以看到傳送的時間點基本上是跟前面Chrome的netlog viewer對的上去的（因為請求實際上都很小，一個報文長度內就能發完）

目標流量確認了，現在我們可以安心的去分析TCP報文了

我們只需要關注No 968 後面的報文（因為我們的目標請求是從這裡開始的），可以看到其實第一個資料回包在No 1031 （時間為：35.875）
與發出請求的那個包的時間差為189ms，這個其實就是TTFB （與chrome裡計算出的198ms也是接近的）
逐條檢視後面下載的包，看起來都很正常。
下面列出最開始在網路方向懷疑的幾個可能的點，並逐個嘗試排查。 （下一段內容主要是逐個排除自己猜測，且過程與網路傳輸強相關，如果實在不感興趣可以跳過直接看結論 ）

1:首先懷疑滑動窗持續收縮，導致後面接收效率急劇下降

 通過Wireshark提供的流圖形我們可以直觀的看到滑動視窗在整個TCP資料流裡的變化趨勢（當然在外面報文列表裡也能直接看出來）

 不過看起來當前流最差的情況滑動視窗也還有100kb （完全是夠用，事實上只要紅框處tcptrace的2條線不重合即表示滑動視窗還沒有滿）

2:而後是擁塞視窗cwnd，會不會是傳送端因為亂序或超時導致伺服器當前鏈路的cwnd下降而主動降速

因為cwnd是傳送端本地維護的，我們無法像Win視窗一樣在Wireshark裡直接看到，不過我們可以通過觀察流量包的狀態得出初步的判斷。（分析在沒有ACK確認的情況下可以傳送多少資料）
目標請求response一共323KB（服務端回我們的包一個為1460位元組）理論一共大概會回覆我們200多個包(通過過濾器我們可以準確統計出229個含有有效資料的回包，當然包括少量的TLS握手及前3個請求的回包)
如果按預設擁塞視窗閥值ssthresh取65532，最差會在第45個包左右（每個報文段都充滿的情況下）就會完成慢啟動進入擁塞避免狀態。

如上圖，通過檢視建立連結握手時收到ACK的時間點，可以大致推斷出客戶端到伺服器的RTT大概是10ms （因為握手的ACK一般不會延遲傳送）

通過觀察服務端傳送資料包序列號新增的圖表我們可以發現，以10ms為間隔基本上都是15個包一組一起傳送。

幾乎大部分時間都是是一次發15個包（21900位元組），雖然沒有達到65K（服務端cwnd應該是能達到64K甚至更高，可能是鏈路中的其他網路裝置的視窗限制住了，畢竟這個速度運營商是要控制的），不過其實20K的cwnd也還是不錯的，不應該會成為瓶頸 。

不同的網路狀態cwnd的穩定峰值可能有差異，多的時候能會超過40K。其實這個一次傳送的量直接受頻寬影響。

3:後面想到的就是資料包亂序，或丟包

因為無論是丟包還是亂序，最終都會反應到cwnd下降，傳送效率降低，不過從資料包列圖表來看並沒有發生這些情況。
為了分析丟包及亂序對資源下載的影響，實際測試的時候有意創造了較差網路，分析了這些有很多亂序及重傳的情況，如下圖是一次有亂序的流量。（與前文中的截圖不是同一個流量資料，該圖是專門選取的網路條件較差的情況）

可以明顯看出來，即使發生了丟包及亂序，TCP恢復的都非常的快，絕不會把下載速度拖到超過1s。

收多次2481的亂序包後，馬上就來了重傳包（當然這裡很可能只是遲到了的包，因為我們看到從第3個亂序ACK從發出到收到“重傳”只有5ms，不到一個RTT。一般傳送端會在收到3個以上的重傳包以後才會認為發生丟包，上圖中遠不到一個RTT，是來不及收到第3個dup，然後再把重傳包傳送到接收方的）

而且看後面報文傳送的情況，而且這些亂序並沒有導致服務端發包的量及速率並沒有明顯下降（上面也提到了理論上cwnd應該已經到達了65k以上，不過實際上一次傳送的量因為其他限制一直被控制在20K內，所以即使服務端認為自己確實發生亂序而降低cwnd，也不會影響到現在的傳送速率）

確認問題

明確原因

反覆查看了多組測試資料包，怎麼看都覺得流量是正常的，鏈路上的資料包及他們的確認包，還包括他們從異常狀態中的恢復過程都很正常，完全看不不同尋常的東西。
有的時候陷進去了是很難拔出來的，之前一直認為是運維的問題，所以竭盡全力的去尋找網路上的問題。

會不會是最開始判斷錯了，恍然大悟，如果網路都是正常的那不可能是超過1s的傳輸時間啊，200多個包一次15個間隔大概10ms，那傳送及確認的時間絕不會超過200ms才對！
這個時候我才開始懷疑chrome的資料（因為之前計算TTFB的時間chrome與wireshark的時間一致，後面就再也沒有懷疑過chrome的時間，也沒有特意去對比後面的時間點）

如上圖是這個response最後的報文段，從最開始傳送response的第一個包（響應的首位元組）的No 1031（35.875692），到上圖的No 1374（36.045216）客戶端確認最後一個服務端發來的資料包的時間差分明只有170ms。

其實前面的流量圖表上也有體現序列號都是在200ms內加上去的，只是當時沒有關注到 （陷入先入為主的思維裡了，一開始自己就認定是網路問題，加上最開始核對chrome的開始時間及TTFB都是對的，就放鬆了對chrome本身的警惕）
現在基本上已經可以判斷就是客戶端（chrome）方面有問題。

驗證問題

為了驗證這個的結論可以使用使用了常用的代理軟體（charles及fiddler）他們都會有獨立的時間線統計功能。

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

其實到現在已經可以下結論是客戶端的的問題（前端）。不過因為這個請求其實在瀏覽器除首頁的其他場景或著使用其他客戶端直接請求下載速度都是正常的，出問題的那次請求又是預載入的請求（同時還會有好幾個請求會被一起傳送），所以乍一看總會覺得是網路方面的問題，當然這個上文中的內容已經證明了，完全不是網路的問題。不過要讓前端同學“誠懇”的接受這個是自己的問題並想辦法修復它，可能還需要我們進一步指出問題出在了什麼地方（萬一有同學把問題直接推給chrome那不就無解了麼）。

通過上文的描述我們可以發現響應回包已經在200ms內全部被客戶端socket確認，但是chrome似乎認為是1，2s。

通過觀察多個被chrome統計稱2s的流量的滑動視窗win數值的變化，發現了一個共性，那就是在接受該請求時客戶端win的大小呈現出趨勢性的下降（而正常的下載時間的場景沒有這個趨勢）
開始因為這個視窗最低也只將到了200kb，實際傳送方一直在以20kb的量在傳輸，200kb的win根本不會阻塞流量，所以自己也一直沒有覺得有什麼問題，而這個趨勢實際上是不正常的，因為其實資料的ACK其實很快就回復了。

那這個變化趨勢的產生的原因可能也是chrome裡下載時間明顯變長的原因。
我們知道win的視窗大小是用來告知對方當前連結自己還能接受多少資料的一個標記，服務端傳送過來的資料會佔用這個win，客戶端在回覆ACK的時候會告知對方當前自己的win大小，通常socket收到的資料被確認後會馬上被應用程式讀取，這個win會迅速恢復，不會持續下降。這裡的持續下降大概率就是資料沒有被應用層讀取。通常應用層讀取本地socket接收快取的速度比包在廣域網路裡傳輸的速度快幾個量級，這裡大量資料沒有及時被應用讀取，那就極可能是應用程式自己遇到了“非常”的情況。

排除其他因素

到這一步可以說是前端應用的鍋已經穩了,不過為了嚴謹我們還要排除是統計問題，會不會只是是chrome算時間算錯了。
其實這個還是比較好確認的，最簡單的就是錄屏逐幀檢視是不是要等2s的下載完成後才載入資料，當然其實chrome的DevTools裡的Performance工具可以幫我們完成分析（同時也會錄屏）

通過Performance可以看出下載那段時間是沒有渲染出資料的（其實下載完成後也還需要一段時間才能展示出資料）
chrome看起來統計下載時間是按應用自己讀取時間來的，因為“某些”異常導致讀取明顯滯後，最終表現在網頁上就是下載時間超長。

總結

應該是前端應用在預載入請求上的寫法給chrome的執行照成了問題，整體上肯定是應用程式碼的問題跑不掉了。
現在就需要前端同學去確定具體是什麼“異常”了。

還有一個細節，因為下載時間變長在測試或預發環境表現正常，因此一開始我按自己的經驗認為是運維的問題（伺服器，網路，nginx）所以一直在試圖證明自己的錯誤的想法，偏執的去找資料流量的茬，同時也沒有懷疑過chrome統計的資料可能不是真實的網路時間，導致整個過程花了很長時間。