解Bug之路-記一次對端機器宕機後的tcp行爲
解Bug之路-記一次對端機器宕機後的tcp行爲
前言
機器通常過質保以後，就會由於各類各樣的問題而宕機。而這一次的宕機，讓筆者觀察到了日常觀察不到的tcp在對端宕機狀況下的行爲。通過詳細跟蹤分析緣由以後，發現能夠經過調整內核tcp參數來減小宕機形成的影響。java
Bug現場
筆者所在的公司用某個中間件的古老版本作消息轉發，此中間件在線上運行有些年頭了，大約剛開始部署的時候機器仍是全新的，如今都已通過保了。機器的宕機致使了一些詭異的現象。以下圖所示:linux
在中間件所在機器宕機以後，出現了調用中間件超時的現象。拋開各類業務細節，會發現出現了時間很長的超時。其中一波在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(最長)的超時時間。
即對應oracle
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源碼的描述:dom
/**
* ......
* 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));
}
裏面有這麼一段話socket
A timeout of zero is interpreted as an infinite timeout
按上述字母解釋爲若是設置爲0的話，應該是等待無限長的時間(直到進程重啓)。
但是按照線上業務的表現，確是有超時時間的，只不過期間很長。最長的達到了940s，即15分鐘多。
這就引發了筆者的興趣，究竟是什麼讓這個無限的超時時間被打斷呢？咱們繼續分析。tcp
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鏈接)ui
Connection timed out(Read failed)
這個錯誤不多遇到。不知道是在哪一種狀況下觸發。具體的異常棧爲:this
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代碼裏面因爲其它問題不建議設置。
總結
機器宕機雖然不討人喜歡，可是觀察宕機後線上的種種表現但是一次可貴機會，可以發現平時注意不到的坑。另外，定量分析其實蠻有意思的，尤爲是種種數據都對上的時刻，挺有成就感_。
公衆號
關注筆者公衆號，獲取更多幹貨文章: