This discussion is archived
6 Replies Latest reply: Jun 6, 2013 8:32 AM by 1010920 RSS

Observing lock when loading class by two thread, is it a JVM bug?

1010920 Newbie
Currently Being Moderated
We encountered the same problem described in ClassLoading locked when loading  class by two threads. The system blocked when trying to load such a class. I would just put the key points here.

public interface NestedThrowable extends Serializable {
    boolean PARENT_TRACE_ENABLED = Util.getBoolean("parentTraceEnabled", true);
    final class Util {
        private static Logger log = Logger.getLogger(NestedThrowable.class);
    }
}

The reply said:
Looks like it could be a static initialization deadlock.
The static initializer for NestedThrowable invokes Util, but the static initalizers in Util access NestedThrowable.class, and in 1.4 class literals cause class initialization.
So if thread 1 starts by initializing NestedThrowable, and thread 2 starts by initializing Util, they will both be waiting for the other to complete - hence deadlock.
Try to break the cyclic dependency between the two classes. For example, you could try replacing the use of the class literal with explicit loading through the classloader without asking for initialization using the long for of Class.forName.

I have read the JVM specification about initializing class. It could lock when initializing two classes which will try to initialize each other during the procedure by two threads in parallel. So there are two key point here:
1, these two classes must initialize each other during initializing procedure.
2, they must be initialized in parallel by two threads.

Regarding to 1st point, as mentioned in the reply, in 1.4 class literals cause class initialization. Here is the bug link [http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=4419673]. While it also mentioned that, after 1.5, class literals will not cause class initialization. We are using JDK 6, the first point does not match(Class literal which is "NestedThrowable.class" in Utill class will not cause intializing class NestedThrowable).

Then let turn back to 2nd point. According to JVM spec(http://docs.oracle.com/javase/specs/jvms/se5.0/html/Concepts.doc.html#19075),
a class or interface type T will be initialized immediately before one of the following occurs:
    *)T is a class and an instance of T is created.
    *)T is a class and a static method of T is invoked.
    *)A nonconstant static field of T is used or assigned. A constant field is one that is (explicitly or implicitly) both final and static, and that is initialized with the value of a compile-time constant expression. A reference to such a field must be resolved at compile time to a copy of the compile-time constant value, so uses of such a field never cause initialization.

In the problem we encountered, Util class is an inner class of interface NestedThrowable. Initializing class Util should always triggered by initializing interface NestedThrowable(when processing class variable initializer) in one thread. I did not a possibility to have two thread intializing these two call in parallel.

