Log4j deadlock auftreten zwischen Logger und Appender

Ich bin mit einem LogAppender Klasse die sich ein Console Appender und intern verwendet, eine Sendmail-Funktion zum senden von mails, wenn der log-level ERROR.
(Ich weiß, ich hätte einen SMPT-appender für den Versand, aber das ist, wie die Infrastruktur ist, so dass jede vermeiden Sie bitte jegliche Kommentare zu diesem).

Meine Anwendung ist aufgeteilt in verschiedenen threads, und das Thema, die unten erwähnt werden happends sporadisch.(Aber etwas Beobachtung sagt mir, dass es vielleicht wegen einem thread mehr Zeit nehmen, um initalize).

Bekomme ich folgenden dump in 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)

Kann jemand etwas Licht, was könnte das Problem sein und was sind die Möglichkeiten, es zu lösen??

  • Ich kann nicht sicher sagen, aber dies scheint ein Fehler in Ihrem eigenen code, nicht in log4j. Überprüfen Sie alle Ihre synchronisierten Blöcken und synchronisierten Methoden, die für die wichtigsten und für Sie die Fäden in Ihrem pool. Schauen Sie für die wichtigsten sperren (einige object ' s monitor) und dann B (ein anderes), und einen thread aus dem pool Verriegelung B und dann A.
InformationsquelleAutor Neeraj | 2011-08-23
  1. 7

    Sah ich eine ähnliche Spur, die heute in meinem eigenen code. Vielleicht ist es für Euch auch gilt?

    Zusammenfassung:

    • Vor (deadlock): logger.info(x); (wo x ist ein kompliziertes Objekt, erwirbt eine Lesesperre in toString())
    • Nach (ok): logger.info(x.toString());

    Details:

    In einem thread von mir genannt logger.info(x), das heißt Category.callAppenders(LoggingEvent), die synchronisiert auf einen appender und ruft dann x.toString(), die versucht, den Erwerb einer Lesesperre auf x und blockiert.

    In einem anderen thread hatte ich eine Methode, die statt der write-lock auf x beim Aufruf logger.info(""), die auch als callAppenders versuchte zu synchronisieren, die auf einem appender, und blockiert. Hier ist der relevante Teil der Spur:

    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 ...)
    • war diese gelöst, nachdem Sie die änderungen, die Sie descire in der Nach dem label?
    • Ja. Mein code war verursacht einen deadlock, da logger.info(x) x aufgerufen.toString (), die erworben mein eigenes Schloss, und einem anderen thread, dass meine eigenen lock genannt logger.info("").
    InformationsquelleAutor yonran
  2. 0

    Gibt es stacks für die "Haupt" - thread und "pool-68-thread-1" - threads? Ich hatte Blick auf die erste Zeile des stack-das ist Ihr code, der in jedem dieser threads, um herauszufinden, was möglicherweise verursacht die Sackgasse.

    InformationsquelleAutor Marcus
Schreibe einen Kommentar