Logger 和 Appender 之间发生 Log4j 死锁

Question

我正在使用一个 LogAppender 类，它扩展了一个控制台 Appender，如果日志级别为 ERROR，则在内部使用 Sendmail 函数发送邮件。 （我知道我可以使用 SMPT appender 进行邮件发送，但这是基础架构的方式，因此请避免使用任何 cmets）。

我的应用程序被分成不同的线程，下面提到的问题偶尔会发生。（但一些观察告诉我，这可能是由于一个线程需要更多时间来初始化）。

我在 jstack 中得到以下转储：

    "pool-68-thread-1":
  waiting to lock Monitor@0x0000000005496818 (Object@0xfffffd7e390328b0, a crazycode/api/core/common/log/LogAppender),
  which is held by "main"
"main":
  waiting to lock Monitor@0x00000000064dbfc0 (Object@0xfffffd7dfb1f8908, a org/apache/log4j/Logger),
  which is held by "pool-68-thread-1"

Found a total of 1 deadlock.

Thread t@328: (state = BLOCKED)
 - org.apache.log4j.Category.callAppenders(org.apache.log4j.spi.LoggingEvent) @bci=13, line=202 (Interpreted frame)
 - org.apache.log4j.Category.forcedLog(java.lang.String, org.apache.log4j.Priority, java.lang.Object, java.lang.Throwable) @bci=14, line=388 (Interpreted frame)
 - org.apache.log4j.Category.log(java.lang.String, org.apache.log4j.Priority, java.lang.Object, java.lang.Throwable) @bci=34, line=853 (Compiled frame)
 - crazycode.team2Api.common.logging.DESLogger.debug(java.lang.Object) @bci=12, line=240 (Interpreted frame)
 - crazycode.api.core.cache.management.CacheFiller.refreshCache(java.util.List, java.lang.Object, java.lang.String) @bci=33, line=229 (Interpreted frame)
 - crazycode.api.core.cache.management.CacheFiller.initialize(java.lang.Object) @bci=70, line=285 (Interpreted frame)
 - crazycode.api.alert.impl.service.ResearchAlertConfigCacheImpl.init() @bci=18, line=110 (Interpreted frame)
 - crazycode.api.alert.impl.service.ResearchAlertConfigCacheImpl.initialize() @bci=1, line=98 (Interpreted frame)
 - crazycode.api.alert.handler.MemoHandler.initRealHandler() @bci=4, line=573 (Interpreted frame)
 - crazycode.api.alert.handler.RealAlertCoordinator.initHandler(crazycode.api.alert.handler.AlertHandler, int, int, boolean, boolean) @bci=61, line=47 (Interpreted frame)
 - crazycode.api.alert.handler.run.BaseAlertHandlerRun$1$1.run() @bci=72, line=229 (Interpreted frame)
 - java.util.concurrent.Executors$RunnableAdapter.call() @bci=4, line=441 (Interpreted frame)
 - java.util.concurrent.FutureTask$Sync.innerRun() @bci=30, line=303 (Interpreted frame)
 - java.util.concurrent.FutureTask.run() @bci=4, line=138 (Interpreted frame)
 - java.util.concurrent.ThreadPoolExecutor$Worker.runTask(java.lang.Runnable) @bci=59, line=886 (Interpreted frame)
 - java.util.concurrent.ThreadPoolExecutor$Worker.run() @bci=28, line=908 (Interpreted frame)
 - java.lang.Thread.run() @bci=11, line=662 (Interpreted frame)


Thread t@327: (state = BLOCKED)
 - org.apache.log4j.Category.callAppenders(org.apache.log4j.spi.LoggingEvent) @bci=13, line=202 (Interpreted frame)
 - org.apache.log4j.Category.forcedLog(java.lang.String, org.apache.log4j.Priority, java.lang.Object, java.lang.Throwable) @bci=14, line=388 (Interpreted frame)
 - org.apache.log4j.Category.log(java.lang.String, org.apache.log4j.Priority, java.lang.Object, java.lang.Throwable) @bci=34, line=853 (Compiled frame)
 - crazycode.team2Api.common.logging.DESLogger.debug(java.lang.Object) @bci=12, line=240 (Interpreted frame)
 - crazycode.api.core.cache.management.CacheFiller.refreshCache(java.util.List, java.lang.Object, java.lang.String) @bci=33, line=229 (Interpreted frame)
 - crazycode.api.core.cache.management.CacheFiller.initialize(java.lang.Object) @bci=70, line=285 (Interpreted frame)
 - crazycode.api.alert.impl.service.ResearchAlertConfigCacheImpl.init() @bci=18, line=110 (Interpreted frame)
 - crazycode.api.alert.impl.service.ResearchAlertConfigCacheImpl.initialize() @bci=1, line=98 (Interpreted frame)
 - crazycode.api.alert.handler.ResearchDocumentHandler.initRealHandler() @bci=86, line=957 (Interpreted frame)
 - crazycode.api.alert.handler.RealAlertCoordinator.initHandler(crazycode.api.alert.handler.AlertHandler, int, int, boolean, boolean) @bci=61, line=47 (Interpreted frame)
 - crazycode.api.alert.handler.run.BaseAlertHandlerRun$1$1.run() @bci=72, line=229 (Interpreted frame)
 - java.util.concurrent.Executors$RunnableAdapter.call() @bci=4, line=441 (Interpreted frame)
 - java.util.concurrent.FutureTask$Sync.innerRun() @bci=30, line=303 (Interpreted frame)
 - java.util.concurrent.FutureTask.run() @bci=4, line=138 (Interpreted frame)
 - java.util.concurrent.ThreadPoolExecutor$Worker.runTask(java.lang.Runnable) @bci=59, line=886 (Interpreted frame)
 - java.util.concurrent.ThreadPoolExecutor$Worker.run() @bci=28, line=908 (Interpreted frame)
 - java.lang.Thread.run() @bci=11, line=662 (Interpreted frame)


