[[338229]]

 

 

之前一段時間，為我們發現的一個SaaS應用程序會間歇性地卡頓、變慢，因為很長時間都沒有定位到原因，所以解決的辦法就只能是重啟。

這個現象和之前我們遇到的程序變得卡頓不太一樣，因為我們發現這個應用程序不僅在高流量期間時會變慢，有時在低流量時期也會變慢。所以這令大家都很奇怪。

這類應用程序的變慢，重新啟動之后就可以維持一段時間，但是過段時間又有可能會再次出現。

 

故障排除

當我們準備排查這個問題的時候，我們在應用程序速度很慢的時候，嘗試著捕獲了這個應用程序的線程Dump。有很多種方式來捕獲線程轉Dump，我們選擇了“jstack”工具來獲取。

在問題發生時獲得線程Dump是非常關鍵的!

然后我們將捕獲的線程Dump上傳到一個線上線程Dump分析工具(https://fastthread.io/)。該工具立即幫我們生成了一份報告。

報告立即找出了問題的根本原因。分析工具上顯示“http-nio-8080-exec-121”線程阻塞了100多個線程。下面是傳遞依賴圖，展示了阻塞線程:

 

 

 

 

從圖中可以看到100多個線程被“http-nio-8080-exec-121”線程阻塞。當我們點擊圖中的“http-nio-8080-exec-121”超鏈接時，它會打印出線程的堆棧軌跡:

 

仔細觀察圖中被框出來的部分，你可以看到該線程已經獲取到org.apache.log4j.Logger的鎖，正在進行其他的操作。

接下來，我們隨便找一個被"http-nio-8080-exec-121"阻塞的線程，看一下他的堆棧信息：

 

看一下上面堆棧跟蹤中被框出來的部分。我們可以看到“http-nio-8080-exec-56”當前正處于阻塞(BLOCKED)狀態，而阻塞的原因是它正在等待獲取org.apache.log4j.Logger的鎖。

前面我們剛剛分析過，“http-nio-8080-exec-121”獲得了org.apache.log4j.Logger的鎖，正在進行其他操作，而鎖并沒有被釋放，所以其他線程想要獲得鎖就只能被阻塞。

其余的所有被阻塞的線程也在等待獲取org.apache.log4j.Logger的鎖。因此，每當任何應用程序線程試圖記錄日志時，它都會因為無法獲取到鎖而進入阻塞狀態。

 

剛開始我們也沒有太多的頭緒，后來我們嘗試借助Google的力量，然后我們用谷歌搜索了"org.apache.log4j.Logger 阻塞 線程"這樣的關鍵字。

我們在Apache Log4j bug數據庫中偶然發現了這個有趣的Bug，而且這個Bug早在2015年就被發現了。(https://bz.apache.org/bugzilla/show_bug.cgi?id=57714 )。

 

 

 

 

 

這是Log4J框架中已知的bug之一，也是開發新的Log4j2框架的主要原因之一。

由于這個bug，任何試圖打印日志的線程都進入了阻塞狀態。它導致整個應用程序嘎然而止。一旦應用程序從Log4j遷移到Log4j2框架，問題就解決了。

結論

Log4j已經在2015年8月開始就不再被維護了。如果您的應用程序仍在使用Log4J框架，強烈建議升級到Log4j2框架。Log4j2不僅僅是Log4j框架的下一個版本，它是一個從零開始編寫的新框架，它有很多性能改進。

最后，如果網站遇到程序被拖慢的問題，那么也可以考慮一下這個因素。

 

 

 

 

關于作者：漫話編程，是一個通過漫畫+音頻的形式講解枯燥的編程知識的公眾號。致力于讓編程變得更有樂趣。

本文轉載自微信公眾號「漫話編程」，可以通過以下二維碼關注。轉載本文請聯系漫話編程公眾號。