JDK-8049585 : Deadlock between PlatformLogger and AppContext
  • Type: Bug
  • Component: client-libs
  • Sub-Component: java.awt
  • Affected Version: 8,9
  • Priority: P2
  • Status: Closed
  • Resolution: Duplicate
  • Submitted: 2014-07-08
  • Updated: 2014-11-25
  • Resolved: 2014-11-25
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 9
9Resolved
Related Reports
Duplicate :  
JDK-8065709 - Deadlock in awt/logging apparently introduced by 8019623
Description
We see the following deadlock in our HotSpot testing:


Found one Java-level deadlock:
=============================

"Thread-32":
  waiting to lock Monitor@0x0000000001d3a7a0 (Object@0x0000000694e24bf8, a sun/awt/AppContext$GetAppContextLock),
  which is held by "Thread-50"
"Thread-50":
  waiting to lock Monitor@0x0000000001ae0d60 (Object@0x00000003c075c440, a java/lang/Class),
  which is held by "Thread-32"

And the threads are standing still at:
"Thread-50" #71 prio=5 os_prio=64 tid=0x0000000001c67000 nid=0x61 waiting for monitor entry [0xfffffd7fbd8c8000]
   java.lang.Thread.State: BLOCKED (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x0000000001c67000  [0x61] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at sun.util.logging.PlatformLogger.getLogger(PlatformLogger.java:192)
	- waiting to lock <0x00000003c075c440> (a java.lang.Class for sun.util.logging.PlatformLogger)
	at java.awt.EventQueue.<clinit>(EventQueue.java:185)
	at java.lang.Class.forName0(Native Method)
	at java.lang.Class.forName(Class.java:259)
	at sun.awt.SunToolkit.initEQ(SunToolkit.java:119)
	at sun.awt.SunToolkit.createNewAppContext(SunToolkit.java:304)
	at sun.awt.AppContext$2.run(AppContext.java:277)
	at sun.awt.AppContext$2.run(AppContext.java:266)
	at java.security.AccessController.doPrivileged(Native Method)
	at sun.awt.AppContext.initMainAppContext(AppContext.java:266)
	at sun.awt.AppContext.access$400(AppContext.java:135)
	at sun.awt.AppContext$3.run(AppContext.java:321)
	- locked <0x0000000694e24bf8> (a sun.awt.AppContext$GetAppContextLock)
	at sun.awt.AppContext$3.run(AppContext.java:304)
	at java.security.AccessController.doPrivileged(Native Method)
	at sun.awt.AppContext.getAppContext(AppContext.java:303)
	at java.awt.Component.<init>(Component.java:999)
	at java.awt.Button.<init>(Button.java:151)
	at java.awt.Button.<init>(Button.java:139)
	at javasoft.sqe.tests.api.java.util.EventObject.serial.ConstructorTests.ConstructorTest0001(ConstructorTests.java:66)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:484)
	at javasoft.sqe.javatest.lib.MultiTest.invokeTestCase(MultiTest.java:406)
	at javasoft.sqe.javatest.lib.MultiTest.run(MultiTest.java:195)
	at sun.reflect.GeneratedMethodAccessor39.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:484)
	at nsk.stress.share.StressTest$TestThread.runTest(StressTest.java:756)
	at nsk.stress.share.StressTest$TestThread.run(StressTest.java:770)