Thread t@322: (state = BLOCKED)
 - org.apache.log4j.Category.callAppenders(org.apache.log4j.spi.LoggingEvent) @bci=13, line=202 (Interpreted frame)
 - org.apache.log4j.Category.forcedLog(java.lang.String, org.apache.log4j.Priority, java.lang.Object, java.lang.Throwable) @bci=14, line=388 (Interpreted frame)
 - org.apache.log4j.Category.log(java.lang.String, org.apache.log4j.Priority, java.lang.Object, java.lang.Throwable) @bci=34, line=853 (Compiled frame)
 - crazycode.team2Api.common.logging.DESLogger.debug(java.lang.Object) @bci=12, line=240 (Interpreted frame)
 - crazycode.api.core.cache.management.CacheFiller.refreshCache(java.util.List, java.lang.Object, java.lang.String) @bci=33, line=229 (Interpreted frame)
 - crazycode.api.core.cache.management.CacheFiller.initialize(java.lang.Object) @bci=70, line=285 (Interpreted frame)
 - crazycode.api.alert.impl.service.ResearchAlertConfigCacheImpl.init() @bci=18, line=110 (Interpreted frame)
 - crazycode.api.alert.impl.service.ResearchAlertConfigCacheImpl.initialize() @bci=1, line=98 (Interpreted frame)
 - crazycode.api.alert.handler.RkdResearchDocumentHandler.initRealHandler() @bci=86, line=779 (Interpreted frame)
 - crazycode.api.alert.handler.RealAlertCoordinator.initHandler(crazycode.api.alert.handler.AlertHandler, int, int, boolean, boolean) @bci=61, line=47 (Interpreted frame)
 - crazycode.api.alert.handler.run.BaseAlertHandlerRun$1$1.run() @bci=72, line=229 (Interpreted frame)
 - java.util.concurrent.Executors$RunnableAdapter.call() @bci=4, line=441 (Interpreted frame)
 - java.util.concurrent.FutureTask$Sync.innerRun() @bci=30, line=303 (Interpreted frame)
 - java.util.concurrent.FutureTask.run() @bci=4, line=138 (Interpreted frame)
 - java.util.concurrent.ThreadPoolExecutor$Worker.runTask(java.lang.Runnable) @bci=59, line=886 (Interpreted frame)
 - java.util.concurrent.ThreadPoolExecutor$Worker.run() @bci=28, line=908 (Interpreted frame)
 - java.lang.Thread.run() @bci=11, line=662 (Interpreted frame)

有人可以说明可能是什么问题以及解决方法是什么？

Answer 1

我今天在自己的代码中看到了类似的痕迹。也许它也适用于你？

总结：

• 之前（死锁）：logger.info(x);（其中x 是一个复杂的对象，它在toString() 内获取一个读锁）
• 之后（确定）：logger.info(x.toString());

详情：

在一个线程中，我调用了logger.info(x)，它调用了Category.callAppenders(LoggingEvent)，它在一个appender上同步，然后调用x.toString()，它试图在x上获取一个读锁并被阻塞。

在另一个线程中，我有一个方法在调用logger.info("")（也称为callAppenders）时保持x 上的写锁定，尝试在appender 上同步，并被阻塞。这是跟踪的相关部分：

Thread One [WAITING]
sun.misc.Unsafe.park(native method)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811)
java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireShared(AbstractQueuedSynchronizer.java:941)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(AbstractQueuedSynchronizer.java:1261)
(... my ReadWriteLock$ReadLock.lock(Lock.java:256))
(... my Object's toString() ...)
org.apache.log4j.or.DefaultRenderer.doRender(DefaultRenderer.java:36)
org.apache.log4j.or.RendererMap.findAndRender(RendererMap.java:80)
org.apache.log4j.spi.LoggingEvent.getRenderedMessage(LoggingEvent.java:362)
org.apache.log4j.xml.XMLLayout.format(XMLLayout.java:148)
org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:302)
org.apache.log4j.WriterAppender.append(WriterAppender.java:160)
org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
org.apache.log4j.Category.callAppenders(Category.java:206)
org.apache.log4j.Category.forcedLog(Category.java:391)
org.apache.log4j.Category.log(Category.java:856)
Log.ndebug(Log.java:965)



Thread Two [BLOCKED; waiting to lock org.apache.log4j.Logger@1623f]
org.apache.log4j.Category.callAppenders(Category.java:204)
org.apache.log4j.Category.forcedLog(Category.java:391)
org.apache.log4j.Category.log(Category.java:856)
Log.debug(Log.java:820)
(.. something that acquires my reentrant ReadWriteLock$WriteLock ...)

Answer 2

“主”线程和“pool-68-thread-1”线程是否有堆栈？我会查看堆栈的第一行，即您在每个线程中的代码，以找出可能导致死锁的原因。