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
