log4j deadlock

用了這麼久的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.