案例解析：執行緒池使用不當導致的系統崩潰

【空山新雨】發表於2019-06-16
執行緒

前幾天，發現一臺阿里雲伺服器上的Web服務不可用。遠端SSH登入不上，嘗試幾次登入上去之後，執行命令都顯示

-bash: fork: Cannot allocate memory

一看以為是記憶體洩漏導致溢位。因為執行不了任何命令， 只能通過控制檯重啟伺服器恢復服務。 

 

初步排查

服務恢復後，檢視系統日誌，linux系統日誌路徑/var/log/messages，可通過journalctl命令檢視，如

journalctl --since="2019-06-12 06:00:00" --until="2019-06-12 10:00:00"

可檢視since之後，until之前時間段的日誌。除了發現crond[14954]: (CRON) CAN'T FORK (do_command): Cannot allocate memory 這個錯誤日誌，未見其它異常（下面的sshd[10764]: error: fork: Cannot allocate memory應是ssh登入執行命名失敗的日誌）

linux-log

通過阿里雲-雲監控-主機監控檢視記憶體使用率指標，這段時間內，記憶體使用率一直在40%以下，基本可排除記憶體溢位的可能。

通過搜尋查閱到程式數超過作業系統限制可能導致bash: fork: Cannot allocate memory的報錯(參考： https://blog.csdn.net/wangshuminjava/article/details/80603847 ）。

通過ps -eLf|wc -l檢視當前程式執行緒數(ps -ef只列印程式，ps -eLf會列印所有的執行緒), 只有1000多個，故障時刻系統到底執行了多少執行緒已無從得知，只能持續跟進監測。

問題定位

幾天後，再次通過ps -eLf|wc -l檢視，發現執行緒數已達16000多個。直接執行ps -eLf可看到大量tomcat程式所產生的執行緒，猜測是不是執行緒死鎖導致大量執行緒未完成一直hung在那裡。

執行 jstack 程式號 > ~/jstack.txt 命令將程式所執行執行緒情況列印出來分析，發現大量的WAITING狀態的執行緒，如下

"pool-19-thread-1" #254 prio=5 os_prio=0 tid=0x00007f0b700a6000 nid=0x29a9 waiting on condition [0x00007f0b274df000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000006ce3d8790> (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 java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

 

根據上述內容可看出執行緒在等一個條件，並且是在執行LinkedBlockingQueue.take方法的時候，檢視該方法的java doc，當佇列為空時，該方法將會一直等待直到有元素可用。

/**
 * Retrieves and removes the head of this queue, waiting if necessary
 * until an element becomes available.
 *
 * @return the head of this queue
 * @throws InterruptedException if interrupted while waiting
 */
E take() throws InterruptedException;

　　

詢問同事在哪裡用到了LinkedBlockingQueue，同事回憶起不久前用執行緒池實現往阿里雲OSS服務通過追加的方式上傳檔案功能，檢視程式碼後發現問題——執行緒池沒有關閉。為了使檔案片段儲存不存在錯亂，每次儲存檔案時，都new了一個執行緒池物件， 

ThreadPoolExecutor saveImgThreadPool = new ThreadPoolExecutor(1, 1, 0, TimeUnit.SECONDS, new LinkedBlockingQueue<>());

但處理完後， 沒有關閉這個執行緒池物件，這樣執行緒池仍會通過take方法去取等待佇列中是否還有未完成的執行緒任務，等待佇列為空時將會一直等待，這樣就導致大量的執行緒hung在這裡了（基本是隻要方法被調一次，就會產生一個hung住的執行緒）。 

延伸

  1. 執行緒狀態為“waiting for monitor entry”：
    意味著它 在等待進入一個臨界區 ，所以它在”Entry Set“佇列中等待。此時執行緒狀態一般都是 Blocked：
    java.lang.Thread.State: BLOCKED (on object monitor)

  2. 執行緒狀態為“waiting on condition”：
    說明它在等待另一個條件的發生，來把自己喚醒，或者乾脆它是呼叫了 sleep(N)。此時執行緒狀態大致為以下幾種：
    java.lang.Thread.State: WAITING (parking)：一直等那個條件發生（本文案例即為此種場景）；java.lang.Thread.State: TIMED_WAITING (parking或sleeping)：定時的，那個條件不到來，也將定時喚醒自己。

  3. 如果大量執行緒在“waiting for monitor entry”：可能是一個全域性鎖阻塞住了大量執行緒。如果短時間內列印的thread dump 檔案反映，隨著時間流逝，waiting for monitor entry 的執行緒越來越多，沒有減少的趨勢，可能意味著某些執行緒在臨界區裡呆的時間太長了，以至於越來越多新執行緒遲遲無法進入臨界區。

  4. 如果大量執行緒在“waiting on condition”：可能是它們又跑去獲取第三方資源，尤其是第三方網路資源，遲遲獲取不到Response，導致大量執行緒進入等待狀態。所以如果你發現有大量的執行緒都處在 Wait on condition，從執行緒堆疊看，正等待網路讀寫，這可能是一個網路瓶頸的徵兆，因為網路阻塞導致執行緒無法執行。也可能是如本文所提到的，由於程式編寫不當所致。





我的個人部落格地址：http://blog.jboost.cn
我的頭條空間： https://www.toutiao.com/c/user/5833678517/#mid=1636101215791112
我的github地址：https://github.com/ronwxy
我的微信公眾號：jboost-ksxy

——————————————————————————————————————

微信公眾號
歡迎關注我的微信公眾號，及時獲取最新分享

相關文章