This Bugzilla instance is a read-only archive of historic NetBeans bug reports. To report a bug in NetBeans please follow the project's instructions for reporting issues.

Bug 227981 - Deadlock initializing logger from NbTestCase vs. ContextMenuWarmUpTask
Summary: Deadlock initializing logger from NbTestCase vs. ContextMenuWarmUpTask
Status: RESOLVED WONTFIX
Alias: None
Product: platform
Classification: Unclassified
Component: JDK Problems (show other bugs)
Version: 7.3.1
Hardware: PC Linux
: P1 normal (vote)
Assignee: Antonin Nebuzelsky
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2013-03-27 08:25 UTC by Jaroslav Tulach
Modified: 2013-04-03 07:37 UTC (History)
0 users

See Also:
Issue Type: DEFECT
Exception Reporter:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Jaroslav Tulach 2013-03-27 08:25:43 UTC 
Full thread dump Java HotSpot(TM) 64-Bit Server VM (23.7-b01 mixed mode):

"Attach Listener" daemon prio=10 tid=0x00007f142c004000 nid=0x113c waiting on condition [0x0000000000000000]                                                                          
   java.lang.Thread.State: RUNNABLE                                                                                                                                                   
                                                                                                                                                                                      
"Thread-0" prio=10 tid=0x00007f13ec014000 nid=0x523e waiting for monitor entry [0x00007f143d8af000]                                                                                   
   java.lang.Thread.State: BLOCKED (on object monitor)                                                                                                                                
        at java.util.logging.LogManager$Cleaner.run(LogManager.java:237)                                                                                                              
        - waiting to lock <0x00000000f9c6be90> (a java.util.logging.LogManager)                                                                                                       
                                                                                                                                                                                      
"XToolkt-Shutdown-Thread" prio=10 tid=0x00007f13ec013000 nid=0x523d waiting for monitor entry [0x00007f143e7b5000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at sun.util.logging.PlatformLogger.getLogger(PlatformLogger.java:122)
        - waiting to lock <0x00000000f9c74150> (a java.lang.Class for sun.util.logging.PlatformLogger)
        at sun.awt.X11.XSystemTrayPeer.<clinit>(XSystemTrayPeer.java:36)
        at sun.awt.X11.XToolkit$1$1.run(XToolkit.java:322)

"SIGTERM handler" daemon prio=10 tid=0x00007f142c003000 nid=0x523c in Object.wait() [0x00007f143d7ae000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000fa2d41d0> (a sun.awt.X11.XToolkit$1$1)
        at java.lang.Thread.join(Thread.java:1258)
        - locked <0x00000000fa2d41d0> (a sun.awt.X11.XToolkit$1$1)
        at java.lang.Thread.join(Thread.java:1332)
        at java.lang.ApplicationShutdownHooks.runHooks(ApplicationShutdownHooks.java:106)
        at java.lang.ApplicationShutdownHooks$1.run(ApplicationShutdownHooks.java:46)
        at java.lang.Shutdown.runHooks(Shutdown.java:123)
        at java.lang.Shutdown.sequence(Shutdown.java:167)
        at java.lang.Shutdown.exit(Shutdown.java:212)
        - locked <0x00000000f9c6ce00> (a java.lang.Class for java.lang.Shutdown)
        at java.lang.Terminator$1.handle(Terminator.java:52)
        at sun.misc.Signal$1.run(Signal.java:212)
        at java.lang.Thread.run(Thread.java:722)

"AWT-EventQueue-0" prio=10 tid=0x00007f145046d800 nid=0x5167 waiting for monitor entry [0x00007f143de85000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at java.util.logging.LogManager.drainLoggerRefQueueBounded(LogManager.java:811)
        - waiting to lock <0x00000000f9c6be90> (a java.util.logging.LogManager)
        at java.util.logging.LogManager$LoggerContext.addLocalLogger(LogManager.java:511)
        - locked <0x00000000f9c6c890> (a java.util.logging.LogManager$SystemLoggerContext)
        at java.util.logging.LogManager$SystemLoggerContext.demandLogger(LogManager.java:647)
        at java.util.logging.LogManager.demandSystemLogger(LogManager.java:430)
        at java.util.logging.Logger.getPlatformLogger(Logger.java:427)
        at java.util.logging.LoggingProxyImpl.getLogger(LoggingProxyImpl.java:41)
        at sun.util.logging.LoggingSupport.getLogger(LoggingSupport.java:100)
        at sun.util.logging.PlatformLogger$JavaLogger.<init>(PlatformLogger.java:497)
        at sun.util.logging.PlatformLogger$JavaLogger.<init>(PlatformLogger.java:492)
        at sun.util.logging.PlatformLogger.<init>(PlatformLogger.java:164)
        at sun.util.logging.PlatformLogger.getLogger(PlatformLogger.java:128)
        - locked <0x00000000f9c74150> (a java.lang.Class for sun.util.logging.PlatformLogger)
        at java.awt.KeyboardFocusManager.<clinit>(KeyboardFocusManager.java:112)
        at java.awt.Component.hasFocus(Component.java:7982)
        at java.awt.Component.isFocusOwner(Component.java:7995)
        at javax.swing.AbstractButton.setFocusPainted(AbstractButton.java:1448)
        at javax.swing.JMenuItem.init(JMenuItem.java:208)
        at javax.swing.JMenuItem.<init>(JMenuItem.java:150)
        at javax.swing.JMenuItem.<init>(JMenuItem.java:109)
        at org.netbeans.core.ui.warmup.ContextMenuWarmUpTask.run(ContextMenuWarmUpTask.java:75)
        at java.awt.event.InvocationEvent.dispatch(InvocationEvent.java:251)
        at java.awt.EventQueue.dispatchEventImpl(EventQueue.java:727)
        at java.awt.EventQueue.access$200(EventQueue.java:103)
        at java.awt.EventQueue$3.run(EventQueue.java:688)
        at java.awt.EventQueue$3.run(EventQueue.java:686)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.security.ProtectionDomain$1.doIntersectionPrivilege(ProtectionDomain.java:76)
        at java.awt.EventQueue.dispatchEvent(EventQueue.java:697)
        at java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:242)
        at java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:161)
        at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:150)
        at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:146)
        at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:138)
        at java.awt.EventDispatchThread.run(EventDispatchThread.java:91)

"AWT-Shutdown" prio=10 tid=0x00007f145046c000 nid=0x5166 in Object.wait() [0x00007f143df88000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000fa2dc7d0> (a java.lang.Object)
        at java.lang.Object.wait(Object.java:503)
        at sun.awt.AWTAutoShutdown.run(AWTAutoShutdown.java:287)
        - locked <0x00000000fa2dc7d0> (a java.lang.Object)
        at java.lang.Thread.run(Thread.java:722)

"AWT-XAWT" daemon prio=10 tid=0x00007f1450468000 nid=0x5165 runnable [0x00007f143e089000]
   java.lang.Thread.State: RUNNABLE
        at sun.awt.X11.XToolkit.waitForEvents(Native Method)
        at sun.awt.X11.XToolkit.run(XToolkit.java:627)
        at sun.awt.X11.XToolkit.run(XToolkit.java:591)
        at java.lang.Thread.run(Thread.java:722)

"Java2D Disposer" daemon prio=10 tid=0x00007f145043c800 nid=0x5162 in Object.wait() [0x00007f143e18a000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000fa2c9ac8> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
        - locked <0x00000000fa2c9ac8> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
        at sun.java2d.Disposer.run(Disposer.java:145)
        at java.lang.Thread.run(Thread.java:722)

"Active Reference Queue Daemon" daemon prio=10 tid=0x00007f14503a5000 nid=0x5155 in Object.wait() [0x00007f143e8b6000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000fa1d0d40> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
        - locked <0x00000000fa1d0d40> (a java.lang.ref.ReferenceQueue$Lock)
        at org.openide.util.lookup.implspi.ActiveQueue$Daemon.run(ActiveQueue.java:180)
        - locked <0x00000000fa1d0d40> (a java.lang.ref.ReferenceQueue$Lock)

"Service Thread" daemon prio=10 tid=0x00007f14500f2000 nid=0x5152 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" daemon prio=10 tid=0x00007f14500f0000 nid=0x5151 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" daemon prio=10 tid=0x00007f14500ed000 nid=0x5150 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x00007f14500eb000 nid=0x514f runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x00007f145009d800 nid=0x514e in Object.wait() [0x00007f144c692000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000f9565798> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
        - locked <0x00000000f9565798> (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=0x00007f145009b800 nid=0x514d in Object.wait() [0x00007f144c793000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000f9565320> (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 <0x00000000f9565320> (a java.lang.ref.Reference$Lock)

"main" prio=10 tid=0x00007f145000a800 nid=0x5132 waiting for monitor entry [0x00007f1455c9f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at java.util.logging.LogManager$LoggerContext.findLogger(LogManager.java:489)
        - waiting to lock <0x00000000f9c6c890> (a java.util.logging.LogManager$SystemLoggerContext)
        at java.util.logging.LogManager.setLevelsOnExistingLoggers(LogManager.java:1356)
        - locked <0x00000000f9c6be90> (a java.util.logging.LogManager)
        at java.util.logging.LogManager.readConfiguration(LogManager.java:1115)
        at org.netbeans.junit.Log.configure(Log.java:258)
        at org.netbeans.junit.NbTestCase.run(NbTestCase.java:286)
        at junit.framework.TestSuite.runTest(TestSuite.java:255)
        at junit.framework.TestSuite.run(TestSuite.java:250)
        at org.junit.internal.runners.JUnit38ClassRunner.run(JUnit38ClassRunner.java:84)
        at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
        at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:422)
        at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:931)
        at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:785)

"VM Thread" prio=10 tid=0x00007f1450094000 nid=0x514c runnable 

"GC task thread#0 (ParallelGC)" prio=10 tid=0x00007f1450018800 nid=0x5134 runnable 

"GC task thread#1 (ParallelGC)" prio=10 tid=0x00007f145001a800 nid=0x5144 runnable 

"GC task thread#2 (ParallelGC)" prio=10 tid=0x00007f145001c000 nid=0x5145 runnable 

"GC task thread#3 (ParallelGC)" prio=10 tid=0x00007f145001e000 nid=0x514b runnable 

"VM Periodic Task Thread" prio=10 tid=0x00007f14500fc800 nid=0x5153 waiting on condition 

JNI global references: 408


Found one Java-level deadlock:
=============================
"Thread-0":
  waiting to lock monitor 0x00007f14040047d8 (object 0x00000000f9c6be90, a java.util.logging.LogManager),
  which is held by "main"
"main":
  waiting to lock monitor 0x00007f1434004298 (object 0x00000000f9c6c890, a java.util.logging.LogManager$SystemLoggerContext),
  which is held by "AWT-EventQueue-0"
"AWT-EventQueue-0":
  waiting to lock monitor 0x00007f14040047d8 (object 0x00000000f9c6be90, a java.util.logging.LogManager),
  which is held by "main"

Java stack information for the threads listed above:
===================================================
"Thread-0":
        at java.util.logging.LogManager$Cleaner.run(LogManager.java:237)
        - waiting to lock <0x00000000f9c6be90> (a java.util.logging.LogManager)
"main":
        at java.util.logging.LogManager$LoggerContext.findLogger(LogManager.java:489)
        - waiting to lock <0x00000000f9c6c890> (a java.util.logging.LogManager$SystemLoggerContext)
        at java.util.logging.LogManager.setLevelsOnExistingLoggers(LogManager.java:1356)
        - locked <0x00000000f9c6be90> (a java.util.logging.LogManager)
        at java.util.logging.LogManager.readConfiguration(LogManager.java:1115)
        at org.netbeans.junit.Log.configure(Log.java:258)
        at org.netbeans.junit.NbTestCase.run(NbTestCase.java:286)
        at junit.framework.TestSuite.runTest(TestSuite.java:255)
        at junit.framework.TestSuite.run(TestSuite.java:250)
        at org.junit.internal.runners.JUnit38ClassRunner.run(JUnit38ClassRunner.java:84)
        at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
        at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:422)
        at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:931)
        at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:785)
"AWT-EventQueue-0":
        at java.util.logging.LogManager.drainLoggerRefQueueBounded(LogManager.java:811)
        - waiting to lock <0x00000000f9c6be90> (a java.util.logging.LogManager)
        at java.util.logging.LogManager$LoggerContext.addLocalLogger(LogManager.java:511)
        - locked <0x00000000f9c6c890> (a java.util.logging.LogManager$SystemLoggerContext)
        at java.util.logging.LogManager$SystemLoggerContext.demandLogger(LogManager.java:647)
        at java.util.logging.LogManager.demandSystemLogger(LogManager.java:430)
        at java.util.logging.Logger.getPlatformLogger(Logger.java:427)
        at java.util.logging.LoggingProxyImpl.getLogger(LoggingProxyImpl.java:41)
        at sun.util.logging.LoggingSupport.getLogger(LoggingSupport.java:100)
        at sun.util.logging.PlatformLogger$JavaLogger.<init>(PlatformLogger.java:497)
        at sun.util.logging.PlatformLogger$JavaLogger.<init>(PlatformLogger.java:492)
        at sun.util.logging.PlatformLogger.<init>(PlatformLogger.java:164)
        at sun.util.logging.PlatformLogger.getLogger(PlatformLogger.java:128)
        - locked <0x00000000f9c74150> (a java.lang.Class for sun.util.logging.PlatformLogger)
        at java.awt.KeyboardFocusManager.<clinit>(KeyboardFocusManager.java:112)
        at java.awt.Component.hasFocus(Component.java:7982)
        at java.awt.Component.isFocusOwner(Component.java:7995)
        at javax.swing.AbstractButton.setFocusPainted(AbstractButton.java:1448)
        at javax.swing.JMenuItem.init(JMenuItem.java:208)
        at javax.swing.JMenuItem.<init>(JMenuItem.java:150)
        at javax.swing.JMenuItem.<init>(JMenuItem.java:109)
        at org.netbeans.core.ui.warmup.ContextMenuWarmUpTask.run(ContextMenuWarmUpTask.java:75)
        at java.awt.event.InvocationEvent.dispatch(InvocationEvent.java:251)
        at java.awt.EventQueue.dispatchEventImpl(EventQueue.java:727)
        at java.awt.EventQueue.access$200(EventQueue.java:103)
        at java.awt.EventQueue$3.run(EventQueue.java:688)
        at java.awt.EventQueue$3.run(EventQueue.java:686)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.security.ProtectionDomain$1.doIntersectionPrivilege(ProtectionDomain.java:76)
        at java.awt.EventQueue.dispatchEvent(EventQueue.java:697)
        at java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:242)
        at java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:161)
        at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:150)
        at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:146)
        at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:138)
        at java.awt.EventDispatchThread.run(EventDispatchThread.java:91)

Found 1 deadlock.
Comment 1 Jaroslav Tulach 2013-03-27 12:17:08 UTC 
This is a deadlock in JDK.

drainLoggerRefQueueBounded is synchronized on LogManager and calls synchronized method on LoggerContext. LoggerContext's synchronized method addLocalLogger has reversed order of locks and calls into synchronized method on LogManager.

Please report to JDK team and escalate.
Comment 2 Jaroslav Tulach 2013-03-27 17:03:17 UTC 
ergonomics#a852a55bde4d
author      : Jaroslav Tulach <jtulach@netbeans.org>
date        : Wed Mar 27 18:02:25 CET 2013
summary     : To workaround #227981 - get the LogManager lock sooner than the LoggerContext lock is acquired
Comment 3 Antonin Nebuzelsky 2013-03-27 17:11:17 UTC 
JDK bug #8010939
Comment 4 Jaroslav Tulach 2013-04-03 07:37:05 UTC 
Downgrading to any JDK older than JDK7_u13 should fix the problem.