logging-log4j-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Ralph Goers <ralph.go...@dslextreme.com>
Subject Re: Logging stopped, but Log4j2-AsyncLogger is RUNNABLE and maybe stuck in ThrowableProxy.toExtendedStackTrace
Date Tue, 05 Jul 2016 21:31:26 GMT
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 <leonfin@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"<leonfin@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


Mime
View raw message