Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-6471736

Ctrl-Break dump: threads waiting on monitors info is incorrect

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Fixed
    • Icon: P4 P4
    • hs10
    • 6
    • hotspot
    • None
    • b03
    • generic
    • generic

        This bug in Ctrl-Break dump was discovered in the process of analysis of the deadlock in
        java.util.logging.LogManager:
          6467152 deadlock occurs in LogManager initialization and JVM termination(5.0u8)
        Please, read the bug 6467152 evaluation.
        The bug 6467152 is intermittent and easily reproducible on Windows XP but it
        can be reproduced on Solaris-10+ if two loops of 1000 runs are running in parallel.
        The following test is from the bug 6467152 attachment:

        % cat test.java
        import java.util.logging.*;

        class test implements Runnable{
            static Object lock = new Object();
            static int c = 0;
            public static void main( String arg[] ) {
        try {
        new Thread(new test()).start();
        synchronized(lock) {
        c++;
        if ( c == 2 ) lock.notify(); else lock.wait();
        }
        LogManager log = LogManager.getLogManager();
        }
        catch(Exception e) { e.printStackTrace(); }
            }

            public void run() {
        try {
        synchronized( lock ) {
        c++;
        if ( c == 2 ) lock.notify(); else lock.wait();
        }
        System.exit(1);
        }
        catch(Exception e) { e.printStackTrace(); }
            }
        }

        I was lucky to reproduce this problem on Solaris 11 (x86 machine: bonsai.sfbay)
        where the pstack utility is available. The JDK 1.5.0_08-b03 was used.
        But, probably, the same bug can be reproduced with JDK 6 and JDK 7.

        The Ctrl-Break dump below provides incorrect info about the Thread-1.
        It says that Thread-1 waiting to lock <0xb5627710> (a java.util.logging.LogManager)
        which is not correct. In fact, Thread-1 has already locked this monitor
        and blocked on waiting for LogManager initialization.

        Running: 802
        Ctrl/Quit
        ss45998@bonsai Full thread dump Java HotSpot(TM) Server VM (1.5.0_08-b03 mixed mode):

        "Thread-1" prio=10 tid=0x081a4c38 nid=0xe in Object.wait() [0x94c02000..0x94c02ba8]
        at java.util.logging.LogManager$Cleaner.run(LogManager.java:204)
        - waiting to lock <0xb5627710> (a java.util.logging.LogManager) <=== INCORRECT info!!!
        ...................................................
        "main" prio=10 tid=0x08074680 nid=0x1 waiting for monitor entry [0x08046000..0x08046de8]
        at java.util.logging.LogManager.addLogger(LogManager.java:322)
        - waiting to lock <0xb5627710> (a java.util.logging.LogManager)
        at java.util.logging.LogManager$1.run(LogManager.java:180)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.util.logging.LogManager.<clinit>(LogManager.java:156)
        at test.main(test.java:14)

        However, the pstack output shows clearly how the deadlock happens between LogManager.<clinit>
        (thread# 1) and Cleaner.run (thread# 14). All unrelated threads are skipped:

        ss45998@bonsai /usr/bin/i86/pstack 18480 | c++filt
        18480: /java/re/jdk/1.5.0_08/promoted/latest/binaries/solaris-i586/bin/java t
        ----------------- lwp# 1 / thread# 1 --------------------
         bff393e7 lwp_cond_wait (80752d0, 80752b8, 0, 0)
         bf9d59ec void os::Solaris::Event::park() (8075290) + 4c
         bf9d3d71 void ObjectMonitor::EnterI(Thread*) (818b2a4, 8074680) + 161
         bf9f0f84 void ObjectMonitor::enter2(Thread*) (818b2a4, 8074680) + 244
         bf92c753 void ObjectMonitor::enter(Thread*) (818b2a4, 8074680) + 83
         bf9299da void ObjectSynchronizer::slow_enter(Handle,BasicLock*,Thread*) (8140e7c, 80463e8, 8074680) + 19a
         bf94447d void InterpreterRuntime::monitorenter(JavaThread*,BasicObjectLock*) (8074680, 80463e8, b9207977, 3, b5627710, 80463e8) + 7d
         b920799d * java/util/logging/LogManager.addLogger(Ljava/util/logging/Logger;)Z+0
         b9202a13 * java/util/logging/LogManager$1.run()Ljava/lang/Object;+144 (line 180)
         bf940704 * StubRoutines (1)
         bf940704 void os::os_exception_wrapper(void(*)(JavaValue*,methodHandle*,JavaCallArguments*,Thread*),JavaValue*,methodHandle*,JavaCallArguments*,Thread*) (80466c4, 8046560, 80466d0, 8074680, 8046554, bf940738) + 14
         bf940704 void os::os_exception_wrapper(void(*)(JavaValue*,methodHandle*,JavaCallArguments*,Thread*),JavaValue*,methodHandle*,JavaCallArguments*,Thread*) (bf9402b0, 80466c4, 8046560, 80466d0, 8074680) + 14
         bf940738 void JavaCalls::call(JavaValue*,methodHandle,JavaCallArguments*,Thread*) (80466c4, 8140e78, 80466d0, 8074680) + 28
         bf99749c JVM_DoPrivileged (8074740, 804680c, 8046814, 0, 0) + 39c
         bf4f88e2 Java_java_security_AccessController_doPrivileged__Ljava_security_PrivilegedAction_2 (8074740, 804680c, 8046814, 80467e8, 0, 8046814) + 22
         b920843a * java/security/AccessController.doPrivileged(Ljava/security/PrivilegedAction;)Ljava/lang/Object;+0
         b9202a94 * java/util/logging/LogManager.<clinit>()V+20 (line 156)
         bf940704 * StubRoutines (1)
         bf940704 void os::os_exception_wrapper(void(*)(JavaValue*,methodHandle*,JavaCallArguments*,Thread*),JavaValue*,methodHandle*,JavaCallArguments*,Thread*) (80469a4, 8046930, 8046948, 8074680, 8046924, bf940738) + 14
         bf940704 void os::os_exception_wrapper(void(*)(JavaValue*,methodHandle*,JavaCallArguments*,Thread*),JavaValue*,methodHandle*,JavaCallArguments*,Thread*) (bf9402b0, 80469a4, 8046930, 8046948, 8074680) + 14
         bf940738 void JavaCalls::call(JavaValue*,methodHandle,JavaCallArguments*,Thread*) (80469a4, 8140e70, 8046948, 8074680) + 28
         bf975c2a void instanceKlass::call_class_initializer_impl(instanceKlassHandle,Thread*) (8140e6c, 8074680) + aa
         bf975dc8 void instanceKlass::call_class_initializer(Thread*) (94f727d8, 8074680) + 58
         bf9244b9 void instanceKlass::initialize_impl(instanceKlassHandle,Thread*) (8074c68, 8074680) + 309
         bf917838 void instanceKlass::initialize(Thread*) (94f727d8, 8074680) + 78
         bf9399e0 void LinkResolver::resolve_static_call(CallInfo&,KlassHandle&,symbolHandle,symbolHandle,KlassHandle,int,int,Thread*) (8046c44, 8046b58, 8074c44, 8074c48, 8074c4c, 1) + e0
         bf955b17 void LinkResolver::resolve_invokestatic(CallInfo&,constantPoolHandle,int,Thread*) (8046c44, 8074c1c, 800, 8074680) + 67
         bf91a387 void LinkResolver::resolve_invoke(CallInfo&,Handle,constantPoolHandle,int,Bytecodes::Code,Thread*) (8046c44, 0, 8074c1c, 800, b8, 8074680) + 76
         bf91c337 void InterpreterRuntime::resolve_invoke(JavaThread*,Bytecodes::Code) (8074680, b8, b920fe68, 1, 0, 8046cfc) + 4b7
         b920fe8e * test.main([Ljava/lang/String;)V+63 (line 14)
         bf940704 * StubRoutines (1)
         bf940704 void os::os_exception_wrapper(void(*)(JavaValue*,methodHandle*,JavaCallArguments*,Thread*),JavaValue*,methodHandle*,JavaCallArguments*,Thread*) (8046f20, 8046e28, 8046e58, 8074680, 8046e1c, bf940738) + 14
         bf940704 void os::os_exception_wrapper(void(*)(JavaValue*,methodHandle*,JavaCallArguments*,Thread*),JavaValue*,methodHandle*,JavaCallArguments*,Thread*) (bf9402b0, 8046f20, 8046e28, 8046e58, 8074680) + 14
         bf940738 void JavaCalls::call(JavaValue*,methodHandle,JavaCallArguments*,Thread*) (8046f20, 8074c14, 8046e58, 8074680) + 28
         bf9f9740 void jni_invoke_static(JNIEnv_*,JavaValue*,_jobject*,JNICallType,_jmethodID*,JNI_ArgumentPusher*,Thread*) (8074740, 8046f20, 0, 0, 807220a, 8046f2c) + 180
         bfa04d5c jni_CallStaticVoidMethod (8074740, 8075204, 807220a, 80751f4) + 14c
         08051e87 main (0, 806f780, 80477f4) + af4
         080512fa ???????? (2, 80478f0, 8047935, 0, 804793a, 8047966) + 480b12fa


        ----------------- lwp# 14 / thread# 14 --------------------
         bff393e7 lwp_cond_wait (81a57c0, 81a57a8, 0, 0)
         bf9d59ec void os::Solaris::Event::park() (81a5780) + 4c
         bf9e3696 void ObjectMonitor::wait(long long,int,Thread*) (818b2e4, 0, 0, 1, 81a4c38) + 346
         bf9e3da0 void ObjectSynchronizer::wait(Handle,long long,Thread*) (81a5210, 0, 0, 81a4c38) + 70
         bf924255 void instanceKlass::initialize_impl(instanceKlassHandle,Thread*) (81a5210, 81a4c38) + a5
         bf917838 void instanceKlass::initialize(Thread*) (94f727d8, 81a4c38) + 78
         bf9399e0 void LinkResolver::resolve_static_call(CallInfo&,KlassHandle&,symbolHandle,symbolHandle,KlassHandle,int,int,Thread*) (94c02a54, 94c02968, 81a51f8, 81a51fc, 81a5200, 1) + e0
         bf955b17 void LinkResolver::resolve_invokestatic(CallInfo&,constantPoolHandle,int,Thread*) (94c02a54, 81a51dc, 300, 81a4c38) + 67
         bf91a387 void LinkResolver::resolve_invoke(CallInfo&,Handle,constantPoolHandle,int,Bytecodes::Code,Thread*) (94c02a54, 0, 81a51dc, 300, b8, 81a4c38) + 76
         bf91c337 void InterpreterRuntime::resolve_invoke(JavaThread*,Bytecodes::Code) (81a4c38, b8, b920fe68, 1, b5627710, 3) + 4b7
         b920fe8e * java/util/logging/LogManager$Cleaner.run()V+12 (line 204)
         bf940704 * StubRoutines (1)
         bf940704 void os::os_exception_wrapper(void(*)(JavaValue*,methodHandle*,JavaCallArguments*,Thread*),JavaValue*,methodHandle*,JavaCallArguments*,Thread*) (94c02d48, 94c02c40, 94c02ca4, 81a4c38, 94c02c34, bf940738) + 14
         bf940704 void os::os_exception_wrapper(void(*)(JavaValue*,methodHandle*,JavaCallArguments*,Thread*),JavaValue*,methodHandle*,JavaCallArguments*,Thread*) (bf9402b0, 94c02d48, 94c02c40, 94c02ca4, 81a4c38) + 14
         bf940738 void JavaCalls::call(JavaValue*,methodHandle,JavaCallArguments*,Thread*) (94c02d48, 81a51d8, 94c02ca4, 81a4c38) + 28
         bf9e624e void JavaCalls::call_virtual(JavaValue*,KlassHandle,symbolHandle,symbolHandle,JavaCallArguments*,Thread*) (94c02d48, 81a51cc, bfe5a6c4, bfe5a798, 94c02ca4, 81a4c38) + be
         bf9f03ed void JavaCalls::call_virtual(JavaValue*,Handle,KlassHandle,symbolHandle,symbolHandle,Thread*) (94c02d48, 81a51c8, 81a51cc, bfe5a6c4, bfe5a798, 81a4c38) + 6d
         bfa076b0 void thread_entry(JavaThread*,Thread*) (81a4c38, 81a4c38) + d0
         bfa03de1 void JavaThread::thread_main_inner() (81a4c38) + 51
         bfa03d85 void JavaThread::run() (81a4c38) + 105
         bfcbe0f2 void*_start(void*) (81a4c38) + d2
         bff3839f _thr_setup (bc2c2c00) + 51
         bff385f0 _lwp_start (bc2c2c00, 0, 0, 0, 0, 0)

        There is a clear deadlock between T-1 and T-14:
          T-1: Performs LogManager.<clinit> (class initialization).
                It waits to lock LogManager.manager object which is held by T-14.

          T-14: Performs shutdown hook - LogManager$Cleaner.
                It locked the LogManager.manager object and wants to invoke a static
                method of the LogManager class at the line 204.
                It has been blocked because the LogManager.<clinit> can't be completed by T-1.

        The T-14 part needs some additional clarification as there are
        some specific details of the inner classes implementation here.
        The Cleaner class code is:
            private class Cleaner extends Thread {
        public void run() {
        synchronized (LogManager.this) {
        deathImminent = true; // <=== Line 204 !!!
        initializedGlobalHandlers = true;
        }
        reset();
          }
            }

        The bytecodes of the method "run()" are:
        public Method run:"()V"
        stack 2 locals 3
        {
        aload_0;
        getfield Field this$0:"Ljava/util/logging/LogManager;";
        dup;
        astore_1;
        monitorenter;
        try t0;
        aload_0;
        getfield Field this$0:"Ljava/util/logging/LogManager;";
        iconst_1;
        invokestatic Method LogManager.access$302:"(Ljava/util/logging/LogManager;Z)Z";
        pop;
        aload_0;
        getfield Field this$0:"Ljava/util/logging/LogManager;";
        iconst_1;
        invokestatic Method LogManager.access$402:"(Ljava/util/logging/LogManager;Z)Z";
        pop;
        aload_1;
        monitorexit;
        endtry t0;

        As we can see, the static method LogManager.access$302 is invoked
        in order to update the outer object field "deathImminent".
        It happens after the method entered synchronized section with the "monitorenter" instruction.

              dholmes David Holmes
              sspitsyn Serguei Spitsyn
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Created:
                Updated:
                Resolved:
                Imported:
                Indexed: