You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by "Leon Finker (JIRA)" <ji...@apache.org> on 2016/07/06 14:57:10 UTC
[jira] [Updated] (LOG4J2-1457) Class loader deadlock when using
async logging
[ https://issues.apache.org/jira/browse/LOG4J2-1457?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Leon Finker updated LOG4J2-1457:
--------------------------------
Attachment: threaddump.txt
> Class loader deadlock when using async logging
> ----------------------------------------------
>
> Key: LOG4J2-1457
> URL: https://issues.apache.org/jira/browse/LOG4J2-1457
> Project: Log4j 2
> Issue Type: Bug
> Affects Versions: 2.6.1
> Environment: On CentOS 6.7 and Java 1.8.0_60.
> Reporter: Leon Finker
> Priority: Critical
> Attachments: threaddump.txt
>
>
> We've encountered a class loading deadlock. Please review attached thread dump. Is it possible to have an option of pre-initializing the exception's thread stack on the caller's thread? It's hard to predict what libraries are doing in their classes' static initializers and may eventually end up logging and causing deadlock.
> In the attached thread dump here are the threads of interest:
> "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)
> ...
> and
> "1A03340:Company:japan" #568 prio=5 os_prio=0 tid=0x00007ff871677000 nid=0x725 runnable [0x00007ff74bd27000]
> ...<clinit>...
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: [jira] [Updated] (LOG4J2-1457) Class loader deadlock when using async logging
Posted by Leon Finker <le...@gmail.com>.
This application doesn't create any other class loaders besides the standard. It's regular JVM app (not tomcat or any other hosted process).
According to: http://docs.oracle.com/javase/7/docs/technotes/guides/lang/cl-mt.html
The class loading lock is done on class loader + class name since Java 7+. We are on Java 1.8.
The only other thread that I see is in static initializer is:
"1A03340:x:japan" #568 prio=5 os_prio=0 tid=0x00007ff871677000 nid=0x725 runnable [0x00007ff74bd27000]
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.ExtendedLoggerWrapper.logMessage(ExtendedLoggerWrapper.java:217)
at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1827)
at org.apache.logging.log4j.spi.AbstractLogger.warn(AbstractLogger.java:2505)
at com.gemstone.gemfire.internal.cache.PoolManagerImpl.allPoolsRegisterInstantiator(PoolManagerImpl.java:235)
at com.gemstone.gemfire.internal.InternalInstantiator.sendRegistrationMessageToServers(InternalInstantiator.java:215)
at com.gemstone.gemfire.internal.InternalInstantiator._register(InternalInstantiator.java:166)
- locked <0x00000006dcbc8e08> (a java.lang.Class for com.gemstone.gemfire.internal.InternalInstantiator)
at com.gemstone.gemfire.internal.InternalInstantiator.register(InternalInstantiator.java:92)
- locked <0x00000006dcbc8e08> (a java.lang.Class for com.gemstone.gemfire.internal.InternalInstantiator)
at com.gemstone.gemfire.Instantiator.register(Instantiator.java:175)
- locked <0x00000006dcfe3300> (a java.lang.Class for com.gemstone.gemfire.Instantiator)
at x.core.services.x.xMessageWrapper.<clinit>(xMessageWrapper.java:31)
at x.core.services.x.GemFirexMapEntryFactory.createValue(GemFirexMapEntryFactory.java:22)
And that is logging a warning with exception:
} catch (RuntimeException e) {
next.getLoggerI18n().warning(LocalizedStrings.PoolmanagerImpl_ERROR_REGISTERING_INSTANTIATOR_ON_POOL, e);
}
But I'm not sure why this thread would cause a deadlock. Unless there was another exception that made it's way to the async logger thread and that exception as well had the above <clinit> mentioned class in it's call stack. But then the class would have been already initialized. So still not sure what causes the class loader deadlock. Looking over thread dumps for 8 minutes the thread dumps are in same place (and as well for next 30 mins there was no logging). So it must be the cause somehow. Also, this is the first time we've seen this. We have already enabled async logging in many services for some time and no such issues observed.
On 2016-07-06 12:09 (-0400), Ralph Goers <ra...@dslextreme.com> wrote:
> Do you know what the exception is and where it originated from? Does it correlate in any way to the other threads that are marked as runnable?
>
> Ralph
>
> > On Jul 6, 2016, at 8:14 AM, Leon Finker <le...@gmail.com> wrote:
> >
> > Although I'm still not clear why it deadlocks. I can confirm the thread in <clinit> is logging an exception. But if the AsyncLogger thread picked up this same event (assumption), why the thread in <clinit> doesn't continue...
> >
> > On 2016-07-06 10:57 (-0400), "Leon Finker (JIRA)" <ji...@apache.org> wrote:
> >>
> >> [ https://issues.apache.org/jira/browse/LOG4J2-1457?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
> >>
> >> Leon Finker updated LOG4J2-1457:
> >> --------------------------------
> >> Attachment: threaddump.txt
> >>
> >>> Class loader deadlock when using async logging
> >>> ----------------------------------------------
> >>>
> >>> Key: LOG4J2-1457
> >>> URL: https://issues.apache.org/jira/browse/LOG4J2-1457
> >>> Project: Log4j 2
> >>> Issue Type: Bug
> >>> Affects Versions: 2.6.1
> >>> Environment: On CentOS 6.7 and Java 1.8.0_60.
> >>> Reporter: Leon Finker
> >>> Priority: Critical
> >>> Attachments: threaddump.txt
> >>>
> >>>
> >>> We've encountered a class loading deadlock. Please review attached thread dump. Is it possible to have an option of pre-initializing the exception's thread stack on the caller's thread? It's hard to predict what libraries are doing in their classes' static initializers and may eventually end up logging and causing deadlock.
> >>> In the attached thread dump here are the threads of interest:
> >>> "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)
> >>> ...
> >>> and
> >>> "1A03340:Company:japan" #568 prio=5 os_prio=0 tid=0x00007ff871677000 nid=0x725 runnable [0x00007ff74bd27000]
> >>> ...<clinit>...
> >>
> >>
> >>
> >> --
> >> This message was sent by Atlassian JIRA
> >> (v6.3.4#6332)
> >>
> >> ---------------------------------------------------------------------
> >> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> >> For additional commands, e-mail: log4j-dev-help@logging.apache.org
> >>
> >>
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> > For additional commands, e-mail: log4j-dev-help@logging.apache.org
> >
> >
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: [jira] [Updated] (LOG4J2-1457) Class loader deadlock when using async logging
Posted by Ralph Goers <ra...@dslextreme.com>.
Do you know what the exception is and where it originated from? Does it correlate in any way to the other threads that are marked as runnable?
Ralph
> On Jul 6, 2016, at 8:14 AM, Leon Finker <le...@gmail.com> wrote:
>
> Although I'm still not clear why it deadlocks. I can confirm the thread in <clinit> is logging an exception. But if the AsyncLogger thread picked up this same event (assumption), why the thread in <clinit> doesn't continue...
>
> On 2016-07-06 10:57 (-0400), "Leon Finker (JIRA)" <ji...@apache.org> wrote:
>>
>> [ https://issues.apache.org/jira/browse/LOG4J2-1457?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
>>
>> Leon Finker updated LOG4J2-1457:
>> --------------------------------
>> Attachment: threaddump.txt
>>
>>> Class loader deadlock when using async logging
>>> ----------------------------------------------
>>>
>>> Key: LOG4J2-1457
>>> URL: https://issues.apache.org/jira/browse/LOG4J2-1457
>>> Project: Log4j 2
>>> Issue Type: Bug
>>> Affects Versions: 2.6.1
>>> Environment: On CentOS 6.7 and Java 1.8.0_60.
>>> Reporter: Leon Finker
>>> Priority: Critical
>>> Attachments: threaddump.txt
>>>
>>>
>>> We've encountered a class loading deadlock. Please review attached thread dump. Is it possible to have an option of pre-initializing the exception's thread stack on the caller's thread? It's hard to predict what libraries are doing in their classes' static initializers and may eventually end up logging and causing deadlock.
>>> In the attached thread dump here are the threads of interest:
>>> "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)
>>> ...
>>> and
>>> "1A03340:Company:japan" #568 prio=5 os_prio=0 tid=0x00007ff871677000 nid=0x725 runnable [0x00007ff74bd27000]
>>> ...<clinit>...
>>
>>
>>
>> --
>> This message was sent by Atlassian JIRA
>> (v6.3.4#6332)
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: [jira] [Updated] (LOG4J2-1457) Class loader deadlock when using async logging
Posted by Leon Finker <le...@gmail.com>.
Although I'm still not clear why it deadlocks. I can confirm the thread in <clinit> is logging an exception. But if the AsyncLogger thread picked up this same event (assumption), why the thread in <clinit> doesn't continue...
On 2016-07-06 10:57 (-0400), "Leon Finker (JIRA)" <ji...@apache.org> wrote:
>
> [ https://issues.apache.org/jira/browse/LOG4J2-1457?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
>
> Leon Finker updated LOG4J2-1457:
> --------------------------------
> Attachment: threaddump.txt
>
> > Class loader deadlock when using async logging
> > ----------------------------------------------
> >
> > Key: LOG4J2-1457
> > URL: https://issues.apache.org/jira/browse/LOG4J2-1457
> > Project: Log4j 2
> > Issue Type: Bug
> > Affects Versions: 2.6.1
> > Environment: On CentOS 6.7 and Java 1.8.0_60.
> > Reporter: Leon Finker
> > Priority: Critical
> > Attachments: threaddump.txt
> >
> >
> > We've encountered a class loading deadlock. Please review attached thread dump. Is it possible to have an option of pre-initializing the exception's thread stack on the caller's thread? It's hard to predict what libraries are doing in their classes' static initializers and may eventually end up logging and causing deadlock.
> > In the attached thread dump here are the threads of interest:
> > "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)
> > ...
> > and
> > "1A03340:Company:japan" #568 prio=5 os_prio=0 tid=0x00007ff871677000 nid=0x725 runnable [0x00007ff74bd27000]
> > ...<clinit>...
>
>
>
> --
> This message was sent by Atlassian JIRA
> (v6.3.4#6332)
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org