"Thread-32" #53 prio=5 os_prio=64 tid=0x0000000001ca7000 nid=0x4f waiting for monitor entry [0xfffffd7fbeadb000]
   java.lang.Thread.State: BLOCKED (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x0000000001ca7000  [0x4f] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at sun.awt.AppContext$3.run(AppContext.java:318)
	- waiting to lock <0x0000000694e24bf8> (a sun.awt.AppContext$GetAppContextLock)
	at sun.awt.AppContext$3.run(AppContext.java:304)
	at java.security.AccessController.doPrivileged(Native Method)
	at sun.awt.AppContext.getAppContext(AppContext.java:303)
	at sun.awt.AppContext$6.getAppletContext(AppContext.java:869)
	at java.util.logging.LogManager.getUserContext(LogManager.java:421)
	- locked <0x0000000694ea8f78> (a sun.awt.AppContext$6)
	at java.util.logging.LogManager.addLogger(LogManager.java:1073)
	at java.util.logging.LogManager.demandSystemLogger(LogManager.java:505)
	at java.util.logging.Logger.getPlatformLogger(Logger.java:576)
	at java.util.logging.LoggingProxyImpl.getLogger(LoggingProxyImpl.java:41)
	at sun.util.logging.LoggingSupport.getLogger(LoggingSupport.java:100)
	at sun.util.logging.PlatformLogger$JavaLoggerProxy.<init>(PlatformLogger.java:602)
	at sun.util.logging.PlatformLogger$JavaLoggerProxy.<init>(PlatformLogger.java:597)
	at sun.util.logging.PlatformLogger.<init>(PlatformLogger.java:239)
	at sun.util.logging.PlatformLogger.getLogger(PlatformLogger.java:198)
	- locked <0x00000003c075c440> (a java.lang.Class for sun.util.logging.PlatformLogger)
	at java.util.prefs.FileSystemPreferences.getLogger(FileSystemPreferences.java:72)
	at java.util.prefs.FileSystemPreferences.access$200(FileSystemPreferences.java:50)
	at java.util.prefs.FileSystemPreferences$1.run(FileSystemPreferences.java:126)
	at java.util.prefs.FileSystemPreferences$1.run(FileSystemPreferences.java:109)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.util.prefs.FileSystemPreferences.setupUserRoot(FileSystemPreferences.java:109)
	at java.util.prefs.FileSystemPreferences.getUserRoot(FileSystemPreferences.java:102)
	- locked <0x00000003c058bf88> (a java.lang.Class for java.util.prefs.FileSystemPreferences)
	at java.util.prefs.FileSystemPreferencesFactory.userRoot(FileSystemPreferencesFactory.java:41)
	at java.util.prefs.Preferences.userRoot(Preferences.java:454)
	at java.util.prefs.Preferences.userNodeForPackage(Preferences.java:368)
	at javasoft.sqe.tests.api.java.util.prefs.Preferences.userNodeForPackageTests.UserNodeForPackage3003(userNodeForPackageTests.java:152)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:484)
	at javasoft.sqe.javatest.lib.MultiTest.invokeTestCase(MultiTest.java:406)
	at javasoft.sqe.javatest.lib.MultiTest.run(MultiTest.java:195)
	at sun.reflect.GeneratedMethodAccessor39.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:484)
	at nsk.stress.share.StressTest$TestThread.runTest(StressTest.java:756)
	at nsk.stress.share.StressTest$TestThread.run(StressTest.java:770)

ILW = H?H => P1 until it's triaged correctly.
Comments
Oh, JDK-8019623 was back ported to 6 recently, so it `will` be reproducible in 6.. But we've never seen this in 9 months of JDK-8, which supports my statement that it's extremely unlikely to happen. Ok, let's make it P2. But it's definitely not a P1.
08-07-2014
It looks to me that one of the locks were introduced 9 months ago. Are you sure this really is reproducible since jdk6? Since the main symptoms of this is a hang in our tests, it's possible that this likelihood isn't extremely low. It could be that no one has bothered to investigate the timeouts further, since there are a lot of other bug reports against the JCK nightly testing. Please, don't change from P2 to P3 if the ILW says P2. That sort of defeats the purpose of the ILW process.
08-07-2014
The deadlock is possible but very unlikely. It's been reproducible from jdk6 and haven't been escalated yet. The impact is high as it's a deadlock. The workaround is possible but hard. ILW=HLH, and it's P2, but I would still set make it P3, because the likelihood is extremely low. A simple fix would be to remove the logger from the EventQueue as nobody uses it. A complicated fix would be to change the Logger synchronization patterns.
08-07-2014
please evaluate asap
08-07-2014
FYI: there's another deadlock with PlatformLogger.getLogger and another lock: JDK-8030092 - Deadlock on LogManager initialization but via <clinit> of HttpURLConnection
08-07-2014
I found the following changeset that introduces the GetAppContextLock: $ hg log -r 8529 -p changeset: 8529:976e5f580124 user: leonidr date: Wed Oct 09 20:59:08 2013 +0400 summary: 8019623: Lack of synchronization in AppContext.getAppContext()
08-07-2014