United StatesChange Country, Oracle Worldwide Web Sites Communities I am a... I want to...
Bug ID: JDK-6471736 Ctrl-Break dump: threads waiting on monitors info is incorrect
JDK-6471736 : Ctrl-Break dump: threads waiting on monitors info is incorrect

Details
Type:
Bug
Submit Date:
2006-09-18
Status:
Closed
Updated Date:
2012-10-08
Project Name:
JDK
Resolved Date:
2006-11-14
Component:
hotspot
OS:
generic
Sub-Component:
runtime
CPU:
generic
Priority:
P4
Resolution:
Fixed
Affected Versions:
6
Fixed Versions:
hs10 (b03)

Related Reports
Backport:
Backport:
Relates:

Sub Tasks

Description
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.

                                    

Comments
EVALUATION

The bug arises because the code that prints the information makes a simple, but incorrect assumption: if there is a monitor in the current frame, and this is the last Java frame, and the thread state is _thread_blocked, then we must be blocked trying to lock the monitor. This ignores implicit excursions into the VM through class resolution etc.
                                     
2006-09-19
EVALUATION

It also ignores the additional problem that as thread dumps are printed at safepoints, the thread state will nearly *always* be _thread_blocked.
                                     
2006-09-26
SUGGESTED FIX

Check if the monitor is inflated and if so whether it matches the thread's pending_monitor() entry. If it does then the thread is blocked acquiring that monitor; else the monitor must be locked.
                                     
2006-09-27



Hardware and Software, Engineered to Work Together