JDK-6977677 : Deadlock on logging subsystem initialization
  • Type: Bug
  • Component: core-libs
  • Sub-Component: java.util.logging
  • Affected Version: 6u21,7
  • Priority: P3
  • Status: Closed
  • Resolution: Fixed
  • OS: generic
  • CPU: generic
  • Submitted: 2010-08-17
  • Updated: 2012-02-02
  • Resolved: 2011-07-18
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.
JDK 7
7 b143Fixed
Related Reports
Relates :  
JDK-6882376 - Add internal support for JRE implementation to eliminate the dependency on logging
Relates :  
JDK-7045441 - locking analysis and other possible improvements for Logging API
Relates :  
JDK-7045594 - fix for 6977677 introduced a ResourceBundle race
Description
A stress test running several logging tests hangs. One of threads has this stack trace:
   JavaThread state: _thread_blocked
        at java.util.logging.Logger.getLogger(Logger.java:300)
        - waiting to lock <0xfffffd7f75925610> (a java.lang.Class for java.util.logging.Logger)
        at java.util.logging.LoggingProxyImpl.getLogger(LoggingProxyImpl.java:40)
        at sun.util.logging.LoggingSupport.getLogger(LoggingSupport.java:99)
        at sun.util.logging.PlatformLogger$JavaLogger.<init>(PlatformLogger.java:516)
        at sun.util.logging.PlatformLogger.newJavaLogger(PlatformLogger.java:155)
        at sun.util.logging.PlatformLogger.redirectPlatformLoggers(PlatformLogger.java:146)
        - locked <0xfffffd7f75f10e18> (a java.lang.Class for sun.util.logging.PlatformLogger)
        at java.util.logging.LogManager$2.run(LogManager.java:289)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.util.logging.LogManager.readPrimordialConfiguration(LogManager.java:284)
        - locked <0xfffffd7f7a587110> (a java.util.logging.LogManager)
        at java.util.logging.LogManager.getLogManager(LogManager.java:267)
        at java.util.logging.Logger.<init>(Logger.java:247)
        at java.util.logging.LogManager$RootLogger.<init>(LogManager.java:1101)
        at java.util.logging.LogManager$RootLogger.<init>(LogManager.java:1098)
        at java.util.logging.LogManager$1.run(LogManager.java:199)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.util.logging.LogManager.<clinit>(LogManager.java:176)
        at java.util.logging.Handler.<init>(Handler.java:50)
        at javasoft.sqe.tests.api.java.util.logging.Handler.MyHandler.<init>(MyHandler.java:34)
        at javasoft.sqe.tests.api.java.util.logging.Handler.LevelTests.Handler0005(LevelTests.java:48)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:613)
        at javasoft.sqe.javatest.lib.MultiTest.invokeTestCase(MultiTest.java:406)
        at javasoft.sqe.javatest.lib.MultiTest.run(MultiTest.java:195)
        at nsk.stress.share.StressTest$TestThread.runTest(StressTest.java:739)
        at nsk.stress.share.StressTest$TestThread.run(StressTest.java:755)
Comments
EVALUATION Changeset: 2ecb989b6fcc Author: dcubed Date: 2011-05-16 12:56 -0700 URL: http://hg.openjdk.java.net/jdk7/tl/jdk/rev/2ecb989b6fcc 6977677: 3/2 Deadlock on logging subsystem initialization Summary: Over synchronized Logger.getLogger() deadlocks with LogManager.<clinit>via PlatformLogger Reviewed-by: dsamersoff, never, acorn, mchung
16-05-2011
SUGGESTED FIX See attached logging-batch-20110515-webrev-cr0.tgz for the proposed fix for this bug along with the fixes for 7016208 and 7041595.
16-05-2011
SUGGESTED FIX See attached logging-batch-20110515-webrev-cr1.tgz for the revised proposed fix for this bug along with the fixes for 7016208 and 7041595 after code review round 0.
16-05-2011
EVALUATION I've started an analysis of all synchronization uses in the LogManager and Logger classes. My plan: - examine each use of synchronized in the Logging API - gather the history behind each use - if the reason is not obvious, i.e., the code that needs to be protected isn't within a short distance (<25 lines?), then I'll add a comment to make the reason for synchronization clear - if I remove synchronization, then I'll add a comment to make it clear where the synchronization is done instead - sometimes I'll add a comment if it looks like a method should be synchronized but is not This plan is subject to change. My preliminary analysis for Logger.getLogger(name) and Logger.getLogger(name, resourceBundle) indicates that they are over synchronized due to being "static synchronized" methods. I have an experimental, but incomplete fix in place and with it, the LoggingDeadlock4 test ran for 6000+ runs in 82 minutes without a single deadlock. Definitely promising, but no other Logging API tests have been run.
08-05-2011
EVALUATION Based on the previous two notes, I've been able to write a pretty simple test that reliably reproduces this deadlock. On my Solaris X86 machine and on my WinXP VMware client, this test deadlocked in 10/10 runs. :::::::::::::: LoggingDeadlock4.java :::::::::::::: import java.awt.Container; import java.util.concurrent.CountDownLatch; import java.util.logging.LogManager; import java.util.logging.Logger; public class LoggingDeadlock4 { private static CountDownLatch barrier = new CountDownLatch(1); private static CountDownLatch lmIsRunning = new CountDownLatch(1); private static CountDownLatch logIsRunning = new CountDownLatch(1); public static void main(String[] args) { System.out.println("main: LoggingDeadlock4 is starting."); // Loading the java.awt.Container class will create a // sun.util.logging.PlatformLogger$JavaLogger object // that has to be redirected when the LogManager class // is initialized. This can cause a deadlock between // LogManager.<clinit> and Logger.getLogger(). try { Class.forName("java.awt.Container"); } catch (ClassNotFoundException cnfe) { throw new RuntimeException("Test failed: could not load" + " java.awt.Container." + cnfe); } Thread lmThread = new Thread("LogManagerThread") { public void run() { // let main know LogManagerThread is running lmIsRunning.countDown(); System.out.println(Thread.currentThread().getName() + ": is running."); try { barrier.await(); // wait for race to start } catch (InterruptedException e) { } LogManager manager = LogManager.getLogManager(); } }; lmThread.start(); Thread logThread = new Thread("LoggerThread") { public void run() { // let main know LoggerThread is running logIsRunning.countDown(); System.out.println(Thread.currentThread().getName() + ": is running."); try { barrier.await(); // wait for race to start } catch (InterruptedException e) { } Logger foo = Logger.getLogger("foo logger"); } }; logThread.start(); try { // wait for LogManagerThread and LoggerThread to get going lmIsRunning.await(); logIsRunning.await(); } catch (InterruptedException e) { } barrier.countDown(); // start the race try { lmThread.join(); logThread.join(); } catch (InterruptedException ie) { } System.out.println("main: LoggingDeadlock4 is done."); } } :::::::::::::: LoggingDeadlock4.log :::::::::::::: java version "1.7.0-ea" Java(TM) SE Runtime Environment (build 1.7.0-ea-b141) Java HotSpot(TM) Client VM (build 21.0-b11, mixed mode) main: LoggingDeadlock4 is starting. LogManagerThread: is running. LoggerThread: is running. <jstack at this point, then CTRL-C> :::::::::::::: LoggingDeadlock4.jstack :::::::::::::: 2011-05-05 19:13:07 Full thread dump Java HotSpot(TM) Client VM (21.0-b11 mixed mode): "LoggerThread" prio=6 tid=0x16d7bc00 nid=0xb68 in Object.wait() [0x1711f000] java.lang.Thread.State: RUNNABLE at java.util.logging.Logger.getLogger(Logger.java:314) - locked <0x02a48db0> (a java.lang.Class for java.util.logging.Logger) at LoggingDeadlock4$2.run(LoggingDeadlock4.java:57) "LogManagerThread" prio=6 tid=0x16d7a800 nid=0x1a98 waiting for monitor entry [0 x170ce000] java.lang.Thread.State: BLOCKED (on object monitor) at java.util.logging.Logger.getLogger(Logger.java:314) - waiting to lock <0x02a48db0> (a java.lang.Class for java.util.logging. Logger) at java.util.logging.LoggingProxyImpl.getLogger(LoggingProxyImpl.java:40 ) at sun.util.logging.LoggingSupport.getLogger(LoggingSupport.java:100) at sun.util.logging.PlatformLogger$JavaLogger.<init>(PlatformLogger.java :497) at sun.util.logging.PlatformLogger.newJavaLogger(PlatformLogger.java:155 ) at sun.util.logging.PlatformLogger.redirectPlatformLoggers(PlatformLogge r.java:146) - locked <0x02a10348> (a java.lang.Class for sun.util.logging.PlatformLo gger) at java.util.logging.LogManager$2.run(LogManager.java:288) at java.security.AccessController.doPrivileged(Native Method) at java.util.logging.LogManager.readPrimordialConfiguration(LogManager.j ava:283) - locked <0x02a33500> (a java.util.logging.LogManager) at java.util.logging.LogManager.getLogManager(LogManager.java:266) at java.util.logging.Logger.<init>(Logger.java:252) at java.util.logging.LogManager$RootLogger.<init>(LogManager.java:1113) at java.util.logging.LogManager$RootLogger.<init>(LogManager.java:1110) at java.util.logging.LogManager$1.run(LogManager.java:198) at java.security.AccessController.doPrivileged(Native Method) at java.util.logging.LogManager.<clinit>(LogManager.java:175) at LoggingDeadlock4$1.run(LoggingDeadlock4.java:39) "Service Thread" daemon prio=6 tid=0x16d1b800 nid=0x1b20 runnable [0x00000000] java.lang.Thread.State: RUNNABLE "C1 CompilerThread0" daemon prio=10 tid=0x16d0d800 nid=0x17f4 waiting on conditi on [0x00000000] java.lang.Thread.State: RUNNABLE "Attach Listener" daemon prio=10 tid=0x16d0bc00 nid=0x1be4 waiting on condition [0x00000000] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" daemon prio=10 tid=0x16d0a800 nid=0x1c04 runnable [0x0000000 0] java.lang.Thread.State: RUNNABLE "Finalizer" daemon prio=8 tid=0x16be1000 nid=0x1b74 in Object.wait() [0x16cef000 ] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x029c4f70> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135) - locked <0x029c4f70> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:177) "Reference Handler" daemon prio=10 tid=0x16bdc000 nid=0x1c78 in Object.wait() [0 x16c9f000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x029c4b78> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:503) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133) - locked <0x029c4b78> (a java.lang.ref.Reference$Lock) "main" prio=6 tid=0x003c7c00 nid=0x1b6c in Object.wait() [0x0090f000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x02a1c1c0> (a LoggingDeadlock4$1) at java.lang.Thread.join(Thread.java:1258) - locked <0x02a1c1c0> (a LoggingDeadlock4$1) at java.lang.Thread.join(Thread.java:1332) at LoggingDeadlock4.main(LoggingDeadlock4.java:72) "VM Thread" prio=10 tid=0x16bd6400 nid=0x1b08 runnable "VM Periodic Task Thread" prio=10 tid=0x16d2f400 nid=0x1abc waiting on condition JNI global references: 129 The deadlocked threads in the jstack output above match the same code paths in Nicolay's jstack output.
06-05-2011
EVALUATION Here is the analysis for Thread-169: I've tagged the interesting lines from the stack trace snippet from the point of deadlock down to the call into java.util.logging code. I've reversed the order of the frames so that I can analyze the call sequence from entry into java.util.logging code to the deadlock. ST-21 at javasoft.sqe.tests.api.java.util.logging.MyLogger.<init>(MyLogger.java:21) The above frame is initializing a MyLogger object that is a subclass of java.util.logging.Logger. ST-20 at java.util.logging.Logger.<init>(Logger.java:252) The above frame is initializing a java.util.logging.Logger object: 251 protected Logger(String name, String resourceBundleName) { 252 this.manager = LogManager.getLogManager(); so we're on line 252 initiating the load of the LogManager class. ST-19 at java.util.logging.LogManager.<clinit>(LogManager.java:175) ST-18 at java.security.AccessController.doPrivileged(Native Method) The above frames are in the static initializer for the LogManager class and get us into privileged mode. One of the pieces of work done by this code block: 178 try { 179 cname = System.getProperty("java.util.logging.manager"); 180 if (cname != null) { 181 try { 182 Class clz = ClassLoader.getSystemClassLoader().loadClass(cname); 183 manager = (LogManager) clz.newInstance(); 184 } catch (ClassNotFoundException ex) { 185 Class clz = Thread.currentThread().getContextClassLoader().loadClass(cname); 186 manager = (LogManager) clz.newInstance(); 187 } 188 } 189 } catch (Exception ex) { 190 System.err.println("Could not load Logmanager \"" + cname + "\""); 191 ex.printStackTrace(); 192 } 193 if (manager == null) { 194 manager = new LogManager(); 195 } So we set the 'manager' field to a new LogManager object. Interesting since we're still in LogManager.<clinit>. We're still holding the LogManager class lock so nobody else can see this field yet. ST-17 at java.util.logging.LogManager$1.run(LogManager.java:198) The above frame is in the run() method for the privileged code: 198 manager.rootLogger = manager.new RootLogger(); ST-16 at java.util.logging.LogManager$RootLogger.<init>(LogManager.java:1110) ST-15 at java.util.logging.LogManager$RootLogger.<init>(LogManager.java:1113) The above frames are initializing a RootLogger object. Not sure why there are two frames here: 1113 super("", null); ST-14 at java.util.logging.Logger.<init>(Logger.java:252) The above frame is initializing a java.util.logging.Logger object: 251 protected Logger(String name, String resourceBundleName) { 252 this.manager = LogManager.getLogManager(); We're on line 252 again only this time, we're the thread that's loading the LogManager class so we go on. ST-13 at java.util.logging.LogManager.getLogManager(LogManager.java:266) The above frame is where we read the primordial config: 266 manager.readPrimordialConfiguration(); ST-12 - locked <0xfffffd7f7a0fa868> (a java.util.logging.LogManager) The above shows we've locked the LogManager object: 271 private void readPrimordialConfiguration() { 272 if (!readPrimordialConfiguration) { 273 synchronized (this) { 274 if (!readPrimordialConfiguration) { The above is a use of double-check locking. It could be fine but we have to check carefully. The following makes me nervous: 281 readPrimordialConfiguration = true; readPrimordialConfiguration is volatile so now another thread that hits the check line line 272 above will breeze past the lock check and might be able to access the state that we're initializing in the next frame below. ST-11 at java.util.logging.LogManager.readPrimordialConfiguration(LogManager.java:283) ST-10 at java.security.AccessController.doPrivileged(Native Method) The above frames get us into privileged mode. One of the pieces of work done by this code block: 285 readConfiguration(); The above call requires privilege, but can a racing thread see partially set info due to the double-check locking? ST-09 at java.util.logging.LogManager$2.run(LogManager.java:288) The above frame is in the run() method for the privileged code: 288 sun.util.logging.PlatformLogger.redirectPlatformLoggers(); and off we go into the PlatformLogger stuff ST-08 - locked <0xfffffd7f7a0f8348> (a java.lang.Class for sun.util.logging.PlatformLogger) The above shows we've locked the sun.util.logging.PlatformLogger class: 138 public static synchronized void redirectPlatformLoggers() { After we've locked the PlatformLogger class: 139 if (loggingEnabled || !LoggingSupport.isAvailable()) return; 140 141 loggingEnabled = true; 142 for (Map.Entry<String, WeakReference<PlatformLogger>> entry : loggers.entrySet()) { 143 WeakReference<PlatformLogger> ref = entry.getValue(); 144 PlatformLogger plog = ref.get(); 145 if (plog != null) { For our thread to get past the check on line 139, loggingEnabled needed to be false (i.e., we haven't done this part before) and LoggingSupport.isAvailable() needs to be true. If we have a PlatformLogger object on the loggers list, then we get to the next frame. PlatformLogger objects are created by sun.util.logging.PlatformLogger.getLogger() method. ST-07 at sun.util.logging.PlatformLogger.redirectPlatformLoggers(PlatformLogger.java:146) The above frame is where we get a new, real java.util.logging.Logger object to redirect the PlatformLogger object to: 146 plog.newJavaLogger(); ST-06 at sun.util.logging.PlatformLogger.newJavaLogger(PlatformLogger.java:155) The above frame makes a new JavaLogger object. ST-05 at sun.util.logging.PlatformLogger$JavaLogger.<init>(PlatformLogger.java:497) The above frame is initializing a JavaLogger object: 497 this.javaLogger = LoggingSupport.getLogger(name); ST-04 at sun.util.logging.LoggingSupport.getLogger(LoggingSupport.java:100) The above frame proxies the LoggingSupport.getLogger(name) call over to the LoggingProxy.getLogger() method: 98 public static Object getLogger(String name) { 99 ensureAvailable(); 100 return proxy.getLogger(name); ensureAvailable() just makes sure we have a LoggingProxy. ST-03 at java.util.logging.LoggingProxyImpl.getLogger(LoggingProxyImpl.java:40) The above frame gets us back into the real Logger code: 39 public Object getLogger(String name) { 40 return Logger.getLogger(name); ST-02 - waiting to lock <0xfffffd7f79cb6c88> (a java.lang.Class for java.util.logging.Logger) The above frame shows we're trying to lock the java.util.logging.Logger class: 313 public static synchronized Logger getLogger(String name) { java.util.logging.Logger.getLogger() is synchronized for some reason so we grab the class lock ST-01 at java.util.logging.Logger.getLogger(Logger.java:314) The above frame indicates that we're past line 313, but that's not quite true. The following line is what we will execute once we get the class lock: 314 LogManager manager = LogManager.getLogManager(); Here is the complete stack trace snippet: "Thread-169" prio=3 tid=0x00000000024c0800 nid=0xba waiting for monitor entry [0xfffffd7f67d25000] java.lang.Thread.State: BLOCKED (on object monitor) JavaThread state: _thread_blocked Thread: 0x00000000024c0800 [0xba] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.util.logging.Logger.getLogger(Logger.java:314) - waiting to lock <0xfffffd7f79cb6c88> (a java.lang.Class for java.util.logging.Logger) at java.util.logging.LoggingProxyImpl.getLogger(LoggingProxyImpl.java:40) at sun.util.logging.LoggingSupport.getLogger(LoggingSupport.java:100) at sun.util.logging.PlatformLogger$JavaLogger.<init>(PlatformLogger.java:497) at sun.util.logging.PlatformLogger.newJavaLogger(PlatformLogger.java:155) at sun.util.logging.PlatformLogger.redirectPlatformLoggers(PlatformLogger.java:146) - locked <0xfffffd7f7a0f8348> (a java.lang.Class for sun.util.logging.PlatformLogger) at java.util.logging.LogManager$2.run(LogManager.java:288) at java.security.AccessController.doPrivileged(Native Method) at java.util.logging.LogManager.readPrimordialConfiguration(LogManager.java:283) - locked <0xfffffd7f7a0fa868> (a java.util.logging.LogManager) at java.util.logging.LogManager.getLogManager(LogManager.java:266) at java.util.logging.Logger.<init>(Logger.java:252) at java.util.logging.LogManager$RootLogger.<init>(LogManager.java:1113) at java.util.logging.LogManager$RootLogger.<init>(LogManager.java:1110) at java.util.logging.LogManager$1.run(LogManager.java:198) at java.security.AccessController.doPrivileged(Native Method) at java.util.logging.LogManager.<clinit>(LogManager.java:175) at java.util.logging.Logger.<init>(Logger.java:252) at javasoft.sqe.tests.api.java.util.logging.MyLogger.<init>(MyLogger.java:21) at javasoft.sqe.tests.api.java.util.logging.Porter.checkLog1(Porter.java:399) at javasoft.sqe.tests.api.java.util.logging.Logger.Fine1Tests.Logger0052(Fine1Tests.java:44) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:601) at javasoft.sqe.javatest.lib.MultiTest.invokeTestCase(MultiTest.java:406) at javasoft.sqe.javatest.lib.MultiTest.run(MultiTest.java:195) at nsk.stress.share.StressTest$TestThread.runTest(StressTest.java:752) at nsk.stress.share.StressTest$TestThread.run(StressTest.java:768)
06-05-2011
EVALUATION Here is the analysis for Thread-168: This thread's code path *looks* pretty simple. javasoft.sqe.tests.api.java.util.logging.Logger.FieldsTests.Logger2001 is calling java.util.logging.Logger.getLogger(). Here's where the thread is in Logger.java: 313 public static synchronized Logger getLogger(String name) { => 314 LogManager manager = LogManager.getLogManager(); 315 return manager.demandLogger(name); 316 } The java.util.logging.Logger class lock is grabbed on line 313 and the thread blocks trying to call LogManager.getLogManager() on line 314. Or more accurately, the thread blocks trying to access the LogManager class because the other thread (Thread-169) is still in LogManager.<clinit>. This part of the stack trace could be better: "Thread-168" prio=3 tid=0x00000000024ad800 nid=0xb9 in Object.wait() [0xfffffd7f67e2b000] java.lang.Thread.State: RUNNABLE JavaThread state: _thread_blocked Thread: 0x00000000024ad800 [0xb9] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.util.logging.Logger.getLogger(Logger.java:314) - locked <0xfffffd7f79cb6c88> (a java.lang.Class for java.util.logging.Logger) at javasoft.sqe.tests.api.java.util.logging.Logger.FieldsTests.Logger2001(FieldsTests.java:38) Right after: at java.util.logging.Logger.getLogger(Logger.java:314) there should be something like: - waiting to lock <0xXXXXXXXXXXXXXXXX> (a java.lang.Class for java.util.logging.LogManager) or something like that. Since the output says that the thread went to a safepoint, we at least know that something safepointable like a lock enter happened. In Demo1.java, I tried to repro the code path in Thread-168 and here's what jstack shows: "LoggerThread" prio=6 tid=0x16d4c800 nid=0xb54 in Object.wait() [0x1711f000] java.lang.Thread.State: RUNNABLE at Logger.getLogger(Demo1.java:119) - locked <0x02a33cc8> (a java.lang.Class for Logger) at Demo1$2.run(Demo1.java:26) We aren't at a safepoint so the only clue that we have that this thread is blocked is the "Object.wait()" in the header line. This part of thread dumps definitely needs some help. The prime spots for repro delays: - a small delay in LoggerThread prior to the Logger.getLogger() call to allow the LogManagerThread to get into LogManager.<clinit> - a small delay in LogManagerThread at the start of LogManager.<clinit> to allow the LoggerThread to acquire the java.util.logging.Logger class lock Here is the complete stack trace snippet: "Thread-168" prio=3 tid=0x00000000024ad800 nid=0xb9 in Object.wait() [0xfffffd7f67e2b000] java.lang.Thread.State: RUNNABLE JavaThread state: _thread_blocked Thread: 0x00000000024ad800 [0xb9] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.util.logging.Logger.getLogger(Logger.java:314) - locked <0xfffffd7f79cb6c88> (a java.lang.Class for java.util.logging.Logger) at javasoft.sqe.tests.api.java.util.logging.Logger.FieldsTests.Logger2001(FieldsTests.java:38) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:601) at javasoft.sqe.javatest.lib.MultiTest.invokeTestCase(MultiTest.java:406) at javasoft.sqe.javatest.lib.MultiTest.run(MultiTest.java:195) at nsk.stress.share.StressTest$TestThread.runTest(StressTest.java:752) at nsk.stress.share.StressTest$TestThread.run(StressTest.java:768)
06-05-2011
EVALUATION The jstack.log attachment shows thread stacks for 257 threads. Of those many threads, two are interesting for this bug: :::::::::::::: Thread-168 :::::::::::::: "Thread-168" prio=3 tid=0x00000000024ad800 nid=0xb9 in Object.wait() [0xfffffd7f 67e2b000] java.lang.Thread.State: RUNNABLE JavaThread state: _thread_blocked Thread: 0x00000000024ad800 [0xb9] State: _at_safepoint _has_called_back 0 _at_p oll_safepoint 0 JavaThread state: _thread_blocked at java.util.logging.Logger.getLogger(Logger.java:314) - locked <0xfffffd7f79cb6c88> (a java.lang.Class for java.util.logging.L ogger) at javasoft.sqe.tests.api.java.util.logging.Logger.FieldsTests.Logger200 1(FieldsTests.java:38) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl. java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces sorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:601) at javasoft.sqe.javatest.lib.MultiTest.invokeTestCase(MultiTest.java:406 ) at javasoft.sqe.javatest.lib.MultiTest.run(MultiTest.java:195) at nsk.stress.share.StressTest$TestThread.runTest(StressTest.java:752) at nsk.stress.share.StressTest$TestThread.run(StressTest.java:768) :::::::::::::: Thread-169 :::::::::::::: "Thread-169" prio=3 tid=0x00000000024c0800 nid=0xba waiting for monitor entry [0 xfffffd7f67d25000] java.lang.Thread.State: BLOCKED (on object monitor) JavaThread state: _thread_blocked Thread: 0x00000000024c0800 [0xba] State: _at_safepoint _has_called_back 0 _at_p oll_safepoint 0 JavaThread state: _thread_blocked at java.util.logging.Logger.getLogger(Logger.java:314) - waiting to lock <0xfffffd7f79cb6c88> (a java.lang.Class for java.util. logging.Logger) at java.util.logging.LoggingProxyImpl.getLogger(LoggingProxyImpl.java:40 ) at sun.util.logging.LoggingSupport.getLogger(LoggingSupport.java:100) at sun.util.logging.PlatformLogger$JavaLogger.<init>(PlatformLogger.java :497) at sun.util.logging.PlatformLogger.newJavaLogger(PlatformLogger.java:155 ) at sun.util.logging.PlatformLogger.redirectPlatformLoggers(PlatformLogge r.java:146) - locked <0xfffffd7f7a0f8348> (a java.lang.Class for sun.util.logging.Pl atformLogger) at java.util.logging.LogManager$2.run(LogManager.java:288) at java.security.AccessController.doPrivileged(Native Method) at java.util.logging.LogManager.readPrimordialConfiguration(LogManager.j ava:283) - locked <0xfffffd7f7a0fa868> (a java.util.logging.LogManager) at java.util.logging.LogManager.getLogManager(LogManager.java:266) at java.util.logging.Logger.<init>(Logger.java:252) at java.util.logging.LogManager$RootLogger.<init>(LogManager.java:1113) at java.util.logging.LogManager$RootLogger.<init>(LogManager.java:1110) at java.util.logging.LogManager$1.run(LogManager.java:198) at java.security.AccessController.doPrivileged(Native Method) at java.util.logging.LogManager.<clinit>(LogManager.java:175) at java.util.logging.Logger.<init>(Logger.java:252) at javasoft.sqe.tests.api.java.util.logging.MyLogger.<init>(MyLogger.jav a:21) at javasoft.sqe.tests.api.java.util.logging.Porter.checkLog1(Porter.java :399) at javasoft.sqe.tests.api.java.util.logging.Logger.Fine1Tests.Logger0052 (Fine1Tests.java:44) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl. java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces sorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:601) at javasoft.sqe.javatest.lib.MultiTest.invokeTestCase(MultiTest.java:406 ) at javasoft.sqe.javatest.lib.MultiTest.run(MultiTest.java:195) at nsk.stress.share.StressTest$TestThread.runTest(StressTest.java:752) at nsk.stress.share.StressTest$TestThread.run(StressTest.java:768) The interesting part of Thread-168 is actually not shown, but can be deciphered from: Thread: 0x00000000024ad800 [0xb9] State: _at_safepoint _has_called_back 0 _at_p oll_safepoint 0 JavaThread state: _thread_blocked at java.util.logging.Logger.getLogger(Logger.java:314) - locked <0xfffffd7f79cb6c88> (a java.lang.Class for java.util.logging.L ogger) at javasoft.sqe.tests.api.java.util.logging.Logger.FieldsTests.Logger200 1(FieldsTests.java:38) Thread-168 is holding the class lock for java.util.logging.Logger, but what is it doing at Logger.java:314? Obviously something that allowed the thread to go to a safepoint: 313 public static synchronized Logger getLogger(String name) { 314 LogManager manager = LogManager.getLogManager(); 315 return manager.demandLogger(name); 316 } Calling LogManager.getLogManager(), but Thread-169 has the class lock for java.util.logging.LogManager. Deadlock...
04-05-2011