Any feedback is always appreciated.
  • 1. Re: Observing lock when loading class by two thread, is it a JVM bug?
    jschellSomeoneStoleMyAlias Expert
    Currently Being Moderated
    Initializer blocks (static or not) are just java code. If they block then the class doesn't initialize.

    Initialization statements involving classes are done in initializer blocks. So same thing applies.

    Does that answer it or is there a question when initializer blocks are not involved?
  • 2. Re: Observing lock when loading class by two thread, is it a JVM bug?
    1010920 Newbie
    Currently Being Moderated
    Thanks for you reply.

    I understand the class initialization, and understand if there are two threads simultaneously initializing those two classes, NestedThrowable and Util(which is an inner class of NestedThrowable). What I don't understand is how could it happen. The reasons are:
    1, We are using jdk6. According jvm spec, class literal will not cause class initialization. So even there are two threads are simultaneously initializing NestedThrowable and Util, there should not be a problem. Here is the scenario. Let's say Thread 1(T1) is initializing NestedThrowable, while Thread 2(T2) is initializing Util. When T1 is at
         boolean PARENT_TRACE_ENABLED = Util.getBoolean("parentTraceEnabled", true);
    T1 will try to initialize class Util. According to jvm spec, it will wait as there is another thread(T2) which is doing that. Then let's look at T2. when T2 is at
        private static Logger log = Logger.getLogger(NestedThrowable.class);
    T2 will not try to initialize class NestedThrowable. And T2 will finish initializing class Util normally. After T2 finishing initializing Util, T1 will continue to initialize NestedThrowable and finish it soon.

    2, Util is an inner class of NestedThrowable. Its initialization should always triggered by initializing NestedThrowable, which means there is not a chance for two thread to simultaneously initializing these two classess.
  • 3. Re: Observing lock when loading class by two thread, is it a JVM bug?
    jschellSomeoneStoleMyAlias Expert
    Currently Being Moderated
    Xi Feng wrote:
    I understand the class initialization, and understand if there are two threads simultaneously initializing those two classes, NestedThrowable and Util(which is an inner class of NestedThrowable).
    However that isn't what I said. And it certainly doesn't seem to have anything to do with your actual problem.

    The thread you posted provided a possible example which was true at the time which demonstrated the problem.

    Whether or not the example is still relevant doesn't alter the fact that it is still possible to produce a block during initialization. There are many ways to do it.
  • 4. Re: Observing lock when loading class by two thread, is it a JVM bug?
    1010920 Newbie
    Currently Being Moderated
    Sorry for late response. My point is that the problem should not happen if jdk6 is used, while it did occur. And I am thinking if there is a bug in jvm.
  • 5. Re: Observing lock when loading class by two thread, is it a JVM bug?
    jschellSomeoneStoleMyAlias Expert
    Currently Being Moderated
    Xi Feng wrote:
    My point is that the problem should not happen if jdk6 is used, while it did occur.
    AGAIN what problem?

    The bug refers to how literals are used. NOTHING else.

    Have you reduced your actual problem to the point where you can demonstrate it is caused by literals and NOTHING else?

    If so you can post it. If so then you already have the answer.

    However the bug has nothing to do with any of the other many ways that blocking can occur. And there is no way for the compiler/vm to prevent those.
  • 6. Re: Observing lock when loading class by two thread, is it a JVM bug?
    1010920 Newbie
    Currently Being Moderated
    Sorry for misleading you, and million thanks for your patience.

    I will explain what we encountered, so that you can understand. We were using Infinispan and our DHT nodes got stuck. We used jstack to dump the threads of jvm. Following are the detail:

    There are 707 thread got blocked by the same reason, "waiting to lock <0x00000006b44e0fd0>".
    "OOB-8540,xyz-cluster-ac18bde1,abcdtg-wc-3501-26791" prio=10 tid=0x00002aaad0393000 nid=0x2ed1 waiting for monitor entry [0x00002aaae5410000]
        java.lang.Thread.State: BLOCKED (on object monitor)
        at org.apache.log4j.Category.callAppenders(Category.java:204)
    *    - waiting to lock <0x00000006b44e0fd0> (a org.apache.log4j.spi.RootLogger)*
        at org.apache.log4j.Category.forcedLog(Category.java:391)
        at org.apache.log4j.Category.log(Category.java:856)
        at org.shaded.logging.Log4jLogger.doLogf(Log4jLogger.java:53)
        at org.shaded.logging.Logger.logf(Logger.java:2112)
        at org.infinispan.util.logging.Log_$logger.prepareViewIdMismatch(Log_$logger.java:897)

    And also, we observed following two:

    let's name following thread as T1
    "OOB-9340,xyz-cluster-ac18bde1,abcdtg-wc-3501-60671" prio=10 tid=0x00002aaabe625000 nid=0x2143 in Object.wait() [0x0000000050de8000]
        java.lang.Thread.State: RUNNABLE
    *    at org.jboss.util.NestedThrowable.<clinit>(NestedThrowable.java:51)*
        at org.jboss.tm.JBossRollbackException.printStackTrace(JBossRollbackException.java:113)
        at org.apache.log4j.DefaultThrowableRenderer.render(DefaultThrowableRenderer.java:60)
        at org.apache.log4j.spi.ThrowableInformation.getThrowableStrRep(ThrowableInformation.java:87)
        - locked <0x0000000714cbd200> (a org.apache.log4j.spi.ThrowableInformation)
        at org.apache.log4j.spi.LoggingEvent.getThrowableStrRep(LoggingEvent.java:413)
        at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:313)
        at org.apache.log4j.appender.TimeAndSizeRollingAppender.subAppend(TimeAndSizeRollingAppender.java:733)
        at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
        - locked <0x00000006b44f56c0> (a org.apache.log4j.appender.TimeAndSizeRollingAppender)
        at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
        at org.apache.log4j.Category.callAppenders(Category.java:206)
    *    - locked <0x00000006b44e0fd0> (a org.apache.log4j.spi.RootLogger)*
    ....


    And name this thread T2
    "http-0.0.0.0-8080-3" daemon prio=10 tid=0x00002aaac1a5d800 nid=0x7fb5 in Object.wait() [0x000000005e9c3000]
        java.lang.Thread.State: RUNNABLE
        at java.lang.Class.forName0(Native Method)
        at java.lang.Class.forName(Class.java:169)
        at org.jboss.util.NestedThrowable$1.class$(NestedThrowable.java:113)
    *    at org.jboss.util.NestedThrowable$Util.<clinit>(NestedThrowable.java:113)*
        at org.jboss.tm.JBossRollbackException.getMessage(JBossRollbackException.java:87)
        at java.lang.Throwable.getLocalizedMessage(Throwable.java:267)
        at java.lang.Throwable.toString(Throwable.java:343)
        at java.lang.Throwable.<init>(Throwable.java:242)
    ....

    According to stack trace of T1
    *    - locked <0x00000006b44e0fd0> (a org.apache.log4j.spi.RootLogger)*

    This is the root cause of 707 thread get blocked.

    While T1 and T2 both are "RUNNABLE", and after checking the code, we believe they are live locked(*this is the problem*).

    I am trying to state the live lock should not happen according to jvm spec and the fact that we were using jdk6.

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points