解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程式碼裡面由於其它問題不建議設定。
總結
機器當機雖然不討人喜歡，但是觀察當機後線上的種種表現可是一次難得機會，能夠發現平時注意不到的坑。另外，定量分析其實蠻有意思的，尤其是種種資料都對上的時刻，挺有成就感_。
公眾號
關注筆者公眾號，獲取更多幹貨文章:
