log4j deadlock

简介: 用了这么久的Log4j这次倒下了,而且官方也还没有给出解决方案。 描述:tomcat 经过一天多时间的访问,出现了hang ,使用 Jstack 查看堆栈后,发现现成 blocked ,主要是 Log4j 的ROOTlock了。

用了这么久的Log4j这次倒下了,而且官方也还没有给出解决方案。

描述:tomcat 经过一天多时间的访问,出现了hang ,使用 Jstack 查看堆栈后,发现现成 blocked ,主要是 Log4j 的ROOTlock了。

"http-nio-2180-exec-9" #35 daemon prio=5 os_prio=0 tid=0x0000000021a8b000 nid=0x12a8 runnable [0x000000002e5ee000]
   java.lang.Thread.State: RUNNABLE
    at java.io.FileOutputStream.writeBytes(Native Method)
    at java.io.FileOutputStream.write(Unknown Source)
    at java.io.BufferedOutputStream.write(Unknown Source)
    - locked <0x00000006c0cf7380> (a java.io.BufferedOutputStream)
    at java.io.PrintStream.write(Unknown Source)
    - locked <0x00000006c0cf7360> (a java.io.PrintStream)
    at org.apache.tomcat.util.log.SystemLogHandler.write(SystemLogHandler.java:172)
    at sun.nio.cs.StreamEncoder.writeBytes(Unknown Source)
    at sun.nio.cs.StreamEncoder.implFlushBuffer(Unknown Source)
    at sun.nio.cs.StreamEncoder.implFlush(Unknown Source)
    at sun.nio.cs.StreamEncoder.flush(Unknown Source)
    - locked <0x00000006c0eb2428> (a java.io.OutputStreamWriter)
    at java.io.OutputStreamWriter.flush(Unknown Source)
    at org.apache.log4j.helpers.QuietWriter.flush(QuietWriter.java:59)
    at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:324)
    at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
    at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
    - locked <0x00000006c0eaf3b8> (a org.apache.log4j.ConsoleAppender)
    at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
    at org.apache.log4j.Category.callAppenders(Category.java:206)
    - locked <0x00000006c0ea85c8> (a org.apache.log4j.spi.RootLogger)
    at org.apache.log4j.Category.forcedLog(Category.java:391)
    at org.apache.log4j.Category.log(Category.java:856)
    at org.apache.commons.logging.impl.Log4JLogger.debug(Log4JLogger.java:155)
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:861)
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:966)
    at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:857)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:622)
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:842)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:85)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
    at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:617)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:518)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1091)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:668)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1527)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1484)
    - locked <0x00000006c27752a8> (a org.apache.tomcat.util.net.NioChannel)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Unknown Source)

 

被锁住的线程堆栈:

"http-nio-2180-exec-10" #36 daemon prio=5 os_prio=0 tid=0x0000000021a8c000 nid=0xcfc waiting for monitor entry [0x000000002e49e000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at org.apache.log4j.Category.callAppenders(Category.java:204)
    - waiting to lock <0x00000006c0ea85c8> (a org.apache.log4j.spi.RootLogger)
    at org.apache.log4j.Category.forcedLog(Category.java:391)
    at org.apache.log4j.Category.log(Category.java:856)
    at org.apache.commons.logging.impl.Log4JLogger.debug(Log4JLogger.java:155)
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:861)
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:966)
    at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:857)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:622)
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:842)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:85)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
    at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:617)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:518)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1091)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:668)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1527)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1484)
    - locked <0x00000006c2723a10> (a org.apache.tomcat.util.net.NioChannel)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Unknown Source)

查了很多资料,比较全的是这个老兄回答的:

http://stackoverflow.com/questions/3537870/production-settings-file-for-log4j/

第一个回答的截取在这里,备份下,解决方案他也提到了,不过只是减缓,没有完全解决。

Log4j 1.2 is vulnerable to deadlocks when toString() produces nested logging.

See old aged still unresolved issues like Log4J can create deadlock conditions (concurrent package donation) and Deadlock with RollingFileAppender.

It also has performance-killing lock synchronization issues under heavy concurrent load. LikeCategory callAppenders synchronization causes java.lang.Thread.State: BLOCKED and Move org.apache.log4j.Category to reentrant read/write locks.

Even AsyncAppender is not free of excessive locks: AsyncAppender.doAppend() does not need to be synchronized and Deadlock in 1.2.15 caused by AsyncAppender and ThrowableInformation classes. Also beware of AsyncAppender overflow.

One caveat is to always constrain root category level to at least INFO or higher. This would prevent logging calls from acquiring unnecessary locks mentioned in the above issues. Just limiting appender threshold is not sufficient as it is taken into account later. See explanation with publish/subscribe analogy. Nested categories of interest can be individually given lower priorities if needed.

 

目录
相关文章
|
7月前
|
Java
log4j:WARN Please initialize the log4j system properly.
log4j:WARN Please initialize the log4j system properly.
335 0
|
SQL 关系型数据库 MySQL
Deadlock found when trying to get lock; try restarting transaction
Deadlock found when trying to get lock; try restarting transaction
326 1
Error:svn:E155037:Previous operation has not finished; run ‘cleanup‘ if it was interrupted(完美解决)
Error:svn:E155037:Previous operation has not finished; run ‘cleanup‘ if it was interrupted(完美解决)
428 0
Error:svn:E155037:Previous operation has not finished; run ‘cleanup‘ if it was interrupted(完美解决)
|
关系型数据库 Oracle 数据库
|
关系型数据库
InnoDB redo log thread cpu usage
InnoDB 在8.0 里面把写redo log 角色的各个线程都独立出来, 每一个thread 都处于wait 状态, 同样用户thread 调用log_write_up_to 以后, 也会进入wait 状态.这里的wait 等待最后都是通过调用 os_event_wait_for 来实现, 而 os_event_wait_for 是先spin + wait 的方式实现.所以这里有两个参数会影响os_event_wait_for 函数:spins_limit,timeout.
159 0
|
关系型数据库 MySQL
[Err] 1205 - Lock wait timeout exceeded; try restarting transaction Mysql 报错
Mysql 报错: [Err] 1205 - Lock wait timeout exceeded; try restarting transaction
489 0
|
存储 缓存 数据处理
完全揭秘log file sync等待事件
什么是log file sync等待事件呢?在一个提交(commit)十分频繁的数据库中,一般会出现log file sync等待事件,当这个等待事件出现在top5中,这个时侯我们需要针对log file sync等待事件进行优化,一定要尽快分析并解决问题,否则当log file sync等待时间从几毫秒直接到20几毫秒可能导致系统性能急剧下降,甚至会导致短暂的挂起。
完全揭秘log file sync等待事件
|
Oracle 关系型数据库 数据库
PMON failed to acquire latch, see PMON dump
前几天,一台Oracle数据库(Oracle Database 10g Release 10.2.0.4.0 - 64bit Production)监控出现"PMON failed to acquire latch, see PMON dump"错误,连接数据库出现短暂异常,告警日志中具体错误如下所...
1144 0