JDK-6467152 : deadlock occurs in LogManager initialization and JVM termination
  • Type: Bug
  • Component: core-libs
  • Sub-Component: java.util.logging
  • Affected Version: 5.0u8
  • Priority: P2
  • Status: Closed
  • Resolution: Fixed
  • OS: windows_xp
  • CPU: x86
  • Submitted: 2006-09-05
  • Updated: 2011-09-22
  • Resolved: 2011-03-08
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
Other JDK 6 JDK 7
1.4.2_15Fixed 6u2Fixed 7 b03Fixed
Related Reports
Relates :  
JDK-6716076 - test UTIL_REGRESSION/test/java/util/logging/LoggingDeadlock2.java failed with exit code 1
Relates :  
JDK-6471736 - Ctrl-Break dump: threads waiting on monitors info is incorrect
Description
The attached program ains to generate the situation which LogManager initialization and JVM termination
runs at the same time.

This program generates deadlock easiliy.

REPRODUCE:
 Compile the attached "test.java" and invoke "java test"
 You will see program does not return.

LOG :
 The following is thread dump.

=====================
K:\shares2\dead-lock-jvminit-logmngrinit>java test
Full thread dump Java HotSpot(TM) Client VM (1.5.0_08-b03 mixed mode):

"Thread-1" prio=6 tid=0x00ab6df0 nid=0xefc in Object.wait() [0x0ad1f000..0x0ad1f
b68]
        at java.util.logging.LogManager$Cleaner.run(LogManager.java:204)
        - waiting to lock <0x02b10238> (a java.util.logging.LogManager)

"Thread-0" prio=6 tid=0x00ab7070 nid=0x50c in Object.wait() [0x0acdf000..0x0acdf
be8]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x02b10370> (a java.util.logging.LogManager$Cleaner)
        at java.lang.Thread.join(Thread.java:1095)
        - locked <0x02b10370> (a java.util.logging.LogManager$Cleaner)
        at java.lang.Thread.join(Thread.java:1148)
        at java.lang.Shutdown.runHooks(Shutdown.java:132)
        at java.lang.Shutdown.sequence(Shutdown.java:173)
        at java.lang.Shutdown.exit(Shutdown.java:218)
        - locked <0x06c8f310> (a java.lang.Class)
        at java.lang.Runtime.exit(Runtime.java:90)
        at java.lang.System.exit(System.java:869)
        at test.run(test.java:29)
        at java.lang.Thread.run(Thread.java:595)

"Low Memory Detector" daemon prio=6 tid=0x00aa42f8 nid=0xdf4 runnable [0x0000000
0..0x00000000]

"CompilerThread0" daemon prio=10 tid=0x00ac4c00 nid=0x1e8 waiting on condition [
0x00000000..0x0ac1f6c8]

"Signal Dispatcher" daemon prio=10 tid=0x00ac4008 nid=0x5c4 waiting on condition
 [0x00000000..0x00000000]

"Finalizer" daemon prio=8 tid=0x00a98b30 nid=0x99c in Object.wait() [0x0ab9f000.
.0x0ab9fa68]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x02ae06e0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
        - locked <0x02ae06e0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x00a976c8 nid=0xbc in Object.wait() [0x0
ab5f000..0x0ab5fae8]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x02ae05f0> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:474)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
        - locked <0x02ae05f0> (a java.lang.ref.Reference$Lock)

"main" prio=6 tid=0x000359b8 nid=0xfc8 waiting for monitor entry [0x0007f000..0x
0007fc3c]
        at java.util.logging.LogManager.addLogger(LogManager.java:322)
        - waiting to lock <0x02b10238> (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)

"VM Thread" prio=10 tid=0x00a94c00 nid=0xf5c runnable

