由一次線上故障來理解下 TCP 三握、四揮 & Java 堆棧分析到源碼的探秘
- 2019 年 10 月 19 日
- 筆記
本文導讀:
- 生產故障場景介紹
- TCP 建連三次握手過程
- TCP 斷連四次揮手過程
- 結合 Java 堆棧剖析源碼
- 再從堆棧中找到"罪魁禍首"
- 問題優化方案總結
1、生產故障場景介紹
業務簡介:
該服務主要是提供對外的代理介面,大部分介面都會調用第三方介面,獲取數據後做聚合處理後,提供給客戶端使用。
有一天晚上,系統正處於高峰期間,項目組小夥伴正在津津有味的吃著「加班餐」,剛把?塞進嘴裡,郵件和簡訊同時發起來告警。
有一台伺服器介面超時,平時偶爾也會收到類似告警,有時會因為網路波動等原因。實在不好意思,沒事總讓人家「網路」同學背鍋 : )。但是,這次告警並沒有收斂,持續告警了十幾分鐘以上,感到了不妙。
點擊郵件中告警的 URL 介面鏈接,一直在頁面轉圈圈,響應很慢,悲劇!
此刻,默默的把?盒飯推到一邊去,不忍直視 🙁
問題定位基本流程:
1)確定影響範圍
該服務後面掛著多台伺服器,僅有一台伺服器掛掉了,所以對用戶不會有太大的影響。
先臨時從註冊中心上摘掉,別讓客戶端繼續重試到這台機器上了,保留事故現場。
2)排查監控指標
查看介面服務的訪問量,因為是晚高峰,因此會比其他時間段用戶訪問量會更大些,但是這個訪問量看上去跟平時同一時段對比,並沒有特別明顯突增現象。
監控上觀察伺服器的 CPU、記憶體、IO、網路指標看起來也一切正常。
3)伺服器排查
登錄到伺服器上,結合監控進一步查看伺服器 CPU、記憶體 等指標,查看服務日誌都是正常的,並且也沒有發現特別的異常日誌輸出,Exception 或者 OOM 等異常。
我們看到的現象是,介面服務已經無法正常響應了,應用跑在 JVM 上,快速通過 JDK 自帶的常用命令排查一番了。
如下命令列印堆棧資訊:
jstack -l $pid > jstack.log
統計結果如下:
cat jstack.log | grep "java.lang.Thread.State" | sort -nr | uniq -c
994 java.lang.Thread.State: WAITING (parking) 501 java.lang.Thread.State: WAITING (on object monitor) 7 java.lang.Thread.State: TIMED_WAITING (sleeping) 13 java.lang.Thread.State: TIMED_WAITING (parking) 2 java.lang.Thread.State: TIMED_WAITING (on object monitor) 23 java.lang.Thread.State: RUNNABLE
如果遇到 java.lang.Thread.State: WAITING (parking)、java.lang.Thread.State: WAITING (on object monitor) 這類執行緒狀態,就要引起注意了,一般可能都是程式本身問題導致的。
根據 java.lang.Thread.State: WAITING 查看 jstack.log 里的堆棧資訊,發現了了大量的調用 HttpClient 工具類請求等待掛起的日誌,具體堆棧資訊待下面詳細分析。
這些服務調用都是通過 HttpClient 工具直接調用的,對 Spring RestTemplate 做了一次封裝,其底層也是調用的 Apache HttpClient 工具類來實現服務調用的。
除看到上述 jstack 日誌異常外,還排查了伺服器上的網路狀態,這也是運維同學們常用的排查手段。
附上統計網路連接狀態的命令:
netstat -n | awk '/^tcp/ {++State[$NF]} END {for(i in State) print i, State[i]}'
統計結果:
TIME_WAIT 9 CLOSE_WAIT 3826 SYN_SENT 2 ESTABLISHED 28 SYN_RECV 8
這裡注意了,我們看到伺服器詭異的網路連接統計中,出現了大量的 CLOSE_WAIT 狀態的連接。
而且這個狀態,當你間隔一段時間再次執行統計命令,還是會存在,也就是不會被釋放掉了,看上去問題有些嚴重。
進一步猜測,出現這些 CLOSE_WAIT 狀態跟介面響應慢應該是有關係的,同時,也跟 java 堆棧資訊中出現的 HttpClient 執行緒阻塞有關係,作為問題突破口去分析。
不如,我們先來了解下 CLOSE_WAIT 狀態,這個 CLOSE_WAIT 狀態處於 TCP 網路斷開連接過程中,當客戶端發起斷連請求,服務端首次收到斷連請求,回復確認消息,之後便處於 CLOSE_WAIT 狀態了,當服務端響應處理完畢會回復網路包給客戶端,正常連接會被關閉掉的。
2、 TCP 建連三次握手過程
儘管 CLOSE_WAIT 狀態是在 TCP 網路連接四次揮手過程中的。我們還是有必要,先來了解下 TCP 網路連接的三次握手,因為它是請求伺服器要做的第一件事情,那就是建立 TCP 連接。
技術源於生活。
我們可以舉個日常生活中的例子來理解 TCP 三次握手的過程。
比如你在微信上想與一位很久未曾謀面的朋友聊一聊:
小東:小升,在嗎?
(過了很久… … )
小升: 在了,你還在嗎?
(小東剛好在線,天天刷朋友圈… … )
小東:嗯嗯,在了
(然後兩位開始熱聊起來… …)
如果你平時跟朋友,開頭總這麼聊天是不是覺得很累呢。
其實上面的過程,可以很好的理解 TCP 三次握手的過程。
我們姑且將小東看做是「客戶端」,小升看做是「服務端」。
小東是做名程式設計師,做 IT 工作。小升在老家開店創業中。
理解TCP三次握手過程:
1)小東作為「客戶端」,向作為「服務端」的小升發起聊天,就是發送了一個網路包(包簽名為 syn
)給小升。【這是 TCP 第一次握手
,小東狀態此時處於 syn_sent
狀態】
2)小升收到了小東的聊天網路包,你得確認下吧,表示你收到了。此時,小升還有別的事情,不像小東那樣搞 IT 工作的,上班還上著微信。到了晚上,小升得空看了一眼手機微信,彈出了小東的消息。然後,激動的做了個回復「 針對小東發來的 sync
包,做了個 ack
回復確認」。因隔了一段時間了,小升也不確定小東還在不在線了。【這是 TCP 第二次握手
,小升狀態此時處於 syn_rcvd
狀態 】
3)小東因為剛好在線,收到了小升的回復確認消息,馬上對這次消息做了一個回復「對著小升給的 sync + ack
,做了進一步 ack
回復確認,這是 TCP 第三次握手
」 。【小升狀態此時變成了 established
可馬上聊天狀態】
4)此時,小升也在線,兩位就開始熱聊起來了。【正式傳輸數據了,小東和小升的狀態都處於 established
狀態】
上述提到的那些狀態 syn_sent
syn_rcvd
established
,正是 TCP 三次握手過程中涉及的關鍵狀態。
上一張圖來直觀理解下:
3、 TCP 斷連四次揮手過程
小東和小升的熱聊結束了,已經很晚了,也忙了一天了,需要休息了。
小東因工作原因明天要早起,所以提前跟小升說了:
小東:明天要凌晨4點起床升級系統,我要早點休息了,改天過來請你喝酒!
小升:額 ???這樣,反正我也不懂!
小升:那你早點休息吧。你說的這頓酒還是要喝的!
小東:嗯嗯,晚安啊!你也早點休息。
小升:好的,晚安,兄弟!
對應理解 TCP 四次揮手過程:
1)小東要休息了,發起了 fin1
包打算結束聊天了。【小東狀態此時處於 fin_wait1
狀態,這是 TCP 第一次揮手
】
2)小升收到了小東的 fin1
包,回復了 ack
確認消息。【此時,小升狀態處於 close_wait
狀態,小東此時狀態為 fin_wait2
,這是 TCP 第二次揮手
】
3)小升來了一次最後確認,不打算繼續聊了,發送了 fin2
包。【此時,小升狀態處於 last_ack
狀態,這是 TCP 第三次揮手
】
4)小東針對小升發來的 fin2
包,最終回復了個 ack
確認。【此時,小東狀態處於 time_wait
狀態,這是 TCP 第四次揮手
】
為什麼小東還要處於 time_wait
狀態等一下呢?
因為他們按照「老規矩」,得確保最後這次消息小升的確收到了,才能最終結束這次聊天。
time_wait
狀態標準持續等待時間是** 4
** 分鐘,在這段時間內,小東和小升建立的 TCP 網路連接套接字資源(埠),是不能被其他人所使用的,也不能被系統回收重新利用的。
如果小升沒有收到回饋,還會繼續問下「重發 fin2 消息」,直到小東發送了 ack 消息成功了。
雙方正式關閉聊天通道,釋放埠資源,連接關閉。
等待的 4 分鐘就是 2 個 MSL,每個 MSL 是 2 分鐘。MSL就是 maximium segment lifetime——最長報文壽命。這個時間是由官方 RFC 協議規定的。
上一張圖,進一步直觀理解下:
4、結合 Java 堆棧剖析源碼
分析完 TCP 四次揮手過程了,當服務端接收到 TCP 斷開連接的請求包,需要回復一個確認消息給客戶端,此時服務端狀態便處於 CLOSE_WAIT 狀態了。
我們清楚了該狀態所在的網路連接中的位置,結合前文中提到的問題,大量的執行緒阻塞在了 HttpClient 調用上。執行緒狀態為 WAITING,伺服器上統計出來,有大量處於 CLOSE_WAIT 狀態的網路連接無法釋放。
執行緒是 JVM 進程中比較寶貴的資源,如果一直有大量執行緒處於等待或阻塞狀態,慢慢的所有執行緒都被佔滿,導致服務沒法正常響應了。
我們來通過 java 執行緒堆棧資訊,再結合源碼來分析下具體原因。
找到第一段關鍵的堆棧日誌
:
"http-nio-8970-exec-1108" #24971 daemon prio=5 os_prio=0 tid=0x00007f45b4445800 nid=0x61ad waiting on condition [0x00007f444ad69000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000006c2f30968> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(AbstractConnPool.java:380) at org.apache.http.pool.AbstractConnPool.access$200(AbstractConnPool.java:69) at org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:246) - locked <0x0000000641c7fe38> (a org.apache.http.pool.AbstractConnPool$2) at org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:193) at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:303) at org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:279) at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:191) at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185) at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89) at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:111) at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185) at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83) at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:56) at org.springframework.http.client.HttpComponentsClientHttpRequest.executeInternal(HttpComponentsClientHttpRequest.java:89) at org.springframework.http.client.AbstractBufferingClientHttpRequest.executeInternal(AbstractBufferingClientHttpRequest.java:48) at org.springframework.http.client.AbstractClientHttpRequest.execute(AbstractClientHttpRequest.java:53) at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:660) at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:629) at org.springframework.web.client.RestTemplate.getForEntity(RestTemplate.java:329) at com.xxx.proxy.common.util.HttpClientUtil.getForEntity(HttpClientUtil.java:267) at com.xxx.proxy.common.util.HttpClientUtil.getForObject(HttpClientUtil.java:521) ... ...
堆棧日誌中出現了大量的上述日誌,基本都是 HttpClient 工具類所調用的,所有執行緒狀態處於 java.lang.Thread.State: WAITING (parking)
狀態。
出現 WAITING (parking)
執行緒掛起狀態,因為介面服務內部大量調用了第三方介面,要獲取 Http 連接,但始終無法獲取到,只能等待。
HttpClientUtil 工具類是繼承自 Spring RestTemplate 並做了一些參數、重試機制、代理訂製,其包路徑位於 org.springframework.web.client.RestTemplate
。
類圖如下所示:
創建 HttpClient 工具示例程式碼:
HttpClientFactoryBean httpClientFactoryBean = new HttpClientFactoryBean(config); HttpComponentsClientHttpRequestFactory httpRequestFactory = new HttpComponentsClientHttpRequestFactory(httpClientFactoryBean.getObject()); return new HttpClientUtil(httpRequestFactory);
HttpClientFactoryBean 繼承自 AbstractFactoryBean,重寫 getObjectType() 和 createInstance() 方法。
類圖如下所示:
HttpClientFactoryBean 部分示例方法:
@Override public Class<?> getObjectType() { return HttpClient.class; } @Override protected HttpClient createInstance() { if (restConfig == null) { HttpClients.custom().build(); } // 每個路由最大的連接數 int maxPerRoute = restConfig.getMaxConnections(); // 總的最大連接數 int maxTotal = restConfig.getMaxTotalConnections(); // 連接超時時間 int connectTimeout = restConfig.getConnectionTimeout(); // 讀取數據的超時時間 int socketTimeout = restConfig.getTimeout(); PoolingHttpClientConnectionManager connManager = new PoolingHttpClientConnectionManager(30, TimeUnit.SECONDS); connManager.setDefaultMaxPerRoute(maxPerRoute); connManager.setMaxTotal(maxTotal); connManager.setValidateAfterInactivity(1000); RequestConfig requestConfig = RequestConfig.custom().setConnectTimeout(connectTimeout) .setSocketTimeout(socketTimeout).build(); / ... 省略部分程式碼 return HttpClients.custom().setConnectionManager(connManager).evictExpiredConnections().setDefaultRequestConfig(requestConfig).build(); }
根據堆棧資訊也能看到是從 PoolingHttpClientConnectionManager
的 leaseConnection() 方法獲取連接,那我們可以詳細看下源程式碼,為什麼沒有獲取成功呢?
怎麼查找源碼,通過堆棧資訊中的調用棧鏈路,就能非常容易的找到經過了哪些類哪些方法,第多少行程式碼。
根據上面jstack中的日誌:
org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(AbstractConnPool.java:380)
根據名稱猜測,通過 AbstractConnPool 抽象連接池的類,調用 getPoolEntryBlocking 阻塞式方法獲取連接,第 380 行程式碼。
查看源碼:
private E getPoolEntryBlocking( final T route, final Object state, final long timeout, final TimeUnit tunit, final Future<E> future) throws IOException, InterruptedException, TimeoutException { Date deadline = null; // 連接獲取超時時間參數 if (timeout > 0) { deadline = new Date (System.currentTimeMillis() + tunit.toMillis(timeout)); } this.lock.lock(); try { final RouteSpecificPool<T, C, E> pool = getPool(route); // .... 省略部分源碼 boolean success = false; try { if (future.isCancelled()) { throw new InterruptedException("Operation interrupted"); } // 將 future,實際類型為 Future<CPoolEntry>,放入 pending 雙向鏈表隊列中 pool.queue(future); this.pending.add(future); if (deadline != null) { success = this.condition.awaitUntil(deadline); } else { // 這裡正是第 380 行源程式碼 this.condition.await(); success = true; } if (future.isCancelled()) { throw new InterruptedException("Operation interrupted"); } } finally { // In case of 'success', we were woken up by the // connection pool and should now have a connection // waiting for us, or else we're shutting down. // Just continue in the loop, both cases are checked. pool.unqueue(future); this.pending.remove(future); } // check for spurious wakeup vs. timeout if (!success && (deadline != null && deadline.getTime() <= System.currentTimeMillis())) { break; } } throw new TimeoutException("Timeout waiting for connection"); } finally { this.lock.unlock(); } }
查找到第 380 行源碼,調用了 condition 的 await() 方法:
this.condition.await();
這裡使用了並發包下的 Condition 實現多執行緒協調通訊機制,await() 方法調用後,會將當前執行緒加入到 Condition 等待隊列中,是一個FIFO結構的隊列,同時當前執行緒鎖釋放,如果不釋放,會導致其他執行緒無法獲得鎖,可能造成死鎖。
await() 方法源碼:
public final void await() throws InterruptedException { if (Thread.interrupted()) throw new InterruptedException(); // 加入 Condition 等待隊列 Node node = addConditionWaiter(); // 釋放當前執行緒的鎖 long savedState = fullyRelease(node); int interruptMode = 0; // 不在 AQS 同步隊列中,將當前執行緒掛起,如果在 AQS 隊列中退出循環 while (!isOnSyncQueue(node)) { LockSupport.park(this); if ((interruptMode = checkInterruptWhileWaiting(node)) != 0) break; } // 已被 signal() 方法喚醒,自旋等待嘗試再次獲取鎖 if (acquireQueued(node, savedState) && interruptMode != THROW_IE) interruptMode = REINTERRUPT; if (node.nextWaiter != null) // clean up if cancelled unlinkCancelledWaiters(); if (interruptMode != 0) reportInterruptAfterWait(interruptMode); }
當前執行緒加入 Condition 等待隊列結構圖:
當通過 Condtion 調用 signalAll() 或者 signal() 方法時,會獲取等待隊列的首節點,將其移動到同步隊列,利用 LockSupport 喚醒節點中的執行緒。節點從等待隊列,移動到 AQS 同步隊列如下結構圖所示:
在 AbstractConnPool 類的找到了 release() 釋放連接的程式碼。
release() 方法源碼如下:
@Override public void release(final E entry, final boolean reusable) { this.lock.lock(); try { if (this.leased.remove(entry)) { final RouteSpecificPool<T, C, E> pool = getPool(entry.getRoute()); pool.free(entry, reusable); if (reusable && !this.isShutDown) { this.available.addFirst(entry); } else { entry.close(); } onRelease(entry); Future<E> future = pool.nextPending(); if (future != null) { this.pending.remove(future); } else { future = this.pending.poll(); } if (future != null) { this.condition.signalAll(); } } } finally { this.lock.unlock(); } }
我們看到了釋放連接時,調用 this.condition.signalAll();
signalAll() 方法的調用會喚醒所有的所有等待隊列執行緒,雖然喚醒所有,但是仍然只有一個執行緒能拿到鎖,其他執行緒還是需要自旋等待。
signalAll() 方法源碼如下:
private void doSignalAll(Node first) { lastWaiter = firstWaiter = null; do { Node next = first.nextWaiter; first.nextWaiter = null; // 訊號通知 transferForSignal(first); first = next; } while (first != null); } final boolean transferForSignal(Node node) { /* * 設置node的waitStatus:Condition->0 */ if (!compareAndSetWaitStatus(node, Node.CONDITION, 0)) return false; // 加入到AQS的等待隊列,讓節點繼續獲取鎖,設置前置節點狀態為SIGNAL Node p = enq(node); int c = p.waitStatus; if (c > 0 || !compareAndSetWaitStatus(p, c, Node.SIGNAL)) // 調用 LockSupport 的 unpark() 方法喚醒執行緒 LockSupport.unpark(node.thread); return true; }
剖析完了底層程式碼,回過頭去,我們看下是因為調用到了 condition 的 await() 無參方法,並且一直無法獲得 Http 連接,然後一直占著 tomcat 執行緒的坑。
getPoolEntryBlocking() 方法的最開始,有個不能忽視的一段程式碼:
Date deadline = null; // 連接獲取超時時間參數 if (timeout > 0) { deadline = new Date (System.currentTimeMillis() + tunit.toMillis(timeout)); }
這段程式碼一看就是超時時間,猜測一下,程式碼在此處,timeout 應該就是從連接池獲取連接時的等待時間。
getPoolEntryBocking() 方法的下面看到:
if (deadline != null) { success = this.condition.awaitUntil(deadline); }
如果 deadline 不為空,會調用 condtion 的 awaitUtil(deadline) 方法,awaitUtil(deadline) 發方法表示直到達到 deadline 時間還未喚醒,就會自動喚醒,加入 AQS 同步隊列獲取鎖。
我們可以根據堆棧資訊繼續往前查找調用者,看看 deadline 中的 timeout 來源。
at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:191)
MainClientExec#execute() 方法部分源碼:
final HttpClientConnection managedConn; try { final int timeout = config.getConnectionRequestTimeout(); managedConn = connRequest.get(timeout > 0 ? timeout : 0, TimeUnit.MILLISECONDS); } catch(final InterruptedException interrupted) { }
這裡的 timeout,即 connectionRequestTimeout,正是計算 deadline 時間的 timeout 值。
印證了我們的猜測。
初始化 HttpClient 工具的初始配置參數,並沒有配置 connectionRequestTimeout
這個參數的,該參數也是很關鍵的,如果沒有設置,並且被 park 掛起的執行緒一直沒有被 signal 喚醒,那麼會一直等待下去。
所以,必須得設置這個參數。這裡的 deadline 是個絕對時間,不為空時,會調用 condition 的 awaitUtil(deadline) 方法,即使沒有被 signal 喚醒,也會自動喚醒,去爭搶鎖,而不會導致未被喚醒就一直阻塞下去。
而且這個 awaitUtil(deadline) 方法跟 awaitNanos(long nanosTimeout) 方法里的 deadline 變數設計上異曲同工。
達到了設定的超時時間,並且沒有 signal 過,最終 success
變數為 false 不成功,直接 break 跳出循環,最終會拋出 TimeoutException("Timeout waiting for connection") 異常。
拋出這個異常,系統錯誤日誌中,也就明確了是因為無法獲得連接導致的。同時,也避免了一直佔用著執行緒。
5、再從堆棧中找到"罪魁禍首"
上一節,從第一段堆棧日誌分析到了 Condition 並發底層源碼細節。
但是這還沒完,因為我們統計 java.lang.Thread.State
中,僅分析完了WAITING (parking)
狀態,問題原因也不一定是這個狀態導致的。接下來繼續分析另外的「異常」執行緒狀態 WAITING (on object monitor)
。
在 java 堆棧中 第二段關鍵的日誌
如下:
"http-nio-8970-exec-462" #24297 daemon prio=5 os_prio=0 tid=0x00007f45b41bd000 nid=0x5f0b in Object.wait() [0x00007f446befa000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) at java.lang.Object.wait(Object.java:502) at java.net.InetAddress.checkLookupTable(InetAddress.java:1393) - locked <0x00000006c05a5570> (a java.util.HashMap) at java.net.InetAddress.getAddressesFromNameService(InetAddress.java:1310) at java.net.InetAddress.getAllByName0(InetAddress.java:1276) at java.net.InetAddress.getAllByName(InetAddress.java:1192) at java.net.InetAddress.getAllByName(InetAddress.java:1126) at org.apache.http.impl.conn.SystemDefaultDnsResolver.resolve(SystemDefaultDnsResolver.java:45) at org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.connect(DefaultHttpClientConnectionOperator.java:112) at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.connect(PoolingHttpClientConnectionManager.java:373) at org.apache.http.impl.execchain.MainClientExec.establishRoute(MainClientExec.java:381) at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:237) at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185) at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89) at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:111) at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185) at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83) at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:56) at org.springframework.http.client.HttpComponentsClientHttpRequest.executeInternal(HttpComponentsClientHttpRequest.java:89) at org.springframework.http.client.AbstractBufferingClientHttpRequest.executeInternal(AbstractBufferingClientHttpRequest.java:48) at org.springframework.http.client.AbstractClientHttpRequest.execute(AbstractClientHttpRequest.java:53) at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:660) at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:629) at org.springframework.web.client.RestTemplate.getForEntity(RestTemplate.java:329) at com.xxx.tvproxy.common.util.HttpClientUtil.getForEntity(HttpClientUtil.java:267) at com.xxx.tvproxy.common.util.HttpClientUtil.getForObject(HttpClientUtil.java:521) `` java.lang.Thread.State: WAITING (on object monitor),這樣的執行緒狀態也要引起格外的注意,監視對象鎖,並且一直阻塞著執行緒不釋放。 根據執行緒堆棧資訊看,猜測就是跟 HttpClient 參數設置有關,我們來分析下創建參數。 查找棧頂資訊看到了有調用 Object 對象的 wait() 方法,說明是在等待另外的執行緒 notify 通知,但遲遲未等到,當前執行緒就一直處於 WAITING 狀態。 繼續查找是誰調用的:
at java.net.InetAddress.checkLookupTable(InetAddress.java:1393)
“
這段程式碼調用引起,還是要去看下源碼:
private static InetAddress[] checkLookupTable(String host) { synchronized (lookupTable) { // If the host isn't in the lookupTable, add it in the // lookuptable and return null. The caller should do // the lookup. if (lookupTable.containsKey(host) == false) { lookupTable.put(host, null); return null; } // If the host is in the lookupTable, it means that another // thread is trying to look up the addresses of this host. // This thread should wait. while (lookupTable.containsKey(host)) { try { // 對應堆棧中的 java.net.InetAddress.checkLookupTable(InetAddress.java:1393) lookupTable.wait(); } catch (InterruptedException e) { } } } // The other thread has finished looking up the addresses of // the host. This thread should retry to get the addresses // from the addressCache. If it doesn't get the addresses from // the cache, it will try to look up the addresses itself. InetAddress[] addresses = getCachedAddresses(host); if (addresses == null) { synchronized (lookupTable) { lookupTable.put(host, null); return null; } } return addresses; }
找到了是 lookupTable 對象,使用了同步塊鎖 synchronized,內部調用了 lookupTable 對象的 wait() 方法,就是在這裡等不到通知,一直阻塞著。
這個問題程式碼排查一通,你是看不出什麼問題來的,因為跟應用程式本身關係不大了,是因為 IPV6 導致的 JVM 執行緒死鎖問題。
參考國外 zimbra 站點 wiki:https://wiki.zimbra.com/wiki/Configuring_for_IPv4
這裡解釋下問題產生的原因:
應用本身在 IPv4 環境下,如果嘗試使用了 IPv6 會導致一些已知問題。
當調用了 Inet6AddressImpl.lookupAllHostAddr() 方法,因為 Java 與作業系統 libc 庫之間存在一個bug,當特定的競態條件發生時,將會導致查找 host 地址動作一直無限循環下去。這種情況發生的頻率很低,但是一旦發生將會導致 JVM 死鎖問題,進而導致 JVM 中所有執行緒會被阻塞住。
根據上述分析,在 jstack 堆棧中找到了 第三段關鍵的堆棧日誌
如下:
java.lang.Thread.State: RUNNABLE at java.net.Inet6AddressImpl.lookupAllHostAddr(Native Method) at java.net.InetAddress$2.lookupAllHostAddr(InetAddress.java:928) at java.net.InetAddress.getAddressesFromNameService(InetAddress.java:1323) at java.net.InetAddress.getAllByName0(InetAddress.java:1276) at java.net.InetAddress.getAllByName(InetAddress.java:1192) at java.net.InetAddress.getAllByName(InetAddress.java:1126) at org.apache.http.impl.conn.SystemDefaultDnsResolver.resolve(SystemDefaultDnsResolver.java:45) at org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.connect(DefaultHttpClientConnectionOperator.java:112) at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.connect(PoolingHttpClientConnectionManager.java:373) at org.apache.http.impl.execchain.MainClientExec.establishRoute(MainClientExec.java:381) at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:237) at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185) at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89) at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:111) at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185) at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83) at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:56) at ... ...
如何判斷作業系統是否啟用了 IPv6 ?
介紹兩種方式:
1)ifconfig
這個很明顯就能看得出來,有 inet6 addr
字樣說明啟用了 IPv6。
2)lsmod
[root@BJ]# lsmod | grep ipv6 Module Size Used by ipv6 335951 73 bridge
主要看 Used 這一列,數值 70+,不支援 IPv6 環境 Used 列是 1。
6、問題優化方案總結
經過對 java 堆棧中關鍵執行緒狀態的分析,明確了問題原因,接下來說下問題解決方案。
第一個問題:
針對從 Http 連接池中獲取不到連接時,可能使執行緒進入阻塞狀態。
在 HttpClient 客戶端初始化參數配置中增加 connectionRequestTimeout
,獲取連接的超時時間,一般不建議過大,我們設置為 500ms。
設置後,就會調用底層的 condition#awaitUtil(deadline) 方法,當執行緒無法被 signal 喚醒,到達了 deadline 絕對時間後,執行緒會自動從等待隊列中被喚醒,加入到 AQS 同步隊列爭搶鎖。
第二個問題:
針對 IPv6 導致的 JVM 進程死鎖問題,有兩種解決方案:
1)作業系統層面禁用 IPv6
編輯 /etc/sysctl.conf 文件
添加下面兩行:
net.ipv6.conf.all.disable_ipv6 = 1 net.ipv6.conf.default.disable_ipv6 = 1
保存,執行 sysctl -p
使其生效。
運行作業系統中執行如下命令直接生效:
sysctl -w net.ipv6.conf.all.disable_ipv6=1 sysctl -w net.ipv6.conf.default.disable_ipv6=1
2)Java 應用程式層面
在應用 JVM 啟動參數上添加 -Djava.net.preferIPv4Stack=true
。
從作業系統層面禁用 IPv6,如果伺服器上還部署了其他應用,注意觀察下,如果遇到一些問題可以藉助搜索引擎查下。
我們有很多台伺服器,都是運維來維護的,所以我採用了第二種方式,直接在 JVM 上增加參數,簡單方便。
最後的總結:
java 堆棧日誌中兩個關鍵的 WAITING
執行緒狀態,先出現了 WAITING (on object monitor)
,因 IPv6 問題觸發了 HttpClient 執行緒池所有執行緒阻塞。後出現了 WAITING (parking)
,Tomcat 執行緒接收轉發請求,當請求調用到 HttpClient,因無法獲得 Http 連接資源,且未設置獲取連接的超時時間,造成了大量執行緒阻塞。
經過對上述兩個問題的優化後,上線觀察很長一段時間,也經歷過比這次問題出現時更高的訪問量,再沒有出現過 JVM 執行緒阻塞問題。
通過網路命令行統計,基本不會出現大量的 CLOSE_WAIT
網路連接狀態。
歡迎關注我的公眾號,掃二維碼關注獲得更多精彩文章,與你一同成長~