# 解Bug之路-記一次對端機器宕機後的tcp行為 ## 前言 機器一般過質保之後，就會因為各種各樣的問題而宕機。而這一次的宕機，讓筆者觀察到了平常觀察不到的tcp在對端宕機情況下的行為。經過詳細跟蹤分析原因之後，發現可以通過調整核心tcp引數來減少宕機造成的影響。 ## Bug現場 筆者所在的公司用某個中介軟體的古老版本做訊息轉發，此中介軟體在線上執行有些年頭了，大約剛開始部署的時候機器還是全新的，現在都已經過保了。機器的宕機導致了一些詭異的現象。如下圖所示:  在中介軟體所在機器宕機之後，出現了呼叫中介軟體超時的現象。拋開各種業務細節，會發現出現了時間很長的超時。其中一波在821s之後報出了Connection reset異常，還有一波在940s之後報出了Connection timed out(Read failed)異常。 ## 線索追查 發現出bug的時間點很微妙,有將近10個請求是在22:32:22.300左右集中報錯，並且這個時間點有Connection reset。 另一波是在22:34.11.450左右集中報錯,並且這個時間點由Connection timed out(Read failed)。 於是筆者看了下此中介軟體client的網路模型,如下圖所示:  這就很容易理解，為何請求為何都是在同一時刻超時，因為是順序請求，後面的幾個請求還沒傳送出去，就由於第一個請求超時而導致後面的所有請求報錯。如下圖所示:  進一步推出，真正的socket超時時間是請求1(最長)的超時時間。 即對應 ``` Connection reset的821s Connection timed out(Read failed)的940s ``` ### client設定了socket.soTimeOut為0 這個中介軟體採用了bio模型，並且socket沒有設定超時時間，其業務超時時間通過業務層的future來控制。但是這個超時時間只有在真正傳送請求的時間起作用，每個請求之前還會有其它的一段互動，如下圖所示:  至此，問題原因已經很明顯了，在(do something)的那個過程由於socket設定soTimeOut為0，導致卡住了相當長的一段時間。程式碼如下圖所示: ``` ..... protected int soTimeout; ...... protected void initialiseSocket(Socket sock) throws SocketException, IllegalArgumentException { ...... // 預設是0 sock.setSoTimeout(soTimeout); ...... } ``` ### socket設定soTimeOut為0的表現 問題本身的查詢是比較簡單的，如果僅僅只有這些的話，筆者也不會將其寫成一篇部落格。 由於socket設定timeout(>0)是一種常識，很少遇到設定為0的情況。於是其引起的現象引起了筆者的興趣。我們看看socket設定timeout為0後jdk原始碼的描述: ``` /** * ...... * A timeout of zero is interpreted as an infinite timeout. * ...... */ public synchronized void setSoTimeout(int timeout) throws SocketException { if (isClosed()) throw new SocketException("Socket is closed"); if (timeout < 0) throw new IllegalArgumentException("timeout can't be negative"); getImpl().setOption(SocketOptions.SO_TIMEOUT, new Integer(timeout)); } ``` 裡面有這麼一段話 ``` A timeout of zero is interpreted as an infinite timeout ``` 按上述字母解釋為如果設定為0的話，應該是等待無限長的時間(直到程序重啟)。 可是按照線上業務的表現，確是有超時時間的，只不過時間很長。最長的達到了940s，即15分鐘多。 這就引起了筆者的興趣，到底是什麼讓這個無限的超時時間被打斷呢？我們繼續分析。 ## Connection reset 首先我們聚焦於第一個異常報錯Connection reset(22:32分), 筆者本身閱讀過tcp協議棧原始碼，知道基本上所有Connection reset都由對端發出。所以筆者料定在22:32分的時候，機器肯定又活過來了，但是對應的中介軟體程序確沒有起來，所以沒有對應的埠，進而當包過來的時候，傳送tcp reset包回去(即使當前中介軟體起來了也會發送reset,因為tcp本身的seq序列號校驗失敗)。如下圖所示:  然後瞭解到在22:32左右，為了拷貝宿主機內部的訊息記錄，運維確實將宕掉的機器重新給拉起來了，這進一步印證了我的想法。但是按照筆者的推論，在22:32分新發出重傳的所有的請求都被Connection reset了，為何在將近兩分鐘之後(準確的說是在1分49s之後由又報了一波錯？)繼續往下分析。 (注意22:32分和22:34分報錯的是不同的socket連線) ## Connection timed out(Read failed) 這個錯誤很少遇到。不知道是在哪種情況下觸發。具體的異常棧為: ``` Caused by: java.net.SocketException: Connection timed out(Read failed) at java.net.SocketInputStream.socketRead0(Native Method) ~[?1.8.0_121] at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) ~[?:1.8.0_121] ...... ``` 於是用sublime搜尋Connection timed out,發現其只在Java\_java\_net\_PlainSocketImpl\_socketConnect出現，和上面的異常棧明顯不符合。 那麼就從socketRead0入手，我們詳細看看原始碼: ``` JNIEXPORT jint JNICALL Java_java_net_SocketInputStream_socketRead0(JNIEnv *env, jobject this, jobject fdObj, jbyteArray data, jint off, jint len, jint timeout) { ...... nread = NET_Read(fd, bufP, len); if (nread <= 0) { if (nread < 0) { switch (errno) { case ECONNRESET: case EPIPE: JNU_ThrowByName(env, "sun/net/ConnectionResetException", "Connection reset"); break; case EBADF: JNU_ThrowByName(env, JNU_JAVANETPKG "SocketException", "Socket closed"); break; case EINTR: JNU_ThrowByName(env, JNU_JAVAIOPKG "InterruptedIOException", "Operation interrupted"); break; default: NET_ThrowByNameWithLastError(env, JNU_JAVANETPKG "SocketException", "Read failed"); } } } ...... } ``` 答案就在NET\_ThrowByNameWithLastError裡面，其最後呼叫的是os::stderr來獲取kernel返回的error字串。 查了下linux stderr手冊，發現是ETIMEDOUT對應了Connection timed out。 但是後面的Connection timed out(Read failed)中的(Read failed)不應該拼接在後面，因為其邏輯是kernel返回error就用kernel的error,否則用defaultDetail即(Read failed和errno的組合)。具體原因，筆者並沒有在openJdk原始碼中找到，猜測可能是版本的原因或者oracleJdk和openJdk之間細微的差別。 ## ETIMEDOUT 既然是linux kernel返回的，筆者就立馬翻了linux原始碼。 (這其中有個插曲，就是筆者一開始看的是2.6.24核心原始碼，發現怎麼計算都對不上資料。後來看到線上用的是2.6.32核心版本，翻了對應版本的原始碼，才搞定) 既然是sockRead0返回的，那肯定不是socket建立連線階段(SYN)，肯定到了establish的send/rcv階段。這個錯誤最有可能就是在重傳失敗的時候返回的錯誤。於是翻了下重傳的原始碼: ``` static void tcp_retransmit_timer(struct sock *sk) { ...... // 檢查當前重傳是否已經超過最大時間 if (tcp_write_timeout(sk)) goto out; ...... icsk->icsk_backoff++; icsk->icsk_retransmits++; out_reset_timer: // 重新重傳定時器，rto最大為TCP_RTO_MAX即為120s icsk->icsk_rto = min(icsk->icsk_rto << 1, TCP_RTO_MAX); inet_csk_reset_xmit_timer(sk, ICSK_TIME_RETRANS, icsk->icsk_rto, TCP_RTO_MAX); if (retransmits_timed_out(sk, sysctl_tcp_retries1 + 1)) __sk_dst_reset(sk); } ``` 上面邏輯是首先判定是否超時，如果未超時則設定下一個超時時間。邏輯如下圖所示：  我們再看下tcp\_write\_timeout: ``` static int tcp_write_timeout(struct sock *sk){ ... // 對SYN，即建立連線過程中的處理 ... // retry即使kernel中的tcp_retries2 // 即cat /proc/sys/net/ipv4/tcp_retries2即是15 retry_until = sysctl_tcp_retries2; // 下面就是超時判斷的過程 if (retransmits_timed_out(sk, retry_until)) { /* Has it gone just too far? */ // 如果超過最大時間，則呼叫tcp_write_err tcp_write_err(sk); return 1; } return 0; } ``` tcp\_write\_err確實返回了ETIMEDOUT,如下面原始碼所示: ``` static void tcp_write_err(struct sock *sk) { sk->sk_err = sk->sk_err_soft ? : ETIMEDOUT; // 返回ETIMEDOUT sk->sk_error_report(sk); tcp_done(sk); NET_INC_STATS_BH(sock_net(sk), LINUX_MIB_TCPABORTONTIMEOUT); } ``` 至此，基本可以判定就是tcp\_write\_timeout超時了，也即其中的 retransmits\_timed\_out判定超時。 很明顯為什麼940s的時候沒有Connection reset，就是由於先判斷了tcp\_write\_timeout超時導致沒有傳送下一個重傳包，而直接time\_out,如果發了，那就是Connection reset。 ## retransmits\_timed\_out的計算過程 這個計算過程直接上原始碼: ``` static inline bool retransmits_timed_out(struct sock *sk, unsigned int boundary) { unsigned int timeout, linear_backoff_thresh; unsigned int start_ts; if (!inet_csk(sk)->icsk_retransmits) return false; if (unlikely(!tcp_sk(sk)->retrans_stamp)) start_ts = TCP_SKB_CB(tcp_write_queue_head(sk))->when; else start_ts = tcp_sk(sk)->retrans_stamp; linear_backoff_thresh = (TCP_RTO_MAX/TCP_RTO_MIN); if (boundary <= linear_backoff_thresh) timeout = ((2 << boundary) - 1) * TCP_RTO_MIN; else timeout = ((2 << linear_backoff_thresh) - 1) * TCP_RTO_MIN + (boundary - linear_backoff_thresh) * TCP_RTO_MAX; return (tcp_time_stamp - start_ts) >= timeout; } ``` 上述原始碼中,boundary = 15，那麼 TCP\_RTO\_MAX=120s,TCP\_RTO\_MIN=200ms linear\_backoff\_thresh = ilog2(120s/200ms)=ilog2(600)=ilog2(1001011000二進位制),ilog的實現為: ``` #define ilog2(n) ( \ __builtin_constant_p(n) ? ( \ (n) < 1 ? ____ilog2_NaN() : \ (n) & (1ULL << 63) ? 63 : \ ...... (n) & (1ULL << 9) ? 9 : \ /* 即(1001011000 & 1000000000)=1=>返回9 */ ...... ) ``` 由於boundary=15 > linear\_backoff\_thresh(9)所以，計算超時時間為: timeout = ((2 << linear\_backoff\_thresh) - 1) * TCP\_RTO\_MIN +(boundary - linear\_backoff\_thresh) * TCP_RTO_MAX; 即(TCP\_RTO\_MIN=200ms,TCP\_RTO\_MAX=120s) timeout = ((2 << 9 - 1) * 0.2s + (15 - 9) * 120s=924.6s 值得注意的是，由上面的程式碼邏輯，我們tcp\_retries=15指的並不是重傳15次，而是在rto初始值為200ms的情況下計算一個最終超時時間，實際重傳次數和15並沒有直接的關係。 ## 重傳最終超時的上下界 ### 重傳最終超時的下界 由上面的計算可知, 即在重傳後的tcp\_time\_stamp（當前時間戳）- start\_ts(第一次重傳時間戳)>=924.6s的時候,即丟擲異常，那麼重傳最終超時的下界就是924.6s，如下圖所示:  ### 重傳最終超時的上界 我們假設在第N次的時候tcp\_time\_stamp - start\_ts=924.5999s時候進行超時判定，那麼勢必會進行下一次重傳，並在924.5999+120=1044.5999s後超時，如下圖所示:  那麼，重傳最終超時的上界就是1044.6s 最終結論: ``` 重傳最終超時的上下界是: [924.6,1044.6] ``` ## 用不同的rto計算下最終超時 由上面程式碼可知，重傳rto是不停的*2,一直到TCP\_RTO\_MAX(120s)為止,閱讀linux程式碼可知,在筆者的線上情況下,初始rto=srtt>>3 + rttvar(TCP\_RTO\_MIN)(當然了，實際比這個複雜的多,計算暫以TCP\_RTO\_MIN代替),即初始rto=200ms+(一個計算出來的值) 筆者寫了個模擬程式: ``` public class RetransSimulate { public static void timeOutCaclulate(double rto) { double initialRto = rto; double sum = 0; while (true) { sum += rto; if (sum > 924600) { break; } rto = rto * 2; rto = rto < 120000 ? rto : 120000; } // 以50ms作為誤差 if(Math.abs(sum - 939997) < 50){ System.out.println("rto="+initialRto+",timeout=" + sum); System.out.println(); } } public static void main(String[] args) { // rtt > 3 + rttval(這個計算有點複雜，這邊可以直接用TCP_RTO_MIN做計算) // 以0.01ms為精度 double rto = 0.01 + 200;// 0.01 for random rtt > 3（初始擾動）,200 for TCP_RTO_MIN // 最多計算到300 for (int i = 0; i < 10000; i++) { timeOutCaclulate(rto); rto += 0.01 ; } } } ``` 發現距離線上真實表現超時時間最近的是: ``` rto=215.00999999998635,timeout=939955.229999986 rto=215.01999999998634,timeout=939965.459999986 rto=215.02999999998633,timeout=939975.689999986 rto=215.03999999998632,timeout=939985.919999986 rto=215.0499999999863,timeout=939996.1499999859 rto=215.0599999999863,timeout=940006.3799999859 rto=215.0699999999863,timeout=940016.609999986 rto=215.07999999998628,timeout=940026.839999986 ``` 這樣，基本就能基本確定在宕機的時候，用的rto是215了 題外話: 之前部落格裡面筆者想當然的將rto認為成rtt，導致之前的模擬程式在rto的初始值沒有加上200ms,我們同事在復現現場的時候，發現第一次重傳包確實是200ms左右，和筆者的推理並不一樣。 使得筆者重新閱讀了rto原始碼，發現其rto初始就要加上TCP\_RTO\_MIN(其實是rttvar,細節有點複雜,在此略過不表),感謝那位同事，也向之前閱讀過筆者此篇部落格的人道歉,筆者犯了想當然的毛病。 ## 機器響應的時間視窗 由於到了800s/900s的時候，肯定已經到了TCP\_RTO\_MAX(120s),所以我們可以根據兩個socket的報錯時間計算一下機器響應的時間視窗。在這裡為了簡便分析，我們忽略包在網路中的最長存活時間,如下圖所示:  即機器開始應答的時間應該在22:32:11至22:32:22之間。 當然了，很難獲取到機器真正開始應答的精確時間來證實筆者的計算。但是這個計算的意義在於如果兩者的應答視窗沒有交疊，那麼筆者的上述推論就是錯的，需要推倒重來。存在這個時間視窗，可以讓筆者的推測在邏輯上自洽。 ## 後續改進 將tcp\_retries2減少。soTimeOut在這個中介軟體client程式碼裡面由於其它問題不建議設定。 ## 總結 機器宕機雖然不討人喜歡，但是觀察宕機後線上的種種表現可是一次難得機會，能夠發現平時注意不到的坑。另外，定量分析其實蠻有意思的，尤其是種種資料都對上的時刻，挺有成就感^_^。 ## 公眾號 關注筆者公眾號，獲取更多幹貨文章: