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种直接解决方案：