苏州建设公司,seo自然优化排名,网站纯色背景图怎么做,上海app搭建log4j 多线程死锁问题此案例研究描述了影响Weblogic Portal 10.0生产环境的Apache Log4j线程争用问题的完整根本原因分析和解决方案。 它还将展示在开发和支持Java EE应用程序时适当的Java类加载器知识的重要性。 本文也是您提高线程转储分析技能和了解线程竞争条件的另一个机会… log4j 多线程死锁问题 此案例研究描述了影响Weblogic Portal 10.0生产环境的Apache Log4j线程争用问题的完整根本原因分析和解决方案。 它还将展示在开发和支持Java EE应用程序时适当的Java类加载器知识的重要性。 本文也是您提高线程转储分析技能和了解线程竞争条件的另一个机会。 环境规格 Java EE服务器Oracle Weblogic Portal 10.0 操作系统Solaris 10 JDKOracle / Sun HotSpot JVM 1.5 记录APIApache Log4j 1.2.15 RDBMSOracle 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 prio10 tid0x03c4fc38 nid0xe6 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 codethis/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?id41214 以上Log4j行为是否是我们问题的实际根本原因 没那么快…请记住只有在最近部署之后才暴露此问题。 真正的问题是哪些应用程序更改从Apache Log4j日志记录API触发了此问题和副作用 根本原因完美的风暴 对最近部署的更改的深入分析确实表明已删除了子类加载器级别的某些Log4j库以及相关的“子优先”策略。 这个重构练习最终将Commons日志记录和Log4j的委派移到了父类加载器级别。 问题是什么 在进行此更改之前日志记录事件在父类加载器的Weblogic Beehive Log4j调用和子类加载器的Web应用程序日志记录事件之间分配。 由于每个类加载器都有其自己的Log4j对象副本因此线程竞争条件问题被分成两半并且在当前负载条件下不暴露屏蔽。 重构之后所有Log4j调用都移到了父类加载器Java EE应用程序中。 为Log4j组件例如Category添加了显着的并发级别。 并发级别的提高以及这种已知的Category.java线程争用/死锁行为对我们的生产环境而言是一场完美的风暴。 为了缓解此问题还对环境应用了2种直接解决方案 在父类和子类加载器之间回滚重构和拆分的Log4j回调。 将某些附加程序的日志记录级别从DEBUG降低到WARNING 当应用诸如库和类加载器相关的更改之类的更改时此问题案例再次加强了执行适当的测试和影响评估的重要性。 这样的更改在“表面”上看起来很简单但可以触发一些深层的执行模式更改从而使您的应用程序处于已知的线程竞争条件下。 还将探索对Apache Log4j 2或其他日志记录API的未来升级因为它有望带来一些性能增强从而解决一些线程竞争和可伸缩性方面的问题。 请提供任何评论或分享您与日志API相关的线程竞赛相关问题的经验。 祝您编程愉快别忘了分享 参考 Log4j线程死锁– Java EE支持模式和Java教程博客上的JCG合作伙伴 Pierre-Hugues Charbonneau的案例研究 。 翻译自: https://www.javacodegeeks.com/2012/09/log4j-thread-deadlock-case-study.htmllog4j 多线程死锁问题
