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.