United StatesChange Country, Oracle Worldwide Web Sites Communities I am a... I want to...
JDK-4994705 : deadlock in LogManager

Details
Type:
Bug
Submit Date:
2004-02-13
Status:
Closed
Updated Date:
2006-10-13
Project Name:
JDK
Resolved Date:
2006-04-29
Component:
core-libs
OS:
generic
Sub-Component:
java.util.logging
CPU:
generic
Priority:
P3
Resolution:
Fixed
Affected Versions:
5.0
Fixed Versions:

Related Reports
Backport:
Backport:
Relates:

Sub Tasks

Description
Deadlock happens with nsk/stress/jck12a/jck12a014. The following two threads
deadlock each other (the lock info in the thread dump is not very accurate).
"Thread-591" prio=10 tid=0x0053c898 nid=0x259 in Object.wait() [0xd157f000..0xd1
57fb10]
        at java.util.logging.LogManager$Cleaner.run(LogManager.java:179)
        - waiting to lock <0xf177beb0> (a java.util.logging.LogManager)

"Thread-453" prio=10 tid=0x004c2770 nid=0x1d0 waiting for monitor entry [0xd3f7c
000..0xd3f7fb90]
        at java.util.logging.LogManager.addLogger(LogManager.java:292)
        - waiting to lock <0xf177beb0> (a java.util.logging.LogManager)
        at java.util.logging.LogManager+1.run(LogManager.java:160)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.util.logging.LogManager.<clinit>(LogManager.java:141)
        at java.util.logging.Logger.getLogger(Logger.java:228)
        - locked <0xf4862c60> (a java.lang.Class)
        at java.util.logging.Logger.<clinit>(Logger.java:181)
        at java.awt.Component.<clinit>(Component.java:159)
        at javasoft.sqe.tests.api.java.util.EventObject.serial.ConstructorTests.
ConstructorTest0001(ConstructorTests.java:76)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.
java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces
sorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:494)
        at javasoft.sqe.javatest.lib.MultiTest.run(MultiTest.java:177)
        at javasoft.sqe.stresstest.StressTest$TestThread.run(StressTest.java:851
)

The full thread dump is attached.

Basically "Thread-591" locks LogManager.manager and waits for the class initializer
of LogManager to be finished. But "Thread-453" is inside the class initializer
of LogManager and it wants to lock LogManager.manager.

Usually instantiation can only happen after class is fully initialized. But in this
case, LogManager.manager is instantiated inside the class initializer of LogManager.
And "Thread-591" gets a chance to lock the object before class LogManager
is fully initialized.

Grabbing locks inside class initializer can be dangeous since there is a hidden
class object that other threads may be waiting on. It's required by spec, see
http://java.sun.com/docs/books/vmspec/2nd-edition/html/Concepts.doc.html#19075
Section 2.17.5, step 2.

It's also a question whether there are places in JDK other than LogManager that are
subject to such vulnerability.

The following simplified testcase shows the possibility of such deadlock.
// B.java
//
// Deadlock happens when Thread 0 is initializing class A and wants C.c and
// Thread 1 holds C.c and waits for Class A to be fully initialized.

class A {
	static {
		try { Thread.sleep(5000); } catch (Exception e) {}
		synchronized (C.c) {
		}
	}
}

public class B {
	public static void main(String[] args) {
		// Thread 0
		new Thread() {
			public void run() {
				// Cause Class A to be initialized.
				new A();
			}
		}.start();
		try { Thread.sleep(1000); } catch (Exception e) {}
		// Thread 1
		new Thread() {
			public void run() {
				synchronized (C.c) {
					// Class A is being initialized so wait
					// for the initialization to finish.
					new A();
				}
			}
		}.start();
	}
}

class C {
	static C c = new C();
}

###@###.### 2004-02-13
I've added a testcase provided by customer SAP which deadlogs if you:

a) run it on a multi-cpu box.
b) run it 1-5 times, often it happens on the 1st attempt.

HTH

                                    

Comments
SUGGESTED FIX

I have deleted the lmdd.Mar6.tar from attachment as it is incorrect fix.
Please, see another webrev lmd.Apr7.tar in attachment.
                                     
2006-04-10
SUGGESTED FIX

Please, see the webrev lmdd.Mar6.tar in attachments.
                                     
2006-03-06
EVALUATION

Big thanks to Mattnias who provided the testcase from SAP.
Now I'm able too reproduce the problem.
This is the deadlock reproducible with the tescase:

Thread #13:
java/util/logging/LogManager.<clinit>() ->
    java/security/AccessController.doPrivileged() -> ... -> JVM_DoPrivileged ->
    java/util/logging/LogManager$1.run() ->
    InterpreterRuntime::_new() -> BLOCKED
    Related lines of the source code:
       LogManager.java(L169) : manager.rootLogger = manager.new RootLogger();
       LogManager.java(L961) : private class RootLogger extends Logger {

Thread #14
java/util/logging/Logger.<clinit>() ->
    java/util/logging/getLogger() ->
    java/util/logging/LogManager.getLogManager() -> BLOCKED
    Related line of the source code:
       Logger.java(L228) : LogManager manager = LogManager.getLogManager();

Concurrent creating the rootLogger object at the LogManager class
initialization in the Thread #13 and a Logger object in the Thread #14
causes a deadlock. The LogManager.<clinit> creates an object of the
RootLogger class which is a subclass of the Logger class.
The Logger.<clinit> invokes the LogManager static method getLogManager(),
and so, both class initializations are waiting for each other to complete.

Please, see a pstack output in attachments: Logmanager_deadlock.pstk.
                                     
2006-03-06
EVALUATION

The description says:
"The following two threads deadlock each other (the lock info in the thread
 dump is not very accurate).
 ...
 Basically "Thread-591" locks LogManager.manager and waits for the class
 initializer of LogManager to be finished. But "Thread-453" is inside the
 class initializer of LogManager and it wants to lock LogManager.manager."

It is not correct.
I think the thread dump is correct (but maybe not complete), and both
threads "Thread-591" and "Thread-453" are waiting to lock the same
LogManager.manager monitor.

But it is completely unclear from the thread dump (from attachment) what
thread holds the LogManager.manager lock.
The sample example in the description is very interesting but it looks
like it is unrelated to the real reason of the deadlock.

The most important part of analysis is reproducing this problem with
the real test.
I was not able to reproduce it with the nsk/stress/jck12a/jck12a014.
There is no info in the description on how to reproduce the bug
and its reproducibility rate.
It is possible that the test was modified to workaround this bug because
this scenarious stress test can be needed to catch other problems.
It would be nice to run the old version of the test from the old testbase.

This is a preliminar input because more analysis is still needs to be done.
                                     
2006-02-27
CONVERTED DATA

BugTraq+ Release Management Values

COMMIT TO FIX:
dragon


                                     
2004-06-14
EVALUATION

This is related to the change in 1.4.2 to move logging initialization out of the system class. (see 4770189 and others)

The difference in 1.5 is that logging is automatically enabled by awt. It may be possible to reduce the rate of occurance by a small amount of tweaking.

###@###.### 2004-02-13

The cleaner thread is the cause of this deadlock, I can narrow down the lock scope however as this is due to a stress test it is probably too risky to integrated at this point in the schedule. I'll carry on testing it for the next update

###@###.### 2004-03-04
                                     
2004-03-04



Hardware and Software, Engineered to Work Together