Done: https://issues.apache.org/jira/browse/LOG4J2-1457
Thank you On 2016-07-06 10:44 (-0400), Remko Popma <remko.po...@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 <leon...@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.po...@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.go...@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 <leon...@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"<leon...@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-unsubscr...@logging.apache.org > >>>>> For additional commands, e-mail: log4j-user-h...@logging.apache.org > >>>> > >>>> --------------------------------------------------------------------- > >>>> To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org > >>>> For additional commands, e-mail: log4j-user-h...@logging.apache.org > >>> > >>> > >>> > >>> --------------------------------------------------------------------- > >>> To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org > >>> For additional commands, e-mail: log4j-user-h...@logging.apache.org > >>> > >> > >> --------------------------------------------------------------------- > >> To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org > >> For additional commands, e-mail: log4j-user-h...@logging.apache.org > >> > >> > > > > --------------------------------------------------------------------- > > To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org > > For additional commands, e-mail: log4j-user-h...@logging.apache.org > > > > --------------------------------------------------------------------- > To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org > For additional commands, e-mail: log4j-user-h...@logging.apache.org > > --------------------------------------------------------------------- To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org For additional commands, e-mail: log4j-user-h...@logging.apache.org
