Log4j線程死鎖–案例研究

此案例研究描述了影響Weblogic Portal 10.0生產環境的Apache Log4j線程爭用問題的完整根本原因分析和解決方案。它還將說明在開發和支持Java EE應用程序時適當的Java類加載器知識的重要性。

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

環境規格

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

故障排除工具

Quest Foglight for Java（監視和警報）
Java VM線程轉儲（線程競爭分析）

問題概述

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

事實的收集和驗證

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

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

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

Weblogic占用線程報告

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

通常，線程問題需要進行適當的線程轉儲分析，以查明線程爭用的根源。缺乏這種關鍵的分析技能將使您無法進行根本原因分析。

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

線程轉儲分析

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

"[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)

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

此時的主要問題是為什么我們突然看到這個問題？經過適當驗證后，此時還排除了日志記錄級別或負載的增加。回滾以前的更改確實解決了問題，這一事實自然使我們對所推動的更改進行了更深入的審查。在進入最終的根本原因部分之前，我們將對受影響的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（）在類別級別使用了一個同步塊，這可能導致嚴重的并發負載下嚴重的線程競爭情況。在這種情況下，使用重入式讀-寫鎖會更合適（例如，這種鎖策略允許并發的“讀”但允許單個“寫”）。您可以在下面找到有關此已知Apache Log4j限制的參考以及一些可能的解決方案。

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

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

根本原因：完美的風暴！

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

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

為了緩解此問題，還對環境應用了2種直接解決方案：