Log4j тупик между Logger и Appender - PullRequest
Новая
       16

Log4j тупик между Logger и Appender

4 голосов
/ 23 августа 2011

Я использую класс LogAppender, который расширяет Console Appender и внутренне использует функцию Sendmail для отправки почты, если уровень журнала - ERROR.(Я знаю, что мог бы использовать приложение SMPT для отправки почты, но такова инфраструктура, поэтому избегайте комментариев по этому поводу.)

Мое приложение разбито на разные потоки, и проблема, упомянутая ниже, случаетсявремя от времени. (Но некоторые наблюдения говорят мне, что это может быть связано с тем, что одному потоку требуется больше времени для инициализации).

Я получаю следующий дамп в 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)

Может кто-то сбросить некоторыесвет в отношении того, что может быть проблемой и как ее решить ??

Ответы [ 2 ]

6 голосов
/ 13 сентября 2011

Сегодня я видел похожий след в моем собственном коде. Может это касается и тебя?

Резюме:

  • До (тупик): logger.info(x); (где x - сложный объект, который получает блокировку чтения в toString())
  • После (в порядке): logger.info(x.toString());

подробности:

В одном потоке я позвонил logger.info(x), который вызвал Category.callAppenders(LoggingEvent), который синхронизируется с аппендером, а затем вызывает x.toString(), который пытался получить блокировку чтения на x и заблокировал.

В другом потоке у меня был метод, который удерживал блокировку записи на x при вызове logger.info(""), который также вызывал callAppenders, пытался синхронизироваться с аппендером и блокировался. Вот соответствующая часть трассировки: 

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 ...)
0 голосов
/ 11 июля 2012

Существуют ли стеки для потоков "main" и "pool-68-thread-1"?Я бы посмотрел на первую строку в стеке - это ваш код в каждом из этих потоков, чтобы выяснить, что может вызвать тупик.

Добро пожаловать на сайт PullRequest, где вы можете задавать вопросы и получать ответы от других членов сообщества.

Похожие темы

...