Log4j blocked 线程阻塞问题
2019年03月11日


我的zoa项目中,一直使用的是log4j 1.x版本,由于简单,一直没更换,也没怀疑过它的问题。


偶尔有两次,zoa在使用过程中假死的情况,不能响应任何请求,包括正常的关闭都无法进行


于是我使用 jvm工具分析了JVM的情况,最终定位为 log4j引起的线程 blocked,不算是死锁,但是所以请求都会调用log4j,而log4j又无法正常执行,所以 所有请求都会 block。线程堆栈信息片段 形如:

"qtp1056944384-232" prio=10 tid=0x00007f54900d0800 nid=0x63b3 waiting for monitor entry [0x00007f54492d0000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.apache.log4j.Category.callAppenders(Category.java:205)
	- waiting to lock <0x00000007e81c4830> (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.slf4j.impl.Log4jLoggerAdapter.info(Log4jLoggerAdapter.java:368)

主要是下面这个类中的这段代码造成的:

 /**
  * Call the appenders in the hierrachy starting at <code>this</code>. If no
  * appenders could be found, emit a warning.
 */
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);
 }
}

它使用了synchronized(this),所有线程共用一个Category,而它通过log4j.properties指定。 同一个Category下的线程打log时,需要进行全局同步,因此它的效率会很低,不适合高并发的场景。

详细分析参见:

https://dzone.com/articles/log4j-thread-deadlock-case