You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-user@logging.apache.org by Leon Finker <le...@gmail.com> on 2016/07/05 19:14:13 UTC
Logging stopped, but Log4j2-AsyncLogger is RUNNABLE and maybe stuck in ThrowableProxy.toExtendedStackTrace
Hi,
Using log4j2 runtime args with 2.6.1:
-DAsyncLogger.RingBufferSize=512
-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
On CentOS 6.7 and Java 1.8.0_60.
We noticed that at some point the process has stopped logging to the log file (during startup). When doing 7 thread dumps over 8 minutes the AsyncLogger thread is Runnable, but always in the below stack trace. And all the other threads are TIMED_WAITING to publish new log events RingBuffer.publishEvent. Has anyone seen this before? There was no log entries for at least 25 minutes till we killed the process and restarted it without problems. If AsyncLogger was progressing properly, something would appear in the log file (RollingRandomAccessFile is configured with immediateFlush=true). It's hard to know how big the stack length was in the ThrowableProxy.toExtendedStackTrace. But the threas is not BLOCKED, it's RUNNABLE. Also it doesn't look like there is a way to limit the stack depth for the toExtendedStackTrace?
"Log4j2-AsyncLogger[AsyncContext@18b4aac2]1" #16 daemon prio=5 os_prio=0 tid=0x00007ff870c7b000 nid=0x79f3 in Object.wait() [0x00007ff839142000]
java.lang.Thread.State: RUNNABLE
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Class.java:348)
at org.apache.logging.log4j.core.util.Loader.initializeClass(Loader.java:241)
at org.apache.logging.log4j.core.impl.ThrowableProxy.loadClass(ThrowableProxy.java:487)
at org.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTrace(ThrowableProxy.java:617)
at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:135)
at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:117)
at org.apache.logging.log4j.core.async.RingBufferLogEvent.getThrownProxy(RingBufferLogEvent.java:316)
at org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter.format(ExtendedThrowablePatternConverter.java:61)
at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:38)
at org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializable(PatternLayout.java:288)
at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:194)
at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:180)
at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:57)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:113)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:104)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:99)
at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:155)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:128)
at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:119)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390)
at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:375)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)
at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:381)
at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:376)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)
at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:79)
at org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(AsyncLogger.java:310)
at org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:149)
at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:45)
at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:29)
at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:129)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Other threads are blocked as in this example stack trace:
"metrics-logger-reporter-1-thread-1" #20 daemon prio=5 os_prio=0 tid=0x00007ff870e7f800 nid=0x7a0c runnable [0x00007ff838a26000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:450)
at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:315)
at org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageInfo(AsyncLoggerDisruptor.java:203)
at org.apache.logging.log4j.core.async.AsyncLogger.handleRingBufferFull(AsyncLogger.java:170)
at org.apache.logging.log4j.core.async.AsyncLogger.publish(AsyncLogger.java:162)
at org.apache.logging.log4j.core.async.AsyncLogger.logWithThreadLocalTranslator(AsyncLogger.java:157)
at org.apache.logging.log4j.core.async.AsyncLogger.logMessage(AsyncLogger.java:127)
at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2013)
at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1882)
at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:229)
at com.codahale.metrics.Slf4jReporter$InfoLoggerProxy.log(Slf4jReporter.java:337)
at com.codahale.metrics.Slf4jReporter.logGauge(Slf4jReporter.java:270)
at com.codahale.metrics.Slf4jReporter.report(Slf4jReporter.java:187)
at com.codahale.metrics.ScheduledReporter.report(ScheduledReporter.java:162)
- locked <0x00000006dcadc538> (a com.codahale.metrics.Slf4jReporter)
at com.codahale.metrics.ScheduledReporter$1.run(ScheduledReporter.java:117)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Logging stopped, but Log4j2-AsyncLogger is RUNNABLE and maybe stuck in ThrowableProxy.toExtendedStackTrace
Posted by Leon Finker <le...@gmail.com>.
Done: https://issues.apache.org/jira/browse/LOG4J2-1457
Thank you
On 2016-07-06 10:44 (-0400), Remko Popma <re...@gmail.com> wrote:
> Leon, I would like to see this myself. Is it possible to attach the full thread dump or create a Jira ticket with the full thread dump?
>
> Sent from my iPhone
>
> > On 2016/07/06, at 23:06, Leon Finker <le...@gmail.com> wrote:
> >
> > Based on google searches, it turns out to be a classic class loading deadlock. I found one thread that was inside the class' static initializer: <clinit>, which then eventually ended up logging indirectly and getting blocked on:
> > at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
> > at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
> > at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
> > at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:450)
> > at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:315)
> > at org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageInfo(AsyncLoggerDisruptor.java:203)
> > ..
> >
> > And the AsyncLogger thread is blocked trying to walk the above thread stack and getting deadlocked on the same class that was in <clinit>. It's a large codebase, so hard to review all the libraries and uses. But now we know what to look out for if it happens again. This can happen with async logging.
> >
> > Basically one thread would be in RUNNABLE state, but will say "in Object.wait()" and another thread would be in <clinit>.
> >
> >> On 2016-07-05 20:10 (-0400), Remko Popma <re...@gmail.com> wrote:
> >> The StackOverflow link may still be relevant if the problem is caused by class loading (by different classloaders?) from different threads.
> >>
> >> Leon, is there any other thread in the thread dump that is loading a class?
> >>
> >> Sent from my iPhone
> >>
> >>> On 2016/07/06, at 6:31, Ralph Goers <ra...@dslextreme.com> wrote:
> >>>
> >>> The stack overflow reference is using Log4j 1, so that isn\u2019t a match.
> >>>
> >>> Based on the fact that you are in ExtendedThrowablePatternConverter that would imply that you are logging an exception. But I don\u2019t know why you would be getting stuck in there. While formatting the exception is slow, it shouldn\u2019t be that slow.
> >>>
> >>> Ralph
> >>>
> >>>> On Jul 5, 2016, at 2:03 PM, Leon Finker <le...@gmail.com> wrote:
> >>>>
> >>>> This looks similar:
> >>>> http://stackoverflow.com/questions/15543521/mixed-usage-of-log4j-and-commons-logging-causes-a-class-loading-deadlock
> >>>>
> >>>> But we don't use any other logging framework besides slf4j, log4j2 and log4j2 bridges.
> >>>>
> >>>>> On 2016-07-05 15:14 (-0400), "Leon Finker"<le...@gmail.com> wrote:
> >>>>> Hi,
> >>>>>
> >>>>> Using log4j2 runtime args with 2.6.1:
> >>>>> -DAsyncLogger.RingBufferSize=512
> >>>>> -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
> >>>>>
> >>>>> On CentOS 6.7 and Java 1.8.0_60.
> >>>>>
> >>>>> We noticed that at some point the process has stopped logging to the log file (during startup). When doing 7 thread dumps over 8 minutes the AsyncLogger thread is Runnable, but always in the below stack trace. And all the other threads are TIMED_WAITING to publish new log events RingBuffer.publishEvent. Has anyone seen this before? There was no log entries for at least 25 minutes till we killed the process and restarted it without problems. If AsyncLogger was progressing properly, something would appear in the log file (RollingRandomAccessFile is configured with immediateFlush=true). It's hard to know how big the stack length was in the ThrowableProxy.toExtendedStackTrace. But the threas is not BLOCKED, it's RUNNABLE. Also it doesn't look like there is a way to limit the stack depth for the toExtendedStackTrace?
> >>>>>
> >>>>> "Log4j2-AsyncLogger[AsyncContext@18b4aac2]1" #16 daemon prio=5 os_prio=0 tid=0x00007ff870c7b000 nid=0x79f3 in Object.wait() [0x00007ff839142000]
> >>>>> java.lang.Thread.State: RUNNABLE
> >>>>> at java.lang.Class.forName0(Native Method)
> >>>>> at java.lang.Class.forName(Class.java:348)
> >>>>> at org.apache.logging.log4j.core.util.Loader.initializeClass(Loader.java:241)
> >>>>> at org.apache.logging.log4j.core.impl.ThrowableProxy.loadClass(ThrowableProxy.java:487)
> >>>>> at org.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTrace(ThrowableProxy.java:617)
> >>>>> at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:135)
> >>>>> at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:117)
> >>>>> at org.apache.logging.log4j.core.async.RingBufferLogEvent.getThrownProxy(RingBufferLogEvent.java:316)
> >>>>> at org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter.format(ExtendedThrowablePatternConverter.java:61)
> >>>>> at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:38)
> >>>>> at org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializable(PatternLayout.java:288)
> >>>>> at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:194)
> >>>>> at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:180)
> >>>>> at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:57)
> >>>>> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:120)
> >>>>> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:113)
> >>>>> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:104)
> >>>>> at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:99)
> >>>>> at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:155)
> >>>>> at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:128)
> >>>>> at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:119)
> >>>>> at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
> >>>>> at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390)
> >>>>> at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:375)
> >>>>> at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)
> >>>>> at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:381)
> >>>>> at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:376)
> >>>>> at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)
> >>>>> at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:79)
> >>>>> at org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(AsyncLogger.java:310)
> >>>>> at org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:149)
> >>>>> at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:45)
> >>>>> at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:29)
> >>>>> at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:129)
> >>>>> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> >>>>> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> >>>>> at java.lang.Thread.run(Thread.java:745)
> >>>>>
> >>>>>
> >>>>> Other threads are blocked as in this example stack trace:
> >>>>> "metrics-logger-reporter-1-thread-1" #20 daemon prio=5 os_prio=0 tid=0x00007ff870e7f800 nid=0x7a0c runnable [0x00007ff838a26000]
> >>>>> java.lang.Thread.State: TIMED_WAITING (parking)
> >>>>> at sun.misc.Unsafe.park(Native Method)
> >>>>> at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
> >>>>> at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
> >>>>> at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
> >>>>> at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:450)
> >>>>> at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:315)
> >>>>> at org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageInfo(AsyncLoggerDisruptor.java:203)
> >>>>> at org.apache.logging.log4j.core.async.AsyncLogger.handleRingBufferFull(AsyncLogger.java:170)
> >>>>> at org.apache.logging.log4j.core.async.AsyncLogger.publish(AsyncLogger.java:162)
> >>>>> at org.apache.logging.log4j.core.async.AsyncLogger.logWithThreadLocalTranslator(AsyncLogger.java:157)
> >>>>> at org.apache.logging.log4j.core.async.AsyncLogger.logMessage(AsyncLogger.java:127)
> >>>>> at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2013)
> >>>>> at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1882)
> >>>>> at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:229)
> >>>>> at com.codahale.metrics.Slf4jReporter$InfoLoggerProxy.log(Slf4jReporter.java:337)
> >>>>> at com.codahale.metrics.Slf4jReporter.logGauge(Slf4jReporter.java:270)
> >>>>> at com.codahale.metrics.Slf4jReporter.report(Slf4jReporter.java:187)
> >>>>> at com.codahale.metrics.ScheduledReporter.report(ScheduledReporter.java:162)
> >>>>> - locked <0x00000006dcadc538> (a com.codahale.metrics.Slf4jReporter)
> >>>>> at com.codahale.metrics.ScheduledReporter$1.run(ScheduledReporter.java:117)
> >>>>> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> >>>>> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
> >>>>> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
> >>>>> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
> >>>>> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> >>>>> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> >>>>> at java.lang.Thread.run(Thread.java:745)
> >>>>>
> >>>>>
> >>>>> ---------------------------------------------------------------------
> >>>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> >>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
> >>>>
> >>>> ---------------------------------------------------------------------
> >>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> >>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
> >>>
> >>>
> >>>
> >>> ---------------------------------------------------------------------
> >>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> >>> For additional commands, e-mail: log4j-user-help@logging.apache.org
> >>>
> >>
> >> ---------------------------------------------------------------------
> >> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> >> For additional commands, e-mail: log4j-user-help@logging.apache.org
> >>
> >>
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> > For additional commands, e-mail: log4j-user-help@logging.apache.org
> >
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Logging stopped, but Log4j2-AsyncLogger is RUNNABLE and maybe stuck in ThrowableProxy.toExtendedStackTrace
Posted by Remko Popma <re...@gmail.com>.
Leon, I would like to see this myself. Is it possible to attach the full thread dump or create a Jira ticket with the full thread dump?
Sent from my iPhone
> On 2016/07/06, at 23:06, Leon Finker <le...@gmail.com> wrote:
>
> Based on google searches, it turns out to be a classic class loading deadlock. I found one thread that was inside the class' static initializer: <clinit>, which then eventually ended up logging indirectly and getting blocked on:
> at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
> at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
> at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
> at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:450)
> at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:315)
> at org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageInfo(AsyncLoggerDisruptor.java:203)
> ..
>
> And the AsyncLogger thread is blocked trying to walk the above thread stack and getting deadlocked on the same class that was in <clinit>. It's a large codebase, so hard to review all the libraries and uses. But now we know what to look out for if it happens again. This can happen with async logging.
>
> Basically one thread would be in RUNNABLE state, but will say "in Object.wait()" and another thread would be in <clinit>.
>
>> On 2016-07-05 20:10 (-0400), Remko Popma <re...@gmail.com> wrote:
>> The StackOverflow link may still be relevant if the problem is caused by class loading (by different classloaders?) from different threads.
>>
>> Leon, is there any other thread in the thread dump that is loading a class?
>>
>> Sent from my iPhone
>>
>>> On 2016/07/06, at 6:31, Ralph Goers <ra...@dslextreme.com> wrote:
>>>
>>> The stack overflow reference is using Log4j 1, so that isn’t a match.
>>>
>>> Based on the fact that you are in ExtendedThrowablePatternConverter that would imply that you are logging an exception. But I don’t know why you would be getting stuck in there. While formatting the exception is slow, it shouldn’t be that slow.
>>>
>>> Ralph
>>>
>>>> On Jul 5, 2016, at 2:03 PM, Leon Finker <le...@gmail.com> wrote:
>>>>
>>>> This looks similar:
>>>> http://stackoverflow.com/questions/15543521/mixed-usage-of-log4j-and-commons-logging-causes-a-class-loading-deadlock
>>>>
>>>> But we don't use any other logging framework besides slf4j, log4j2 and log4j2 bridges.
>>>>
>>>>> On 2016-07-05 15:14 (-0400), "Leon Finker"<le...@gmail.com> wrote:
>>>>> Hi,
>>>>>
>>>>> Using log4j2 runtime args with 2.6.1:
>>>>> -DAsyncLogger.RingBufferSize=512
>>>>> -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
>>>>>
>>>>> On CentOS 6.7 and Java 1.8.0_60.
>>>>>
>>>>> We noticed that at some point the process has stopped logging to the log file (during startup). When doing 7 thread dumps over 8 minutes the AsyncLogger thread is Runnable, but always in the below stack trace. And all the other threads are TIMED_WAITING to publish new log events RingBuffer.publishEvent. Has anyone seen this before? There was no log entries for at least 25 minutes till we killed the process and restarted it without problems. If AsyncLogger was progressing properly, something would appear in the log file (RollingRandomAccessFile is configured with immediateFlush=true). It's hard to know how big the stack length was in the ThrowableProxy.toExtendedStackTrace. But the threas is not BLOCKED, it's RUNNABLE. Also it doesn't look like there is a way to limit the stack depth for the toExtendedStackTrace?
>>>>>
>>>>> "Log4j2-AsyncLogger[AsyncContext@18b4aac2]1" #16 daemon prio=5 os_prio=0 tid=0x00007ff870c7b000 nid=0x79f3 in Object.wait() [0x00007ff839142000]
>>>>> java.lang.Thread.State: RUNNABLE
>>>>> at java.lang.Class.forName0(Native Method)
>>>>> at java.lang.Class.forName(Class.java:348)
>>>>> at org.apache.logging.log4j.core.util.Loader.initializeClass(Loader.java:241)
>>>>> at org.apache.logging.log4j.core.impl.ThrowableProxy.loadClass(ThrowableProxy.java:487)
>>>>> at org.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTrace(ThrowableProxy.java:617)
>>>>> at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:135)
>>>>> at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:117)
>>>>> at org.apache.logging.log4j.core.async.RingBufferLogEvent.getThrownProxy(RingBufferLogEvent.java:316)
>>>>> at org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter.format(ExtendedThrowablePatternConverter.java:61)
>>>>> at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:38)
>>>>> at org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializable(PatternLayout.java:288)
>>>>> at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:194)
>>>>> at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:180)
>>>>> at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:57)
>>>>> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:120)
>>>>> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:113)
>>>>> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:104)
>>>>> at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:99)
>>>>> at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:155)
>>>>> at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:128)
>>>>> at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:119)
>>>>> at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
>>>>> at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390)
>>>>> at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:375)
>>>>> at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)
>>>>> at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:381)
>>>>> at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:376)
>>>>> at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)
>>>>> at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:79)
>>>>> at org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(AsyncLogger.java:310)
>>>>> at org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:149)
>>>>> at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:45)
>>>>> at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:29)
>>>>> at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:129)
>>>>> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>>>>> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>>>>> at java.lang.Thread.run(Thread.java:745)
>>>>>
>>>>>
>>>>> Other threads are blocked as in this example stack trace:
>>>>> "metrics-logger-reporter-1-thread-1" #20 daemon prio=5 os_prio=0 tid=0x00007ff870e7f800 nid=0x7a0c runnable [0x00007ff838a26000]
>>>>> java.lang.Thread.State: TIMED_WAITING (parking)
>>>>> at sun.misc.Unsafe.park(Native Method)
>>>>> at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
>>>>> at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
>>>>> at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
>>>>> at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:450)
>>>>> at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:315)
>>>>> at org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageInfo(AsyncLoggerDisruptor.java:203)
>>>>> at org.apache.logging.log4j.core.async.AsyncLogger.handleRingBufferFull(AsyncLogger.java:170)
>>>>> at org.apache.logging.log4j.core.async.AsyncLogger.publish(AsyncLogger.java:162)
>>>>> at org.apache.logging.log4j.core.async.AsyncLogger.logWithThreadLocalTranslator(AsyncLogger.java:157)
>>>>> at org.apache.logging.log4j.core.async.AsyncLogger.logMessage(AsyncLogger.java:127)
>>>>> at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2013)
>>>>> at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1882)
>>>>> at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:229)
>>>>> at com.codahale.metrics.Slf4jReporter$InfoLoggerProxy.log(Slf4jReporter.java:337)
>>>>> at com.codahale.metrics.Slf4jReporter.logGauge(Slf4jReporter.java:270)
>>>>> at com.codahale.metrics.Slf4jReporter.report(Slf4jReporter.java:187)
>>>>> at com.codahale.metrics.ScheduledReporter.report(ScheduledReporter.java:162)
>>>>> - locked <0x00000006dcadc538> (a com.codahale.metrics.Slf4jReporter)
>>>>> at com.codahale.metrics.ScheduledReporter$1.run(ScheduledReporter.java:117)
>>>>> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
>>>>> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
>>>>> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
>>>>> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
>>>>> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>>>>> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>>>>> at java.lang.Thread.run(Thread.java:745)
>>>>>
>>>>>
>>>>> ---------------------------------------------------------------------
>>>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>>
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Logging stopped, but Log4j2-AsyncLogger is RUNNABLE and maybe stuck in ThrowableProxy.toExtendedStackTrace
Posted by Ralph Goers <ra...@dslextreme.com>.
If you know what the cause is please add that information to the Jira issue. I’d really like to understand what is causing this.
Ralph
> On Jul 6, 2016, at 7:06 AM, Leon Finker <le...@gmail.com> wrote:
>
> Based on google searches, it turns out to be a classic class loading deadlock. I found one thread that was inside the class' static initializer: <clinit>, which then eventually ended up logging indirectly and getting blocked on:
> at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
> at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
> at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
> at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:450)
> at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:315)
> at org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageInfo(AsyncLoggerDisruptor.java:203)
> ..
>
> And the AsyncLogger thread is blocked trying to walk the above thread stack and getting deadlocked on the same class that was in <clinit>. It's a large codebase, so hard to review all the libraries and uses. But now we know what to look out for if it happens again. This can happen with async logging.
>
> Basically one thread would be in RUNNABLE state, but will say "in Object.wait()" and another thread would be in <clinit>.
>
> On 2016-07-05 20:10 (-0400), Remko Popma <remko.popma@gmail.com <ma...@gmail.com>> wrote:
>> The StackOverflow link may still be relevant if the problem is caused by class loading (by different classloaders?) from different threads.
>>
>> Leon, is there any other thread in the thread dump that is loading a class?
>>
>> Sent from my iPhone
>>
>>> On 2016/07/06, at 6:31, Ralph Goers <ralph.goers@dslextreme.com <ma...@dslextreme.com>> wrote:
>>>
>>> The stack overflow reference is using Log4j 1, so that isnât a match.
>>>
>>> Based on the fact that you are in ExtendedThrowablePatternConverter that would imply that you are logging an exception. But I donât know why you would be getting stuck in there. While formatting the exception is slow, it shouldnât be that slow.
>>>
>>> Ralph
>>>
>>>> On Jul 5, 2016, at 2:03 PM, Leon Finker <le...@gmail.com> wrote:
>>>>
>>>> This looks similar:
>>>> http://stackoverflow.com/questions/15543521/mixed-usage-of-log4j-and-commons-logging-causes-a-class-loading-deadlock
>>>>
>>>> But we don't use any other logging framework besides slf4j, log4j2 and log4j2 bridges.
>>>>
>>>>> On 2016-07-05 15:14 (-0400), "Leon Finker"<le...@gmail.com> wrote:
>>>>> Hi,
>>>>>
>>>>> Using log4j2 runtime args with 2.6.1:
>>>>> -DAsyncLogger.RingBufferSize=512
>>>>> -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
>>>>>
>>>>> On CentOS 6.7 and Java 1.8.0_60.
>>>>>
>>>>> We noticed that at some point the process has stopped logging to the log file (during startup). When doing 7 thread dumps over 8 minutes the AsyncLogger thread is Runnable, but always in the below stack trace. And all the other threads are TIMED_WAITING to publish new log events RingBuffer.publishEvent. Has anyone seen this before? There was no log entries for at least 25 minutes till we killed the process and restarted it without problems. If AsyncLogger was progressing properly, something would appear in the log file (RollingRandomAccessFile is configured with immediateFlush=true). It's hard to know how big the stack length was in the ThrowableProxy.toExtendedStackTrace. But the threas is not BLOCKED, it's RUNNABLE. Also it doesn't look like there is a way to limit the stack depth for the toExtendedStackTrace?
>>>>>
>>>>> "Log4j2-AsyncLogger[AsyncContext@18b4aac2]1" #16 daemon prio=5 os_prio=0 tid=0x00007ff870c7b000 nid=0x79f3 in Object.wait() [0x00007ff839142000]
>>>>> java.lang.Thread.State: RUNNABLE
>>>>> at java.lang.Class.forName0(Native Method)
>>>>> at java.lang.Class.forName(Class.java:348)
>>>>> at org.apache.logging.log4j.core.util.Loader.initializeClass(Loader.java:241)
>>>>> at org.apache.logging.log4j.core.impl.ThrowableProxy.loadClass(ThrowableProxy.java:487)
>>>>> at org.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTrace(ThrowableProxy.java:617)
>>>>> at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:135)
>>>>> at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:117)
>>>>> at org.apache.logging.log4j.core.async.RingBufferLogEvent.getThrownProxy(RingBufferLogEvent.java:316)
>>>>> at org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter.format(ExtendedThrowablePatternConverter.java:61)
>>>>> at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:38)
>>>>> at org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializable(PatternLayout.java:288)
>>>>> at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:194)
>>>>> at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:180)
>>>>> at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:57)
>>>>> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:120)
>>>>> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:113)
>>>>> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:104)
>>>>> at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:99)
>>>>> at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:155)
>>>>> at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:128)
>>>>> at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:119)
>>>>> at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
>>>>> at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390)
>>>>> at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:375)
>>>>> at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)
>>>>> at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:381)
>>>>> at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:376)
>>>>> at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)
>>>>> at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:79)
>>>>> at org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(AsyncLogger.java:310)
>>>>> at org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:149)
>>>>> at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:45)
>>>>> at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:29)
>>>>> at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:129)
>>>>> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>>>>> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>>>>> at java.lang.Thread.run(Thread.java:745)
>>>>>
>>>>>
>>>>> Other threads are blocked as in this example stack trace:
>>>>> "metrics-logger-reporter-1-thread-1" #20 daemon prio=5 os_prio=0 tid=0x00007ff870e7f800 nid=0x7a0c runnable [0x00007ff838a26000]
>>>>> java.lang.Thread.State: TIMED_WAITING (parking)
>>>>> at sun.misc.Unsafe.park(Native Method)
>>>>> at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
>>>>> at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
>>>>> at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
>>>>> at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:450)
>>>>> at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:315)
>>>>> at org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageInfo(AsyncLoggerDisruptor.java:203)
>>>>> at org.apache.logging.log4j.core.async.AsyncLogger.handleRingBufferFull(AsyncLogger.java:170)
>>>>> at org.apache.logging.log4j.core.async.AsyncLogger.publish(AsyncLogger.java:162)
>>>>> at org.apache.logging.log4j.core.async.AsyncLogger.logWithThreadLocalTranslator(AsyncLogger.java:157)
>>>>> at org.apache.logging.log4j.core.async.AsyncLogger.logMessage(AsyncLogger.java:127)
>>>>> at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2013)
>>>>> at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1882)
>>>>> at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:229)
>>>>> at com.codahale.metrics.Slf4jReporter$InfoLoggerProxy.log(Slf4jReporter.java:337)
>>>>> at com.codahale.metrics.Slf4jReporter.logGauge(Slf4jReporter.java:270)
>>>>> at com.codahale.metrics.Slf4jReporter.report(Slf4jReporter.java:187)
>>>>> at com.codahale.metrics.ScheduledReporter.report(ScheduledReporter.java:162)
>>>>> - locked <0x00000006dcadc538> (a com.codahale.metrics.Slf4jReporter)
>>>>> at com.codahale.metrics.ScheduledReporter$1.run(ScheduledReporter.java:117)
>>>>> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
>>>>> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
>>>>> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
>>>>> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
>>>>> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>>>>> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>>>>> at java.lang.Thread.run(Thread.java:745)
>>>>>
>>>>>
>>>>> ---------------------------------------------------------------------
>>>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>>
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org <ma...@logging.apache.org>
> For additional commands, e-mail: log4j-user-help@logging.apache.org <ma...@logging.apache.org>
Re: Logging stopped, but Log4j2-AsyncLogger is RUNNABLE and maybe stuck in ThrowableProxy.toExtendedStackTrace
Posted by Leon Finker <le...@gmail.com>.
Based on google searches, it turns out to be a classic class loading deadlock. I found one thread that was inside the class' static initializer: <clinit>, which then eventually ended up logging indirectly and getting blocked on:
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:450)
at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:315)
at org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageInfo(AsyncLoggerDisruptor.java:203)
..
And the AsyncLogger thread is blocked trying to walk the above thread stack and getting deadlocked on the same class that was in <clinit>. It's a large codebase, so hard to review all the libraries and uses. But now we know what to look out for if it happens again. This can happen with async logging.
Basically one thread would be in RUNNABLE state, but will say "in Object.wait()" and another thread would be in <clinit>.
On 2016-07-05 20:10 (-0400), Remko Popma <re...@gmail.com> wrote:
> The StackOverflow link may still be relevant if the problem is caused by class loading (by different classloaders?) from different threads.
>
> Leon, is there any other thread in the thread dump that is loading a class?
>
> Sent from my iPhone
>
> > On 2016/07/06, at 6:31, Ralph Goers <ra...@dslextreme.com> wrote:
> >
> > The stack overflow reference is using Log4j 1, so that isn\u2019t a match.
> >
> > Based on the fact that you are in ExtendedThrowablePatternConverter that would imply that you are logging an exception. But I don\u2019t know why you would be getting stuck in there. While formatting the exception is slow, it shouldn\u2019t be that slow.
> >
> > Ralph
> >
> >> On Jul 5, 2016, at 2:03 PM, Leon Finker <le...@gmail.com> wrote:
> >>
> >> This looks similar:
> >> http://stackoverflow.com/questions/15543521/mixed-usage-of-log4j-and-commons-logging-causes-a-class-loading-deadlock
> >>
> >> But we don't use any other logging framework besides slf4j, log4j2 and log4j2 bridges.
> >>
> >>> On 2016-07-05 15:14 (-0400), "Leon Finker"<le...@gmail.com> wrote:
> >>> Hi,
> >>>
> >>> Using log4j2 runtime args with 2.6.1:
> >>> -DAsyncLogger.RingBufferSize=512
> >>> -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
> >>>
> >>> On CentOS 6.7 and Java 1.8.0_60.
> >>>
> >>> We noticed that at some point the process has stopped logging to the log file (during startup). When doing 7 thread dumps over 8 minutes the AsyncLogger thread is Runnable, but always in the below stack trace. And all the other threads are TIMED_WAITING to publish new log events RingBuffer.publishEvent. Has anyone seen this before? There was no log entries for at least 25 minutes till we killed the process and restarted it without problems. If AsyncLogger was progressing properly, something would appear in the log file (RollingRandomAccessFile is configured with immediateFlush=true). It's hard to know how big the stack length was in the ThrowableProxy.toExtendedStackTrace. But the threas is not BLOCKED, it's RUNNABLE. Also it doesn't look like there is a way to limit the stack depth for the toExtendedStackTrace?
> >>>
> >>> "Log4j2-AsyncLogger[AsyncContext@18b4aac2]1" #16 daemon prio=5 os_prio=0 tid=0x00007ff870c7b000 nid=0x79f3 in Object.wait() [0x00007ff839142000]
> >>> java.lang.Thread.State: RUNNABLE
> >>> at java.lang.Class.forName0(Native Method)
> >>> at java.lang.Class.forName(Class.java:348)
> >>> at org.apache.logging.log4j.core.util.Loader.initializeClass(Loader.java:241)
> >>> at org.apache.logging.log4j.core.impl.ThrowableProxy.loadClass(ThrowableProxy.java:487)
> >>> at org.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTrace(ThrowableProxy.java:617)
> >>> at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:135)
> >>> at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:117)
> >>> at org.apache.logging.log4j.core.async.RingBufferLogEvent.getThrownProxy(RingBufferLogEvent.java:316)
> >>> at org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter.format(ExtendedThrowablePatternConverter.java:61)
> >>> at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:38)
> >>> at org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializable(PatternLayout.java:288)
> >>> at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:194)
> >>> at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:180)
> >>> at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:57)
> >>> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:120)
> >>> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:113)
> >>> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:104)
> >>> at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:99)
> >>> at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:155)
> >>> at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:128)
> >>> at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:119)
> >>> at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
> >>> at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390)
> >>> at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:375)
> >>> at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)
> >>> at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:381)
> >>> at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:376)
> >>> at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)
> >>> at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:79)
> >>> at org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(AsyncLogger.java:310)
> >>> at org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:149)
> >>> at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:45)
> >>> at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:29)
> >>> at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:129)
> >>> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> >>> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> >>> at java.lang.Thread.run(Thread.java:745)
> >>>
> >>>
> >>> Other threads are blocked as in this example stack trace:
> >>> "metrics-logger-reporter-1-thread-1" #20 daemon prio=5 os_prio=0 tid=0x00007ff870e7f800 nid=0x7a0c runnable [0x00007ff838a26000]
> >>> java.lang.Thread.State: TIMED_WAITING (parking)
> >>> at sun.misc.Unsafe.park(Native Method)
> >>> at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
> >>> at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
> >>> at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
> >>> at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:450)
> >>> at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:315)
> >>> at org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageInfo(AsyncLoggerDisruptor.java:203)
> >>> at org.apache.logging.log4j.core.async.AsyncLogger.handleRingBufferFull(AsyncLogger.java:170)
> >>> at org.apache.logging.log4j.core.async.AsyncLogger.publish(AsyncLogger.java:162)
> >>> at org.apache.logging.log4j.core.async.AsyncLogger.logWithThreadLocalTranslator(AsyncLogger.java:157)
> >>> at org.apache.logging.log4j.core.async.AsyncLogger.logMessage(AsyncLogger.java:127)
> >>> at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2013)
> >>> at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1882)
> >>> at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:229)
> >>> at com.codahale.metrics.Slf4jReporter$InfoLoggerProxy.log(Slf4jReporter.java:337)
> >>> at com.codahale.metrics.Slf4jReporter.logGauge(Slf4jReporter.java:270)
> >>> at com.codahale.metrics.Slf4jReporter.report(Slf4jReporter.java:187)
> >>> at com.codahale.metrics.ScheduledReporter.report(ScheduledReporter.java:162)
> >>> - locked <0x00000006dcadc538> (a com.codahale.metrics.Slf4jReporter)
> >>> at com.codahale.metrics.ScheduledReporter$1.run(ScheduledReporter.java:117)
> >>> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> >>> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
> >>> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
> >>> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
> >>> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> >>> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> >>> at java.lang.Thread.run(Thread.java:745)
> >>>
> >>>
> >>> ---------------------------------------------------------------------
> >>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> >>> For additional commands, e-mail: log4j-user-help@logging.apache.org
> >>
> >> ---------------------------------------------------------------------
> >> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> >> For additional commands, e-mail: log4j-user-help@logging.apache.org
> >
> >
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> > For additional commands, e-mail: log4j-user-help@logging.apache.org
> >
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Logging stopped, but Log4j2-AsyncLogger is RUNNABLE and maybe stuck in ThrowableProxy.toExtendedStackTrace
Posted by Remko Popma <re...@gmail.com>.
The StackOverflow link may still be relevant if the problem is caused by class loading (by different classloaders?) from different threads.
Leon, is there any other thread in the thread dump that is loading a class?
Sent from my iPhone
> On 2016/07/06, at 6:31, Ralph Goers <ra...@dslextreme.com> wrote:
>
> The stack overflow reference is using Log4j 1, so that isn’t a match.
>
> Based on the fact that you are in ExtendedThrowablePatternConverter that would imply that you are logging an exception. But I don’t know why you would be getting stuck in there. While formatting the exception is slow, it shouldn’t be that slow.
>
> Ralph
>
>> On Jul 5, 2016, at 2:03 PM, Leon Finker <le...@gmail.com> wrote:
>>
>> This looks similar:
>> http://stackoverflow.com/questions/15543521/mixed-usage-of-log4j-and-commons-logging-causes-a-class-loading-deadlock
>>
>> But we don't use any other logging framework besides slf4j, log4j2 and log4j2 bridges.
>>
>>> On 2016-07-05 15:14 (-0400), "Leon Finker"<le...@gmail.com> wrote:
>>> Hi,
>>>
>>> Using log4j2 runtime args with 2.6.1:
>>> -DAsyncLogger.RingBufferSize=512
>>> -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
>>>
>>> On CentOS 6.7 and Java 1.8.0_60.
>>>
>>> We noticed that at some point the process has stopped logging to the log file (during startup). When doing 7 thread dumps over 8 minutes the AsyncLogger thread is Runnable, but always in the below stack trace. And all the other threads are TIMED_WAITING to publish new log events RingBuffer.publishEvent. Has anyone seen this before? There was no log entries for at least 25 minutes till we killed the process and restarted it without problems. If AsyncLogger was progressing properly, something would appear in the log file (RollingRandomAccessFile is configured with immediateFlush=true). It's hard to know how big the stack length was in the ThrowableProxy.toExtendedStackTrace. But the threas is not BLOCKED, it's RUNNABLE. Also it doesn't look like there is a way to limit the stack depth for the toExtendedStackTrace?
>>>
>>> "Log4j2-AsyncLogger[AsyncContext@18b4aac2]1" #16 daemon prio=5 os_prio=0 tid=0x00007ff870c7b000 nid=0x79f3 in Object.wait() [0x00007ff839142000]
>>> java.lang.Thread.State: RUNNABLE
>>> at java.lang.Class.forName0(Native Method)
>>> at java.lang.Class.forName(Class.java:348)
>>> at org.apache.logging.log4j.core.util.Loader.initializeClass(Loader.java:241)
>>> at org.apache.logging.log4j.core.impl.ThrowableProxy.loadClass(ThrowableProxy.java:487)
>>> at org.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTrace(ThrowableProxy.java:617)
>>> at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:135)
>>> at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:117)
>>> at org.apache.logging.log4j.core.async.RingBufferLogEvent.getThrownProxy(RingBufferLogEvent.java:316)
>>> at org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter.format(ExtendedThrowablePatternConverter.java:61)
>>> at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:38)
>>> at org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializable(PatternLayout.java:288)
>>> at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:194)
>>> at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:180)
>>> at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:57)
>>> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:120)
>>> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:113)
>>> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:104)
>>> at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:99)
>>> at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:155)
>>> at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:128)
>>> at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:119)
>>> at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
>>> at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390)
>>> at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:375)
>>> at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)
>>> at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:381)
>>> at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:376)
>>> at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)
>>> at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:79)
>>> at org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(AsyncLogger.java:310)
>>> at org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:149)
>>> at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:45)
>>> at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:29)
>>> at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:129)
>>> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>>> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>>> at java.lang.Thread.run(Thread.java:745)
>>>
>>>
>>> Other threads are blocked as in this example stack trace:
>>> "metrics-logger-reporter-1-thread-1" #20 daemon prio=5 os_prio=0 tid=0x00007ff870e7f800 nid=0x7a0c runnable [0x00007ff838a26000]
>>> java.lang.Thread.State: TIMED_WAITING (parking)
>>> at sun.misc.Unsafe.park(Native Method)
>>> at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
>>> at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
>>> at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
>>> at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:450)
>>> at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:315)
>>> at org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageInfo(AsyncLoggerDisruptor.java:203)
>>> at org.apache.logging.log4j.core.async.AsyncLogger.handleRingBufferFull(AsyncLogger.java:170)
>>> at org.apache.logging.log4j.core.async.AsyncLogger.publish(AsyncLogger.java:162)
>>> at org.apache.logging.log4j.core.async.AsyncLogger.logWithThreadLocalTranslator(AsyncLogger.java:157)
>>> at org.apache.logging.log4j.core.async.AsyncLogger.logMessage(AsyncLogger.java:127)
>>> at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2013)
>>> at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1882)
>>> at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:229)
>>> at com.codahale.metrics.Slf4jReporter$InfoLoggerProxy.log(Slf4jReporter.java:337)
>>> at com.codahale.metrics.Slf4jReporter.logGauge(Slf4jReporter.java:270)
>>> at com.codahale.metrics.Slf4jReporter.report(Slf4jReporter.java:187)
>>> at com.codahale.metrics.ScheduledReporter.report(ScheduledReporter.java:162)
>>> - locked <0x00000006dcadc538> (a com.codahale.metrics.Slf4jReporter)
>>> at com.codahale.metrics.ScheduledReporter$1.run(ScheduledReporter.java:117)
>>> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
>>> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
>>> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
>>> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
>>> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>>> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>>> at java.lang.Thread.run(Thread.java:745)
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Logging stopped, but Log4j2-AsyncLogger is RUNNABLE and maybe stuck in ThrowableProxy.toExtendedStackTrace
Posted by Ralph Goers <ra...@dslextreme.com>.
The stack overflow reference is using Log4j 1, so that isn’t a match.
Based on the fact that you are in ExtendedThrowablePatternConverter that would imply that you are logging an exception. But I don’t know why you would be getting stuck in there. While formatting the exception is slow, it shouldn’t be that slow.
Ralph
> On Jul 5, 2016, at 2:03 PM, Leon Finker <le...@gmail.com> wrote:
>
> This looks similar:
> http://stackoverflow.com/questions/15543521/mixed-usage-of-log4j-and-commons-logging-causes-a-class-loading-deadlock
>
> But we don't use any other logging framework besides slf4j, log4j2 and log4j2 bridges.
>
> On 2016-07-05 15:14 (-0400), "Leon Finker"<le...@gmail.com> wrote:
>> Hi,
>>
>> Using log4j2 runtime args with 2.6.1:
>> -DAsyncLogger.RingBufferSize=512
>> -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
>>
>> On CentOS 6.7 and Java 1.8.0_60.
>>
>> We noticed that at some point the process has stopped logging to the log file (during startup). When doing 7 thread dumps over 8 minutes the AsyncLogger thread is Runnable, but always in the below stack trace. And all the other threads are TIMED_WAITING to publish new log events RingBuffer.publishEvent. Has anyone seen this before? There was no log entries for at least 25 minutes till we killed the process and restarted it without problems. If AsyncLogger was progressing properly, something would appear in the log file (RollingRandomAccessFile is configured with immediateFlush=true). It's hard to know how big the stack length was in the ThrowableProxy.toExtendedStackTrace. But the threas is not BLOCKED, it's RUNNABLE. Also it doesn't look like there is a way to limit the stack depth for the toExtendedStackTrace?
>>
>> "Log4j2-AsyncLogger[AsyncContext@18b4aac2]1" #16 daemon prio=5 os_prio=0 tid=0x00007ff870c7b000 nid=0x79f3 in Object.wait() [0x00007ff839142000]
>> java.lang.Thread.State: RUNNABLE
>> at java.lang.Class.forName0(Native Method)
>> at java.lang.Class.forName(Class.java:348)
>> at org.apache.logging.log4j.core.util.Loader.initializeClass(Loader.java:241)
>> at org.apache.logging.log4j.core.impl.ThrowableProxy.loadClass(ThrowableProxy.java:487)
>> at org.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTrace(ThrowableProxy.java:617)
>> at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:135)
>> at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:117)
>> at org.apache.logging.log4j.core.async.RingBufferLogEvent.getThrownProxy(RingBufferLogEvent.java:316)
>> at org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter.format(ExtendedThrowablePatternConverter.java:61)
>> at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:38)
>> at org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializable(PatternLayout.java:288)
>> at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:194)
>> at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:180)
>> at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:57)
>> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:120)
>> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:113)
>> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:104)
>> at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:99)
>> at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:155)
>> at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:128)
>> at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:119)
>> at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
>> at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390)
>> at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:375)
>> at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)
>> at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:381)
>> at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:376)
>> at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)
>> at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:79)
>> at org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(AsyncLogger.java:310)
>> at org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:149)
>> at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:45)
>> at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:29)
>> at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:129)
>> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>> at java.lang.Thread.run(Thread.java:745)
>>
>>
>> Other threads are blocked as in this example stack trace:
>> "metrics-logger-reporter-1-thread-1" #20 daemon prio=5 os_prio=0 tid=0x00007ff870e7f800 nid=0x7a0c runnable [0x00007ff838a26000]
>> java.lang.Thread.State: TIMED_WAITING (parking)
>> at sun.misc.Unsafe.park(Native Method)
>> at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
>> at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
>> at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
>> at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:450)
>> at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:315)
>> at org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageInfo(AsyncLoggerDisruptor.java:203)
>> at org.apache.logging.log4j.core.async.AsyncLogger.handleRingBufferFull(AsyncLogger.java:170)
>> at org.apache.logging.log4j.core.async.AsyncLogger.publish(AsyncLogger.java:162)
>> at org.apache.logging.log4j.core.async.AsyncLogger.logWithThreadLocalTranslator(AsyncLogger.java:157)
>> at org.apache.logging.log4j.core.async.AsyncLogger.logMessage(AsyncLogger.java:127)
>> at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2013)
>> at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1882)
>> at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:229)
>> at com.codahale.metrics.Slf4jReporter$InfoLoggerProxy.log(Slf4jReporter.java:337)
>> at com.codahale.metrics.Slf4jReporter.logGauge(Slf4jReporter.java:270)
>> at com.codahale.metrics.Slf4jReporter.report(Slf4jReporter.java:187)
>> at com.codahale.metrics.ScheduledReporter.report(ScheduledReporter.java:162)
>> - locked <0x00000006dcadc538> (a com.codahale.metrics.Slf4jReporter)
>> at com.codahale.metrics.ScheduledReporter$1.run(ScheduledReporter.java:117)
>> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
>> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
>> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
>> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
>> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>> at java.lang.Thread.run(Thread.java:745)
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Logging stopped, but Log4j2-AsyncLogger is RUNNABLE and maybe stuck in ThrowableProxy.toExtendedStackTrace
Posted by Leon Finker <le...@gmail.com>.
This looks similar:
http://stackoverflow.com/questions/15543521/mixed-usage-of-log4j-and-commons-logging-causes-a-class-loading-deadlock
But we don't use any other logging framework besides slf4j, log4j2 and log4j2 bridges.
On 2016-07-05 15:14 (-0400), "Leon Finker"<le...@gmail.com> wrote:
> Hi,
>
> Using log4j2 runtime args with 2.6.1:
> -DAsyncLogger.RingBufferSize=512
> -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
>
> On CentOS 6.7 and Java 1.8.0_60.
>
> We noticed that at some point the process has stopped logging to the log file (during startup). When doing 7 thread dumps over 8 minutes the AsyncLogger thread is Runnable, but always in the below stack trace. And all the other threads are TIMED_WAITING to publish new log events RingBuffer.publishEvent. Has anyone seen this before? There was no log entries for at least 25 minutes till we killed the process and restarted it without problems. If AsyncLogger was progressing properly, something would appear in the log file (RollingRandomAccessFile is configured with immediateFlush=true). It's hard to know how big the stack length was in the ThrowableProxy.toExtendedStackTrace. But the threas is not BLOCKED, it's RUNNABLE. Also it doesn't look like there is a way to limit the stack depth for the toExtendedStackTrace?
>
> "Log4j2-AsyncLogger[AsyncContext@18b4aac2]1" #16 daemon prio=5 os_prio=0 tid=0x00007ff870c7b000 nid=0x79f3 in Object.wait() [0x00007ff839142000]
> java.lang.Thread.State: RUNNABLE
> at java.lang.Class.forName0(Native Method)
> at java.lang.Class.forName(Class.java:348)
> at org.apache.logging.log4j.core.util.Loader.initializeClass(Loader.java:241)
> at org.apache.logging.log4j.core.impl.ThrowableProxy.loadClass(ThrowableProxy.java:487)
> at org.apache.logging.log4j.core.impl.ThrowableProxy.toExtendedStackTrace(ThrowableProxy.java:617)
> at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:135)
> at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:117)
> at org.apache.logging.log4j.core.async.RingBufferLogEvent.getThrownProxy(RingBufferLogEvent.java:316)
> at org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter.format(ExtendedThrowablePatternConverter.java:61)
> at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:38)
> at org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializable(PatternLayout.java:288)
> at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:194)
> at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:180)
> at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:57)
> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:120)
> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:113)
> at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:104)
> at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:99)
> at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:155)
> at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:128)
> at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:119)
> at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
> at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390)
> at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:375)
> at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)
> at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:381)
> at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:376)
> at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359)
> at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:79)
> at org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(AsyncLogger.java:310)
> at org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:149)
> at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:45)
> at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:29)
> at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:129)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
>
>
> Other threads are blocked as in this example stack trace:
> "metrics-logger-reporter-1-thread-1" #20 daemon prio=5 os_prio=0 tid=0x00007ff870e7f800 nid=0x7a0c runnable [0x00007ff838a26000]
> java.lang.Thread.State: TIMED_WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
> at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
> at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
> at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:450)
> at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:315)
> at org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageInfo(AsyncLoggerDisruptor.java:203)
> at org.apache.logging.log4j.core.async.AsyncLogger.handleRingBufferFull(AsyncLogger.java:170)
> at org.apache.logging.log4j.core.async.AsyncLogger.publish(AsyncLogger.java:162)
> at org.apache.logging.log4j.core.async.AsyncLogger.logWithThreadLocalTranslator(AsyncLogger.java:157)
> at org.apache.logging.log4j.core.async.AsyncLogger.logMessage(AsyncLogger.java:127)
> at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2013)
> at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1882)
> at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:229)
> at com.codahale.metrics.Slf4jReporter$InfoLoggerProxy.log(Slf4jReporter.java:337)
> at com.codahale.metrics.Slf4jReporter.logGauge(Slf4jReporter.java:270)
> at com.codahale.metrics.Slf4jReporter.report(Slf4jReporter.java:187)
> at com.codahale.metrics.ScheduledReporter.report(ScheduledReporter.java:162)
> - locked <0x00000006dcadc538> (a com.codahale.metrics.Slf4jReporter)
> at com.codahale.metrics.ScheduledReporter$1.run(ScheduledReporter.java:117)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org