本文導讀:java
業務簡介:node
該服務主要是提供對外的代理接口,大部分接口都會調用第三方接口,獲取數據後作聚合處理後,提供給客戶端使用。程序員
有一天晚上,系統正處於高峯期間,項目組小夥伴正在津津有味的吃着「加班餐」,剛把🍚塞進嘴裏,郵件和短信同時發起來告警。web
有一臺服務器接口超時,平時偶爾也會收到相似告警,有時會由於網絡波動等緣由。實在很差意思,沒事總讓人家「網絡」同窗背鍋 : )。可是,此次告警並無收斂,持續告警了十幾分鍾以上,感到了不妙。spring
點擊郵件中告警的 URL 接口連接,一直在頁面轉圈圈,響應很慢,悲劇!apache
此刻,默默的把🍱盒飯推到一邊去,不忍直視 :( c#
問題定位基本流程:segmentfault
1)肯定影響範圍tomcat
該服務後面掛着多臺服務器,僅有一臺服務器掛掉了,因此對用戶不會有太大的影響。
先臨時從註冊中心上摘掉,別讓客戶端繼續重試到這臺機器上了,保留事故現場。服務器
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 狀態了,當服務端響應處理完畢會回覆網絡包給客戶端,正常鏈接會被關閉掉的。
儘管 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 三次握手過程當中涉及的關鍵狀態。
上一張圖來直觀理解下:
小東和小升的熱聊結束了,已經很晚了,也忙了一天了,須要休息了。
小東因工做緣由明天要早起,因此提早跟小升說了:
小東:明天要凌晨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 協議規定的。
上一張圖,進一步直觀理解下:
分析完 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") 異常。
拋出這個異常,系統錯誤日誌中,也就明確了是由於沒法得到鏈接致使的。同時,也避免了一直佔用着線程。
上一節,從第一段堆棧日誌分析到了 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/...
這裏解釋下問題產生的緣由:
應用自己在 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。
通過對 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
網絡鏈接狀態。
歡迎關注個人公衆號,掃二維碼關注得到更多精彩文章,與你一同成長~