此案例研究描述了影響Weblogic Portal 10.0生產(chǎn)環(huán)境的Apache Log4j線程爭用問題的完整根本原因分析和解決方案。 它還將說明在開發(fā)和支持Java EE應(yīng)用程序時適當?shù)腏ava類加載器知識的重要性。

本文也是您提高線程轉(zhuǎn)儲分析技能和了解線程競爭條件的另一個機會。

環(huán)境規(guī)格

• Java EE服務(wù)器：Oracle Weblogic Portal 10.0
• 操作系統(tǒng)：Solaris 10
• JDK：Oracle / Sun HotSpot JVM 1.5
• 記錄API：Apache Log4j 1.2.15
• RDBMS：Oracle 10g
• 平臺類型：Web門戶

故障排除工具

• Quest Foglight for Java（監(jiān)視和警報）
• Java VM線程轉(zhuǎn)儲（線程競爭分析）

問題概述

從我們的Weblogic Portal生產(chǎn)環(huán)境之一觀察到主要性能下降。 Foglight代理還發(fā)送了警報，表明Weblogic線程利用率顯著上升，達到默認上限400。

事實的收集和驗證

像往常一樣，Java EE問題調(diào)查需要收集技術(shù)事實和非技術(shù)事實，因此我們可以得出其他事實和/或就根本原因進行結(jié)論。 在采取糾正措施之前，要對以下事實進行核實，以便得出根本原因：

• 對客戶有什么影響？ 高
• 受影響平臺的最近更改？ 是的，最近進行的部署涉及少量內(nèi)容更改以及一些Java庫更改和重構(gòu)。
• 受影響平臺最近的流量增加了嗎？ 沒有
• 自從多久以來觀察到此問題？ 部署后觀察到新問題
• 重新啟動Weblogic服務(wù)器是否可以解決問題？ 否，任何重新啟動嘗試均會立即導致線程激增
• 回滾部署更改是否解決了問題？ 是

結(jié)論1：問題似乎與最近的變化有關(guān)。 但是，團隊最初無法查明根本原因。 現(xiàn)在，我們將在本文的其余部分進行討論。

Weblogic占用線程報告

最初的線程激增問題由Foglight報告。 如下所示，線程利用率很高（最多400個），從而導致大量待處理的客戶端請求，最終導致嚴重的性能下降。

通常，線程問題需要進行適當?shù)木€程轉(zhuǎn)儲分析，以查明線程爭用的根源。 缺乏這種關(guān)鍵的分析技能將使您無法進行根本原因分析。

對于我們的案例研究，使用簡單的Solaris OS命令kill -3 <Java PID>從Weblogic服務(wù)器生成了一些線程轉(zhuǎn)儲快照。 然后從Weblogic標準輸出日志文件中提取線程轉(zhuǎn)儲數(shù)據(jù)。

線程轉(zhuǎn)儲分析

分析的第一步是對所有卡住的線程進行快速掃描，并找出問題的“模式”。 我們發(fā)現(xiàn)有250個線程卡在以下執(zhí)行路徑中：

"[ACTIVE] ExecuteThread: '20' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x03c4fc38 nid=0xe6 waiting for monitor entry [0x3f99e000..0x3f99f970]at org.apache.log4j.Category.callAppenders(Category.java:186)- waiting to lock <0x8b3c4c68> (a org.apache.log4j.spi.RootCategory)at org.apache.log4j.Category.forcedLog(Category.java:372)at org.apache.log4j.Category.log(Category.java:864)at org.apache.commons.logging.impl.Log4JLogger.debug(Log4JLogger.java:110)at org.apache.beehive.netui.util.logging.Logger.debug(Logger.java:119)at org.apache.beehive.netui.pageflow.DefaultPageFlowEventReporter.beginPageRequest(DefaultPageFlowEventReporter.java:164)at com.bea.wlw.netui.pageflow.internal.WeblogicPageFlowEventReporter.beginPageRequest(WeblogicPageFlowEventReporter.java:248)at org.apache.beehive.netui.pageflow.PageFlowPageFilter.doFilter(PageFlowPageFilter.java:154)at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:42)at com.bea.p13n.servlets.PortalServletFilter.doFilter(PortalServletFilter.java:336)at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:42)at weblogic.servlet.internal.RequestDispatcherImpl.invokeServlet(RequestDispatcherImpl.java:526)at weblogic.servlet.internal.RequestDispatcherImpl.forward(RequestDispatcherImpl.java:261)at <App>.AppRedirectFilter.doFilter(RedirectFilter.java:83)at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:42)at <App>.AppServletFilter.doFilter(PortalServletFilter.java:336)at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:42)at weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run(WebAppServletContext.java:3393)at weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:321)at weblogic.security.service.SecurityManager.runAs(Unknown Source)at weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2140)at weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2046)at weblogic.servlet.internal.ServletRequestImpl.run(Unknown Source)at weblogic.work.ExecuteThread.execute(ExecuteThread.java:200)at weblogic.work.ExecuteThread.run(ExecuteThread.java:172)