"VM Periodic Task Thread" prio=10 tid=0x00aa54c8 nid=0xd60 waiting on condition
====================
Comments
EVALUATION BTW, this is a Ctrl/Break dump of the deadlock on Solaris x86 below. We are able to see that the dump provides incorrect info about the Thread-1. It says that T-1 waiting to lock <0xb5627710> (a java.util.logging.LogManager) which is not correct. In fact, T-1 has already locked this monitor and blocked on waiting when LogManager initialization is completed. 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) "Thread-0" prio=10 tid=0x081a3db0 nid=0xd in Object.wait() [0x94c44000..0x94c44c28] at java.lang.Object.wait(Native Method) - waiting on <0xb5627848> (a java.util.logging.LogManager$Cleaner) at java.lang.Thread.join(Thread.java:1095) - locked <0xb5627848> (a java.util.logging.LogManager$Cleaner) at java.lang.Thread.join(Thread.java:1148) at java.lang.Shutdown.runHooks(Shutdown.java:132) at java.lang.Shutdown.sequence(Shutdown.java:173) at java.lang.Shutdown.exit(Shutdown.java:218) - locked <0x94f7a928> (a java.lang.Class) at java.lang.Runtime.exit(Runtime.java:90) at java.lang.System.exit(System.java:869) at test.run(test.java:29) at java.lang.Thread.run(Thread.java:595) "Low Memory Detector" daemon prio=10 tid=0x08191aa8 nid=0xb runnable [0x00000000..0x00000000] "CompilerThread1" daemon prio=10 tid=0x08190238 nid=0xa waiting on condition [0x00000000..0x00000000] "CompilerThread0" daemon prio=10 tid=0x0818f4b0 nid=0x9 waiting on condition [0x00000000..0x00000000] "AdapterThread" daemon prio=10 tid=0x0818e688 nid=0x8 waiting on condition [0x00000000..0x00000000] "Signal Dispatcher" daemon prio=10 tid=0x0818d968 nid=0x7 waiting on condition [0x00000000..0x00000000] "Finalizer" daemon prio=10 tid=0x081810b8 nid=0x6 in Object.wait() [0xb9117000..0xb9117ba8] at java.lang.Object.wait(Native Method) - waiting on <0xb56006d8> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116) - locked <0xb56006d8> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=10 tid=0x08180d08 nid=0x5 in Object.wait() [0xbc27b000..0xbc27bc28] at java.lang.Object.wait(Native Method) - waiting on <0xb56005e8> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:474) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) - locked <0xb56005e8> (a java.lang.ref.Reference$Lock) "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) "VM Thread" prio=10 tid=0x0817ec30 nid=0x4 runnable "GC task thread#0 (ParallelGC)" prio=10 tid=0x080f6018 nid=0x2 runnable "GC task thread#1 (ParallelGC)" prio=10 tid=0x080f6a58 nid=0x3 runnable "VM Periodic Task Thread" prio=10 tid=0x08192c48 nid=0xc runnable
07-09-2006
SUGGESTED FIX I suggest to add the following lines at the beginning of the Cleaner.run() method: + // This is to ensure the LogManager.<clinit> is completed + // before synchronized block. Otherwise deadlocks are possible. + LogManager mgr = manager;
07-09-2006
EVALUATION I was lucky to reproduce this problem on Solaris 11 (x86 machine: bonsai.sfbay). 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. This bug exists in the Dolphin workspace as well. It is platform independent. I guess the desciption describes the same situation because it shows the same line #204 in the Cleaner.run() method. I think, this information about waiting on the <0x02b10238> lock is not accurate from the Ctrl/Break thread dump on Windows XP: "Thread-1" prio=6 tid=0x00ab6df0 nid=0xefc in Object.wait() [0x0ad1f000..0x0ad1f b68] at java.util.logging.LogManager$Cleaner.run(LogManager.java:204) - waiting to lock <0x02b10238> (a java.util.logging.LogManager) Please, also see the pstack output below (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)
07-09-2006
EVALUATION It is interesting. Let's take a look at stack traces again (I have skipped unrelated stack traces). (0) Thread-0 performs System.exit. It starts shutdoun hook threads and waits until they complete. Here we have just one hook, the Cleaner thread, to wait. "Thread-0" prio=6 tid=0x00ab7070 nid=0x50c in Object.wait() [0x0acdf000..0x0acdfbe8] at java.lang.Object.wait(Native Method) - waiting on <0x02b10370> (a java.util.logging.LogManager$Cleaner) at java.lang.Thread.join(Thread.java:1095) - locked <0x02b10370> (a java.util.logging.LogManager$Cleaner) at java.lang.Thread.join(Thread.java:1148) at java.lang.Shutdown.runHooks(Shutdown.java:132) at java.lang.Shutdown.sequence(Shutdown.java:173) at java.lang.Shutdown.exit(Shutdown.java:218) - locked <0x06c8f310> (a java.lang.Class) at java.lang.Runtime.exit(Runtime.java:90) at java.lang.System.exit(System.java:869) at test.run(test.java:29) at java.lang.Thread.run(Thread.java:595) (1) Thread-1 is the Cleaner thread. "Thread-1" prio=6 tid=0x00ab6df0 nid=0xefc in Object.wait() [0x0ad1f000..0x0ad1fb68] at java.util.logging.LogManager$Cleaner.run(LogManager.java:204) - waiting to lock <0x02b10238> (a java.util.logging.LogManager) As we can see, it waits on the following synchronized block below: private class Cleaner extends Thread { public void run() { synchronized (LogManager.this) { // Note that death is imminent. deathImminent = true; initializedGlobalHandlers = true; } // Do a reset to close all active handlers. reset(); } } (2) Main Thread executes LogManager static initializer <clinit>. Current method is LogManager.addLogger(). It is called from here: Line 180: manager.addLogger(manager.rootLogger); "main" prio=6 tid=0x000359b8 nid=0xfc8 waiting for monitor entry [0x0007f000..0x0007fc3c] at java.util.logging.LogManager.addLogger(LogManager.java:322) - waiting to lock <0x02b10238> (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) The addLogger() method waits to enter the synchronized block: public synchronized boolean addLogger(Logger logger) { Analysis: The stack traces above shows (is it true?) there is no deadlock issue between Thread-1 (Cleaner.run) and Main Thread (LogManager.<clinit>) because both of them are waiting to lock the same monitor (a LogManager object): The question is: Who is holding the LogManager object monitor? Probably, the locking info in the Ctrl-Break dump is not correct. Probably, the Cleaner thread (Thread-1) is not waiting on this monitor but has already locked it.
05-09-2006
EVALUATION This bug was unveiled after the following bug was fixed in SDK 6 b83 and 5.0u8: 4994705 deadlock in LogManager
05-09-2006