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: [email protected]
For additional commands, e-mail: [email protected]