如您所見，當試圖將調(diào)試信息記錄到配置的附加程序和日志文件中時，似乎所有線程都在等待獲取Apache Log4j對象監(jiān)視器（org.apache.log4j.spi.RootCategory）上的鎖。 我們?nèi)绾螐拇司€程堆棧跟蹤中找出答案？ 讓我們剖析此線程堆棧跟蹤，以便您更好地了解此線程競爭條件，例如250個試圖同時獲取同一對象監(jiān)視器的線程。

此時的主要問題是為什么我們突然看到這個問題？ 經(jīng)過適當驗證后，此時還排除了日志記錄級別或負載的增加。 回滾以前的更改確實解決了問題，這一事實自然使我們對所推動的更改進行了更深入的審查。 在進入最終的根本原因部分之前，我們將對受影響的Log4j代碼進行代碼審查，例如，暴露于線程競爭條件下。

Apache Log4j 1.2.15代碼審查

## org.apache.log4j.Category /*** Call the appenders in the hierrachy starting at <code>this</code>. If no* appenders could be found, emit a warning.** <p>* This method calls all the appenders inherited from the hierarchy* circumventing any evaluation of whether to log or not to log the* particular log request.** @param event* the event to log.*/public void callAppenders(LoggingEvent event) {int writes = 0;for (Category c = this; c != null; c = c.parent) {// Protected against simultaneous call to addAppender,// removeAppender,...synchronized (c) {if (c.aai != null) {writes += c.aai.appendLoopOnAppenders(event);}if (!c.additive) {break;}}}if (writes == 0) {repository.emitNoAppenderWarning(this);}

如您所見，Catelogry.callAppenders（）在類別級別使用了一個同步塊，這可能導致嚴重的并發(fā)負載下嚴重的線程競爭情況。 在這種情況下，使用重入式讀-寫鎖會更合適（例如，這種鎖策略允許并發(fā)的“讀”但允許單個“寫”）。 您可以在下面找到有關(guān)此已知Apache Log4j限制的參考以及一些可能的解決方案。

https://issues.apache.org/bugzilla/show_bug.cgi?id=41214

以上Log4j行為是否是我們問題的實際根本原因？ 并沒有那么快……請記住，只有在最近部署之后才暴露此問題。 真正的問題是，哪些應(yīng)用程序更改從Apache Log4j日志記錄API觸發(fā)了此問題和副作用？

根本原因：完美的風暴！

對最近部署的更改的深入研究確實表明，已刪除了子類加載器級別的某些Log4j庫以及相關(guān)的“子優(yōu)先”策略。 這個重構(gòu)練習最終將Commons日志記錄和Log4j的委派移到了父類加載器級別。 問題是什么？

在進行此更改之前，日志記錄事件在父類加載器的Weblogic Beehive Log4j調(diào)用與子類加載器的Web應(yīng)用程序日志記錄事件之間分配。 由于每個類加載器都有其自己的Log4j對象副本，因此線程競爭條件問題被分成兩半，并且在當前負載條件下不暴露（屏蔽）。 重構(gòu)之后，所有Log4j調(diào)用都移到了父類加載器（Java EE應(yīng)用程序）中。 為Log4j組件（例如Category）添加了顯著的并發(fā)級別。 并發(fā)級別的提高以及這種已知的Category.java線程爭用/死鎖行為對我們的生產(chǎn)環(huán)境是一場完美的風暴。

為了緩解此問題，還對環(huán)境應(yīng)用了2種直接解決方案：

• 在父類和子類加載器之間回滾重構(gòu)和拆分的Log4j回調(diào)。
• 將某些附加程序的日志記錄級別從DEBUG降低到WARNING

當應(yīng)用更改（例如與庫和類加載器相關(guān)的更改）時，此問題案例再次增強了執(zhí)行適當?shù)臏y試和影響評估的重要性。 這樣的更改在“表面”上看起來很簡單，但可以觸發(fā)一些深層的執(zhí)行模式更改，從而使您的應(yīng)用程序處于已知的線程競爭條件下。

還將探索對Apache Log4j 2（或其他日志記錄API）的未來升級，因為它有望帶來一些性能增強，從而解決一些線程競爭和可伸縮性方面的問題。

請?zhí)峁┤魏卧u論或分享您與日志API相關(guān)的線程競賽相關(guān)問題的經(jīng)驗。

祝您編程愉快，別忘了分享！

參考： Log4j線程死鎖– Java EE支持模式和Java教程博客上的JCG合作伙伴 Pierre-Hugues Charbonneau的案例研究 。

翻譯自: https://www.javacodegeeks.com/2012/09/log4j-thread-deadlock-case-study.html

總結(jié)

以上是生活随笔為你收集整理的Log4j线程死锁–案例研究的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯，歡迎將生活随笔推薦給好友。