作者：懷知
對於雲上的用戶來說，業務日誌裡面報超時問題處理起來往往比價棘手，因為1) 問題點可能在雲基礎設施層，也有可能在業務軟件層，需要排查的範圍非常廣；2) 這類問題往往是不可復現問題，抓到現場比較難。在本文裡就分析下如何來分辨和排查這類問題的根本原因。
業務超時 != 網絡丟包
由於業務的形態不同，軟件實現語言和框架的不同，業務日誌中打印出的信息可能是各不相同，比如如下關鍵字：
"SocketTimeOut", "Read timed out", "Request timeout" 等
從形式看都屬於網絡超時這一類，但是需要明確一個概念：這類問題是發生的原因是請求超過了設定的timeout時間，這個設置有可能來自客戶端，服務器端或者網絡中間節點，這是直接原因。網絡丟包可能會導致超時，但是並不是充分條件。總結業務超時和網絡丟包的關係如下：
網絡丟包可能造成業務超時，但是業務超時的原因不一定是丟包。
明確了這個因果關係後，我們再來看怎麼分析業務超時。如果武斷地將業務超時等同於網絡抖動丟包，那這個排查分析過程就完全錯過了業務軟件層本身的原因，很容易進入困局。
本文會從雲基礎設施層和業務軟件層對業務超時做分析，總體來講基礎設置層面的丟包原因相對容易排查，阿里雲有完善的底層監控，根據業務日誌報錯的對應時間段，從監控數據中可以確定是否有基礎設施網絡問題。而業務層的超時通常是軟件層面的設置，和軟件實現及業務形態都有關係，這種往往是更加難以排查的。
網絡丟包為什麼導致業務超時
網絡抖動可能造成業務超時，其主要原因是網絡抖動會帶來不同程度的延遲。本文以互聯網大部分應用以來的TCP為對象來介紹，一個丟包對數據傳輸的完整性其實是沒有影響的，因為TCP協議本身已經有精密的設計來處理丟包，亂序等異常情況。並且所有重傳的處理都在內核TCP協議棧中完成，操作系統用戶空間的進程對這個處理實際上是不感知的。丟包唯一的副作用的就是會增加延遲，如果這段延遲的時間足夠長，達到了應用進程設置的某個Timeout時間，那麼在業務應用側表現出來的就是業務超時。
丟包出現時會不會發生超時，取決於應用進程的Timeout設置。比如數據傳輸中的只丟了一個TCP數據包，引發200 ms後的超時重傳：
- 如果應用設置的Timeout為100 ms，TCP協議棧沒有機會重傳，應用就認為超時並關閉連接；
- 如果應用設置的Timeout為500 ms，則TCP協議棧會完成重傳，這個處理過程對應用進程透明。應用唯一的感知就是處理這次報文交互比基線處理時長多了200 ms，對於時間敏感度不是非常高的應用來說這個影響非常小。
延遲到底有多大？
在設置應用進程Timeout時間時有沒有可以參考的定量值呢？雖然TCP中的RTT/RTO都是動態變化的，但TCP丟包的產生的影響可以做一定的定量總結。
對丟包產生的延遲主要有如下兩類：
- TCP建連超時。如果網絡抖動不幸丟掉了TCP的第一個建連SYN報文，對與不太老的內核版本來說，客戶端會在1秒(Draft RFC 2988bis-02中定義)後重傳SYN報文再次發起建連。1秒對於內網環境來說非常大，對於阿里雲一個區域的機房來說，正常的RTT都是小個位數毫秒級別，1秒內如果沒有丟包足夠完成百個數據報的交互。
- TCP中間數據包丟包。TCP協議處理中間的數據丟包有快速重傳和超時重傳兩種機制。快速重傳通常比較快，和RTT相關，沒有定量的值。超時重傳 (RTO, Retrasmission Timeout) 也和RTT相關，但是Linux中定義的RTO的最小值為，TCP_RTO_MIN = 200ms。所以在RTT比較小的網絡環境下，即使RTT小於1ms，TCP超時重傳的RTO最小值也只能是200ms。這類丟包帶來的延遲相對小。
除了丟包，另外一類比較常見的延遲是TCP Delayed ACK帶來的延遲。這個和協議設計相關，和丟包其實沒有關係，在這裡一併總結如延遲定量部分。在交互式數據流+Nagle算法的場景下比較容易觸發。Linux中定義的Delayed ACK的最小值TCP_DELACK_MIN是40 ms。
所以總結下來有如下幾個定量時間可以供參考：
- 40 ms, 在交互數據流中TCP Delayed ACK + Nagle算法開啟的場景，最小delay值。
- 200 ms，在RTT比較小的正常網絡環境中，TCP數據包丟包，超時重傳的最小值。
- 1 s，較新內核版本(>=3.1)TCP建立的第一個SYN包丟包時的重傳時間，RFC2988bis中定義的initial RTO value TCP_TIMEOUT_INIT。
- 3 s, 較老內核版本(<3.1)TCP建立的第一個SYN包丟包時的重傳時間，RFC 1122中定義的initial RTO value TCP_TIMEOUT_INIT。
雲基礎設施網絡丟包
基礎設施網絡丟包的原因可能有多種，主要總結如下3類：
雲基礎設施網絡抖動
網絡鏈路，物理網絡設備，ECS/RDS等所在的宿主機虛擬化網絡都有可能出現軟硬件問題。雲基礎設施已經做了完備的冗餘，來保證出現問題時能快速隔離，切換和恢復。
現象: 因為有網絡冗餘設備並可以快速恢復，這類問題通常表現為某單一時間點網絡抖動，通常為秒級。抖動的具體現象是在那個時段新建連接失敗，已建立的連接中斷，在業務上可能表現為超時。
影響面: 網絡設備下通常掛很多主機，通常影響面比較大，比如同時影響多個ECS到RDS的連接。
雲產品的限速丟包
很多網絡雲產品在售賣的時候有規格和帶寬選項，比如ECS, SLB, NAT網關等。當雲產品的流量或者連接數超過規格或者帶寬限制時，也會出現丟包。這種丟包並非雲廠商的故障，而是實際業務流量規模和選擇雲產品規格時的偏差所帶來。這種問題通常從雲產品提供的監控中就能分辨出來。
現象: 當流量或者連接數超過規格時，出現流量或者連接丟棄。問題可能間斷並持續地出現，網絡流量高峰期出現的概率更大。
影響面: 通常隻影響單一實例。但對於NAT網關做SNAT的場景，可能影響SNAT後的多個實例。
運營商網絡問題
在走公網的場景中，客戶端和服務器之間的報文交互往往要經過多個AS (autonomous system)。若運營商中間鏈路出現問題往往會導致端到端丟包。
現象: 用雙向mtr可以看到在鏈路中間某跳開始丟包。
影響面: 影響面可能較大，可能影響經過某AS鏈路的報文交互。但是對於單用戶來說看到的影響通常只是對特定實例。
應用設置的Timeout引發的超時
上面分析了幾種基礎設施因為異常或限速等原因丟包導致應用超時的情況，總體來說只要能找出丟包點，就基本能找出根因。但有些情況下，各種網絡監控表明並沒有任何丟包跡象，這個時候就要從應用側面來繼續排查下了。因為應用的形態多樣，下面以兩個典型例子來說明為什麼在沒有網絡丟包的情況下也會出現業務日誌中的超時。
ECS雲主機訪問第三方API超時的例子
問題現象
用戶雲上ECS服務器需要通過HTTP協議訪問第三方服務器的API，但是發現業務日誌中時不時出現訪問第三方API時的"Request timeout"報錯，需要查出根因。
排查思路
根據基本思路，先從監控中查看ECS實例及鏈路有沒有丟包。結果發現並沒有能和業務日誌中出現timeout報錯時間點吻合的丟包。
在這種情況下，只能進一步利用問題復現時的抓包來一探究竟了。
抓包分析
拿到抓包後，可以通過Wireshark的“分析-專家信息”或者如下表達式來過濾是否有重傳。
tcp.analysis.retransmission
結果確實沒有看到任何一個丟包，這個也反證了該問題並非由丟包引起。如果不是丟包引起，那為什麼會產生問題呢？這時候需要進一步來分析抓包。
我們可以注意到：在業務日誌裡其實有"Request Timeout"這樣的關鍵字，從字面理解就是往外的HTTP請求超時。用HTTP協議的話來說，可以翻譯成：“HTTP請求已經發給對端，但是在一段時間內對端並沒有返回完整的響應”。沿著這個思路，我們可以看下報文裡是否存在只有HTTP請求而沒有HTTP響應的情況。在Wireshark裡，可以用如下方法過濾沒有HTTP響應的HTTP請求：
http.request.method == GET && !http.response_in
果然，我們發現了一些這樣的HTTP請求。選擇其中的一個HTTP請求，然後跟一下TCP stream看下報文交互的全過程如下：
根據抓包會有如下一些發現：
- TCP stream中可以看到一個TCP連接上有2個HTTP請求，所以ECS訪問第三方API是用的長連接。
- 第一次HTTP GET請求(735號包)，在65 ms後返回(778號包)。
- 第二次HTTP GET請求(780號包)沒有對應的HTTP響應返回 (我們正是通過這個條件過濾的報文)。
- 第954號包，客戶端沒等收到HTTP響應就主動FIN掉了TCP連接。這是個很異常的行為，並且是客戶端發起的。仔細觀察FIN和第二個HTTP GET請求發出的時間間隔，發現大約300 ms。接著查看其他沒有響應的HTTP stream，這個時間間隔大約300 ms。
至此我們有理由推斷是ECS服務器在對第三方API發出HTTP請求300 ms後主動FIN掉了TCP連接。這可能是程序中客戶端設置的超時時間，業務程序超時後可能有自己的重試邏輯。
用戶最後確認了業務軟件中有該超時設置。
問題總結
1) 那這個300 ms的超時時間設置是否合理呢？
從抓包中可以看出，ECS對端API服務器的RTT大約7 ms左右，推斷是一個同城的訪問。對於個位數毫秒級別的RTT，300 ms的超時時間其實已經有一定餘量了，並且甚至可能可以允許一次超時重傳(200 ms)。
2) 問題的根因？
該問題主要是由於對端API服務器處理請求的速度不穩定造成。有些請求在幾十毫秒內就處理返回完，有些300 ms都沒有處理完。這個不穩定可能和API服務器的資源水位和壓力相關，但是這個是黑盒，需要對端分析了。
3) 解決方案
1> 最佳解決方案是聯繫對端API服務器的owner找到根因並根除。
2> 臨時解決方案是調整增大ECS上設置的客戶端超時時間。
ECS內網訪問自建Redis超時的例子
ECS訪問雲服務RDS/Cache或者自建數據庫/Cache超時是另外一類問題，下面用一個ECS內網訪問字節Redis超時來說明這類問題。
問題現象
ECS上用Redis客戶端Jedis訪問自建在ECS上的Redis服務器，偶爾會出現如下報錯：
redis.clients.jedis.exceptions.JedisConnectionException: java.Net.SocketTimeoutException: Read timed out
排查思路
這類問題很常見的原因是Redis慢查詢，用戶自查了Redis的大key和慢查詢情況，沒有發現時間特別長的查詢。所以需要在網絡層面進一步確認。
根據基本思路，先從監控中查看ECS實例及鏈路有沒有丟包。結果發現並沒有能和"Read timed out"報錯時間點吻合的丟包。
進一步利用問題復現時的抓包來一探究竟了。因為問題偶發，需要在客戶端利用tcpdump -C -W參數部署循環抓包，問題出現後停止循環抓包來查看。
抓包分析
拿到抓包後，同樣先看有沒有丟包重傳，結果是沒有發現丟包重傳。和上一個例子不同，這個例子沒有辦法通過一定特徵來過濾數據包。所以只能根據Jedis日誌報錯的時間點找到對應包的位置來進一步看有沒有什麼線索。
根據Jedis日誌報錯的時間點找到對應的報文，跟TCP stream看下報文交互的全過程如下(Jedis客戶端是9.20，Redis服務器端是20.66)：
根據抓包有如下一些發現：
- 可以看到中間沒有重傳，網絡上看起來是正常的。
- 客戶端利用長連接訪問服務器端，在結束連接之前已經包了非常多的Redis請求和響應。
- 181073 號包是服務器端FIN掉了連接，181078號包客戶端接著發了TCP Reset。
上面這些信息量顯然是不夠說明為什麼有"Read timed out"的報錯。最後一個從客戶端發起的TCP Reset可能會是干擾項，可以看到這個TCP Reset是在收到服務器端的FIN而發出的。對於正常TCP四次回收結束連接的過程，客戶端在收到服務器的FIN後應該也發送個FIN給服務器結束連接。但是TCP有個Linger選項，可以控制這個行為，設置了Linger選項後可以讓客戶端直接回Reset，這樣可以讓雙方快速關閉這組socket, 避免主動關閉放進入長達60秒的TIME_WAIT狀態。看起來是客戶端的Linger設置造成的，搜了下Jedis代碼，在Connection.java (如下)裡果然有這個設置，這樣就能結束為什麼客戶端Reset掉TCP連接，這個行為是符合邏輯的。
socket = new Socket();
socket.setReuseAddress(true);
socket.setKeepAlive(true); // Will monitor the TCP connection is valid
socket.setTcpNoDelay(true); // Socket buffer Whether closed, to ensure timely delivery of data
socket.setSoLinger(true, 0); // Control calls close () method, the underlying socket is closed immediately接著來看報文交互中的Redis命令是否正常。跟蹤TCP stream可以看到ASCII形式的數據，如下：
可以看到客戶端發了DEL命令後，又發了QUIT命令，可以對照報文看下。
- 客戶端在181061號包發出了DEL命令。
- 在3.9 ms後收到了Redis服務器的ACK，注意這只是個ACK包，報文長度是0，說明沒帶任何payload數據。
- 第181070號包，客戶端又發出了QUIT命令，注意這個包和DEL命令的包相差間隔時間大概200 ms。Quit命令用於關閉與當前客戶端與Redis服務器的連接，一旦所有等待中的回覆(如果有的話)順利寫入到客戶端，連接就會被關閉。
- 第181072號包，也就是在QUIT命令發出161 ms後，Redis服務器端回覆了":1"和"+OK"。其中":1"響應DEL命令，"+OK"響應QUIT命令。
- 第181073號包，Redis用FIN報文結束了這個TCP長連接。
如上所述，這個連接被中斷的關鍵點是客戶端給Redis服務器發送了QUIT命令，至於為什麼要發QUIT，並且是之前命令發出後200 ms沒返回時發送QUIT，很有可能是有超時設置。查看另外幾個TCP stream, 基本上都是以類似的模式結束了TCP長連接，基本上可以下這個結論了。
這個案例和第一個案例很類似，不同之點是在抓包裡我們無法看到在超時時間過後客戶端直接FIN掉連接，而是發了Redis QUIT命令，最終等到前面的命令執行完後才關閉連接。相比較第一種，這是一種更優雅的方法，前提是因為Redis存在QUIT命令，並且Jedis內化了這個操作。這個案例更清晰地說明了具體業務對連接行為的影響，需要利用報文來反推Redis客戶端和服務器交互的行為。
總結
本文介紹了業務日誌裡面報超時問題處理起來需要考慮的兩個層面：雲基礎設施層和業務軟件層。有相當一部分的問題可能由於基礎設施的網絡丟包引起，通過網絡監控和網絡產品的雲監控定位丟包點很重要，注意不要把業務超時等同於丟包；另一類業務軟件層Timeout設置導致的超時，發生比例相對少，但需要更廣泛的排查，並且不要輕易忽略了這類原因導致的超時。
