Categories
程式開發

解Bug之路-記一次對端機器宕機後的tcp行為


前言

機器一般過質保之後,就會因為各種各樣的問題而宕機。 而這一次的宕機,讓筆者觀察到了平常觀察不到的tcp在對端宕機情況下的行為。 經過詳細跟踪分析原因之後,發現可以通過調整內核tcp參數來減少宕機造成的影響。

Bug現場

筆者所在的公司用某個中間件的古老版本做消息轉發,此中間件在線上運行有些年頭了,大約剛開始部署的時候機器還是全新的,現在都已經過保了。 機器的宕機導致了一些詭異的現象。 如下圖所示:

解Bug之路-記一次對端機器宕機後的tcp行為 1

在中間件所在機器宕機之後,出現了調用中間件超時的現象。 拋開各種業務細節,會發現出現了時間很長的超時。 其中一波在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的網絡模型,如下圖所示:

解Bug之路-記一次對端機器宕機後的tcp行為 2

這就很容易理解,為何請求為何都是在同一時刻超時,因為是順序請求,後面的幾個請求還沒發送出去,就由於第一個請求超時而導致後面的所有請求報錯。 如下圖所示:

解Bug之路-記一次對端機器宕機後的tcp行為 3

進一步推出,真正的socket超時時間是請求1(最長)的超時時間。

即對應

Connection reset的821s
Connection timed out(Read failed)的940s

client設置了socket.soTimeOut為0

這個中間件採用了bio模型,並且socket沒有設置超時時間,其業務超時時間通過業務層的future來控制。 但是這個超時時間只有在真正發送請求的時間起作用,每個請求之前還會有其它的一段交互,如下圖所示:

解Bug之路-記一次對端機器宕機後的tcp行為 4

至此,問題原因已經很明顯了,在(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(22:32分), 筆者本身閱讀過tcp協議棧源碼,知道基本上所有Connection reset都由對端發出。 所以筆者料定在22:32分的時候,機器肯定又活過來了,但是對應的中間件進程確沒有起來,所以沒有對應的端口,進而當包過來的時候,發送tcp reset包回去(即使當前中間件起來了也會發送reset,因為tcp本身的seq序列號校驗失敗)。 如下圖所示:

解Bug之路-記一次對端機器宕機後的tcp行為 5

然後了解到在22:32左右,為了拷貝宿主機內部的消息記錄,運維確實將宕掉的機器重新給拉起來了,這進一步印證了我的想法。 但是按照筆者的推論,在22:32分新發出重傳的所有的請求都被Connection reset了,為何在將近兩分鐘之後(準確的說是在1分49s之後由又報了一波錯?)繼續往下分析。

(注意22:32分和22:34分報錯的是不同的socket連接)

連接超時(讀取失敗)

這個錯誤很少遇到。 不知道是在哪種情況下觸發。 具體的異常棧為:

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之間細微的差別。

超時

既然是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

上面邏輯是首先判定是否超時,如果未超時則設置下一個超時時間。 邏輯如下圖所示:

解Bug之路-記一次對端機器宕機後的tcp行為 6

我們再看下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 <= 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 */ ...... )

由於boundary=15 > linear_backoff_thresh(9)所以,計算超時時間為:

超時=(((2 << linear_backoff_thresh)-1)TCP_RTO_MIN +(邊界-linear_backoff_thresh)TCP_RTO_MAX;

即(TCP_RTO_MIN = 200ms,TCP_RTO_MAX = 120s)

超時=((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,如下圖所示:

解Bug之路-記一次對端機器宕機後的tcp行為 7

重傳最終超時的上界

我們假設在第N次的時候tcp_time_stamp - start_ts=924.5999s時候進行超時判定,那麼勢必會進行下一次重傳,並在924.5999+120=1044.5999s後超時,如下圖所示:

解Bug之路-記一次對端機器宕機後的tcp行為 8

那麼,重傳最終超時的上界就是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) 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的報錯時間計算一下機器響應的時間窗口。 在這里為了簡便分析,我們忽略包在網絡中的最長存活時間,如下圖所示:

解Bug之路-記一次對端機器宕機後的tcp行為 9

即機器開始應答的時間應該在22:32:11至22:32:22之間。

當然了,很難獲取到機器真正開始應答的精確時間來證實筆者的計算。 但是這個計算的意義在於如果兩者的應答窗口沒有交疊,那麼筆者的上述推論就是錯的,需要推倒重來。 存在這個時間窗口,可以讓筆者的推測在邏輯上自洽。

後續改進

將tcp_retries2減少。 soTimeOut在這個中間件client代碼裡面由於其它問題不建議設置。

總結

機器宕機雖然不討人喜歡,但是觀察宕機後線上的種種表現可是一次難得機會,能夠發現平時注意不到的坑。 另外,定量分析其實蠻有意思的,尤其是種種數據都對上的時刻,挺有成就感^_^。

公眾號

關注筆者公眾號,獲取更多乾貨文章

解Bug之路-記一次對端機器宕機後的tcp行為 10