JDK-8210558 : serviceability/sa/TestJhsdbJstackLock.java fails to find '^\s+- waiting to lock <0x[0-9a-f]+> \(a java\.lang\.Class ...'
  • Type: Bug
  • Component: hotspot
  • Sub-Component: svc-agent
  • Affected Version: 12,14,15,16,17
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2018-09-10
  • Updated: 2022-09-21
  • Resolved: 2021-12-06
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 17 JDK 18
17.0.6-oracleFixed 18 b27Fixed
Related Reports
Relates :  
JDK-8215042 - Umbrella bug for all SA failures in tier1
Description
Test serviceability/sa/TestJhsdbJstackLock.java *highly* intermittently fail to find expected line in jhsdb output. 

The log is:

'LingeredAppWithLock' '0b023fa7-6163-484a-8e84-c3293d499b1e.lck' ]

 stdout: [Attaching to process ID 46496, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 12-ea+10
Deadlock Detection:

No deadlocks found.

"Thread-3" #16 prio=5 tid=0x000000b3703d2000 nid=0x3b68 waiting on condition [0x000000b37165f000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
   JavaThread state: _thread_blocked
 - java.lang.Thread.sleep(long) @bci=0 (Interpreted frame)
 - LingeredAppWithLock.lockMethod(java.lang.Object) @bci=7, line=32 (Interpreted frame)
	- locked <0x0000000754100010> (a java.lang.Class for int)
 - LingeredAppWithLock.lambda$main$3() @bci=3, line=43 (Interpreted frame)
 - LingeredAppWithLock$$Lambda$4.run() @bci=0 (Interpreted frame)
 - java.lang.Thread.run() @bci=11, line=834 (Interpreted frame)


"Thread-2" #15 prio=5 tid=0x000000b3703d1800 nid=0x6c34 waiting on condition [0x000000b37155e000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
   JavaThread state: _thread_blocked
 - java.lang.Thread.sleep(long) @bci=0 (Interpreted frame)
 - LingeredAppWithLock.lockMethod(java.lang.Object) @bci=7, line=32 (Interpreted frame)
	- locked <0x00000007540303f8> (a java.lang.Thread)
 - LingeredAppWithLock.lambda$main$2(java.lang.Thread) @bci=1, line=42 (Interpreted frame)
 - LingeredAppWithLock$$Lambda$3.run() @bci=4 (Interpreted frame)
 - java.lang.Thread.run() @bci=11, line=834 (Interpreted frame)


"Thread-1" #14 prio=5 tid=0x000000b370384800 nid=0x9b88 waiting on condition [0x000000b37145f000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
   JavaThread state: _thread_blocked
 - java.lang.Thread.sleep(long) @bci=0 (Interpreted frame)
 - LingeredAppWithLock.lockMethod(java.lang.Object) @bci=7, line=32 (Interpreted frame)
	- locked <0x000000075402e508> (a java.lang.Class for LingeredAppWithLock)
 - LingeredAppWithLock.lambda$main$0() @bci=2, line=40 (Interpreted frame)
 - LingeredAppWithLock$$Lambda$2.run() @bci=0 (Interpreted frame)
 - java.lang.Thread.run() @bci=11, line=834 (Interpreted frame)


"Thread-0" #13 prio=5 tid=0x000000b370381800 nid=0x707c waiting for monitor entry [0x000000b37135f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
   JavaThread state: _thread_blocked
 - LingeredAppWithLock.lambda$main$0() @bci=2, line=40 (Interpreted frame)
 - LingeredAppWithLock$$Lambda$1.run() @bci=0 (Interpreted frame)
 - java.lang.Thread.run() @bci=11, line=834 (Interpreted frame)


"Common-Cleaner" #12 daemon prio=8 tid=0x000000b37034f000 nid=0x6580 in Object.wait() [0x000000b37125e000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
   JavaThread state: _thread_blocked
 - java.lang.Object.wait(long) @bci=0 (Interpreted frame)
	- waiting on <0x00000007540216d0> (a java.lang.ref.ReferenceQueue$Lock)
 - java.lang.ref.ReferenceQueue.remove(long) @bci=59, line=155 (Interpreted frame)
	- waiting to re-lock in wait() <0x00000007540216d0> (a java.lang.ref.ReferenceQueue$Lock)
 - jdk.internal.ref.CleanerImpl.run() @bci=65, line=148 (Interpreted frame)
 - java.lang.Thread.run() @bci=11, line=834 (Interpreted frame)
 - jdk.internal.misc.InnocuousThread.run() @bci=20, line=134 (Interpreted frame)


"Attach Listener" #5 daemon prio=5 tid=0x000000b37001c000 nid=0x6bc0 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked


"Signal Dispatcher" #4 daemon prio=9 tid=0x000000b370019800 nid=0x5f94 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked


"Finalizer" #3 daemon prio=8 tid=0x000000b36ffb3800 nid=0x28bc in Object.wait() [0x000000b37097f000]
   java.lang.Thread.State: WAITING (on object monitor)
   JavaThread state: _thread_blocked
 - java.lang.Object.wait(long) @bci=0 (Interpreted frame)
	- waiting on <0x0000000754108f10> (a java.lang.ref.ReferenceQueue$Lock)
 - java.lang.ref.ReferenceQueue.remove(long) @bci=59, line=155 (Interpreted frame)
	- waiting to re-lock in wait() <0x0000000754108f10> (a java.lang.ref.ReferenceQueue$Lock)
 - java.lang.ref.ReferenceQueue.remove() @bci=2, line=176 (Interpreted frame)
 - java.lang.ref.Finalizer$FinalizerThread.run() @bci=37, line=170 (Interpreted frame)


"Reference Handler" #2 daemon prio=10 tid=0x000000b36ffa9800 nid=0x7028 waiting on condition [0x000000b37087e000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
 - java.lang.ref.Reference.waitForReferencePendingList() @bci=0 (Interpreted frame)
 - java.lang.ref.Reference.processPendingReferences() @bci=0, line=241 (Interpreted frame)
 - java.lang.ref.Reference$ReferenceHandler.run() @bci=0, line=213 (Interpreted frame)


"main" #1 prio=5 tid=0x000000b34c1a5800 nid=0x1204 waiting on condition [0x000000b34b94f000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
   JavaThread state: _thread_blocked
 - java.lang.Thread.sleep(long) @bci=0 (Interpreted frame)
 - jdk.test.lib.apps.LingeredApp.main(java.lang.String[]) @bci=53, line=498 (Interpreted frame)
 - LingeredAppWithLock.main(java.lang.String[]) @bci=72, line=50 (Interpreted frame)


];
 stderr: []
 exitValue = 0

 LingeredApp stdout: [];
 LingeredApp stderr: []
 LingeredApp exitValue = 0
java.lang.RuntimeException: '^\\s+- waiting to lock <0x[0-9a-f]+> \\(a java\\.lang\\.Class for LingeredAppWithLock\\)$' missing from stdout/stderr 

	at jdk.test.lib.process.OutputAnalyzer.shouldMatch(OutputAnalyzer.java:258)
	at TestJhsdbJstackLock.main(TestJhsdbJstackLock.java:76)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.base/java.lang.Thread.run(Thread.java:834)

JavaTest Message: Test threw exception: java.lang.RuntimeException: '^\\s+- waiting to lock <0x[0-9a-f]+> \\(a java\\.lang\\.Class for LingeredAppWithLock\\)$' missing from stdout/stderr
Comments
A pull request was submitted for review. URL: https://git.openjdk.org/jdk17u-dev/pull/710 Date: 2022-09-21 11:40:16 +0000
21-09-2022
Fix request [17u] I backport this for parity with 17.0.6-oracle. No risk, only a test change. Clean backport. Test passes.
21-09-2022
Changeset: 587e5409 Author: Chris Plummer <cjplummer@openjdk.org> Date: 2021-12-06 16:09:45 +0000 URL: https://git.openjdk.java.net/jdk/commit/587e5409c2488cf8c3579a4932c588efc5a02749
06-12-2021
Making LingeredAppWithLock.main() wait until all the threads have started and reached their intended blocking or time waiting point seems to fix the issue.
04-12-2021
This root cause of the most recent failure above is JDK-8269830. It causes SA to sometimes think that a JavaThread object is actually a CompilerThread object, and jstack intentionally does not include CompilerThread objects. This CR will remain open to cover the initial failure, which is the result of using jstack before all the threads have fully started and stabilized.
02-12-2021
This most recent failure is different than the original one, which is due to not getting the stack trace for one of the 4 "lock" threads that are created: "Thread-1" #23 prio=5 tid=0x0000018daae677b0 nid=0x2704 waiting for monitor entry [0x0000000423bfe000] java.lang.Thread.State: BLOCKED (on object monitor) JavaThread state: _thread_blocked As mentioned above, a short delay would help to get this thread moved forward and stabilized so we can get its stack. For the latest failure, one of the 4 "lock" threads is completely missing. I believe this is the same issue that is causing 3 other CRs to show up, and has been prevalent on OSX recently. The bugs are JDK-8269522, JDK-8244980, and JDK-8257998. In all cases a thread is missing from the jstack output. I'm getting close to figuring out why. What I know so far is that for some reason SA thinks the thread is a CompilerThread (or at least that was the case in the one failure I added more diagnostic output for). CompilerThreads are intentionally not dumped in the jstack output. In one failing test case I also added output for the "clhsdb threads" command, and you will see the missing thread there because unlike jstack it dumps all threads.
02-07-2021
Here's a log file snippet for the jdk-18+5-135-tier4 sighting: serviceability/sa/TestJhsdbJstackLock.java Attaching to process ID 7824, please wait... Debugger attached successfully. Server compiler detected. JVM version is 18-ea+5-135 Deadlock Detection: No deadlocks found. "main" #1 prio=5 tid=0x00007fbbdc008a30 nid=0x1803 waiting on condition [0x0000700001ba9000] java.lang.Thread.State: TIMED_WAITING (sleeping) JavaThread state: _thread_blocked - java.lang.Thread.sleep(long) @bci=0 (Interpreted frame) - jdk.test.lib.apps.LingeredApp.main(java.lang.String[]) @bci=158, line=599 (Interpreted frame) - locked <0x00000007ca944a80> (a java.lang.Object) - LingeredAppWithLock.main(java.lang.String[]) @bci=72, line=50 (Interpreted frame) "Reference Handler" #2 daemon prio=10 tid=0x00007fbbdb80ba30 nid=0x3d03 waiting on condition [0x00007000022be000] java.lang.Thread.State: RUNNABLE JavaThread state: _thread_blocked - java.lang.ref.Reference.waitForReferencePendingList() @bci=0 (Interpreted frame) - java.lang.ref.Reference.processPendingReferences() @bci=0, line=253 (Interpreted frame) - java.lang.ref.Reference$ReferenceHandler.run() @bci=0, line=215 (Interpreted frame) "Finalizer" #3 daemon prio=8 tid=0x00007fbbdb80a430 nid=0x3b03 in Object.wait() [0x00007000023c1000] java.lang.Thread.State: WAITING (on object monitor) JavaThread state: _thread_blocked - java.lang.Object.wait(long) @bci=0 (Interpreted frame) - waiting on <0x00000007ca902f40> (a java.lang.ref.ReferenceQueue$Lock) - java.lang.ref.ReferenceQueue.remove(long) @bci=59, line=155 (Interpreted frame) - locked <0x00000007ca902f40> (a java.lang.ref.ReferenceQueue$Lock) - java.lang.ref.ReferenceQueue.remove() @bci=2, line=176 (Interpreted frame) - java.lang.ref.Finalizer$FinalizerThread.run() @bci=37, line=172 (Interpreted frame) "Signal Dispatcher" #4 daemon prio=9 tid=0x00007fbbda016230 nid=0xa90b waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE JavaThread state: _thread_blocked "Common-Cleaner" #13 daemon prio=8 tid=0x00007fbba981e430 nid=0x9d03 in Object.wait() [0x0000700002de2000] java.lang.Thread.State: TIMED_WAITING (on object monitor) JavaThread state: _thread_blocked - java.lang.Object.wait(long) @bci=0 (Interpreted frame) - waiting on <0x00000007ca91b6b8> (a java.lang.ref.ReferenceQueue$Lock) - java.lang.ref.ReferenceQueue.remove(long) @bci=59, line=155 (Interpreted frame) - locked <0x00000007ca91b6b8> (a java.lang.ref.ReferenceQueue$Lock) - jdk.internal.ref.CleanerImpl.run() @bci=45, line=140 (Interpreted frame) - java.lang.Thread.run() @bci=11, line=833 (Interpreted frame) - jdk.internal.misc.InnocuousThread.run() @bci=20, line=162 (Interpreted frame) "Thread-1" #15 prio=5 tid=0x00007fbbc982ac30 nid=0x9c03 waiting for monitor entry [0x0000700002fe8000] java.lang.Thread.State: BLOCKED (on object monitor) JavaThread state: _thread_blocked - LingeredAppWithLock.lockMethod(java.lang.Object) @bci=4, line=32 (Interpreted frame) - waiting to lock <0x00000007ca925130> (a java.lang.Class for LingeredAppWithLock) - LingeredAppWithLock.lambda$main$0() @bci=2, line=40 (Interpreted frame) - LingeredAppWithLock$$Lambda$2+0x000000012b801800.run() @bci=0 (Interpreted frame) - java.lang.Thread.run() @bci=11, line=833 (Interpreted frame) "Thread-2" #16 prio=5 tid=0x00007fbbc982d630 nid=0x9b03 waiting on condition [0x00007000030eb000] java.lang.Thread.State: TIMED_WAITING (sleeping) JavaThread state: _thread_blocked - java.lang.Thread.sleep(long) @bci=0 (Interpreted frame) - LingeredAppWithLock.lockMethod(java.lang.Object) @bci=7, line=32 (Interpreted frame) - locked <0x00000007ca9284f8> (a java.lang.Thread) - LingeredAppWithLock.lambda$main$2(java.lang.Thread) @bci=1, line=42 (Interpreted frame) - LingeredAppWithLock$$Lambda$3+0x000000012b801a18.run() @bci=4 (Interpreted frame) - java.lang.Thread.run() @bci=11, line=833 (Interpreted frame) "Thread-3" #17 prio=5 tid=0x00007fbbc982dc30 nid=0x6403 waiting on condition [0x00007000031ee000] java.lang.Thread.State: TIMED_WAITING (sleeping) JavaThread state: _thread_blocked - java.lang.Thread.sleep(long) @bci=0 (Interpreted frame) - LingeredAppWithLock.lockMethod(java.lang.Object) @bci=7, line=32 (Interpreted frame) - locked <0x00000007ffe002a0> (a java.lang.Class for int) - LingeredAppWithLock.lambda$main$3() @bci=3, line=43 (Interpreted frame) - LingeredAppWithLock$$Lambda$4+0x000000012b801c38.run() @bci=0 (Interpreted frame) - java.lang.Thread.run() @bci=11, line=833 (Interpreted frame) "SteadyStateThread" #18 prio=5 tid=0x00007fbbda808830 nid=0x6603 waiting for monitor entry [0x00007000032f1000] java.lang.Thread.State: BLOCKED (on object monitor) JavaThread state: _thread_blocked - jdk.test.lib.apps.LingeredApp.steadyState(java.lang.Object) @bci=8, line=537 (Interpreted frame) - waiting to lock <0x00000007ca944a80> (a java.lang.Object) - jdk.test.lib.apps.LingeredApp$1.run() @bci=4, line=543 (Interpreted frame) ]; stderr: [] exitValue = 0 java.lang.RuntimeException: '^\\s+- locked <0x[0-9a-f]+> \\(a java\\.lang\\.Class for LingeredAppWithLock\\)$' missing from stdout/stderr at jdk.test.lib.process.OutputAnalyzer.shouldMatch(OutputAnalyzer.java:340) at TestJhsdbJstackLock.main(TestJhsdbJstackLock.java:63) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:568) at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312) at java.base/java.lang.Thread.run(Thread.java:833) JavaTest Message: Test threw exception: java.lang.RuntimeException JavaTest Message: shutting down test result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: '^\s+- locked <0x[0-9a-f]+> \(a java\.lang\.Class for LingeredAppWithLock\)$' missing from stdout/stderr
02-07-2021
The test is fairly simple: public static void lockMethod(Object lock) { synchronized (lock) { try { Thread.sleep(300000); } catch (InterruptedException e) { throw new RuntimeException(e); } } } public static void main(String args[]) { Thread classLock1 = new Thread(() -> lockMethod(LingeredAppWithLock.class)); Thread classLock2 = new Thread(() -> lockMethod(LingeredAppWithLock.class)); Thread objectLock = new Thread(() -> lockMethod(classLock1)); Thread primitiveLock = new Thread(() -> lockMethod(int.class)); classLock1.start(); classLock2.start(); objectLock.start(); primitiveLock.start(); LingeredApp.main(args); } For the above failure Thread-1 has no stack trace. It should be: "Thread-1" #23 prio=5 tid=0x00000137ad7e3320 nid=0x1f08 waiting for monitor entry [0x0000002f436ff000] java.lang.Thread.State: BLOCKED (on object monitor) JavaThread state: _thread_blocked - LingeredAppWithLock.lockMethod(java.lang.Object) @bci=4, line=32 (Interpreted frame) - waiting to lock <0x00000000c5023b98> (a java.lang.Class for LingeredAppWithLock) - LingeredAppWithLock.lambda$main$0() @bci=2, line=40 (Interpreted frame) - LingeredAppWithLock$$Lambda$2+0x0000000100061040.run() @bci=0 (Interpreted frame) - java.lang.Thread.run() @bci=11, line=832 (Interpreted frame) My guess is we just tried to get the stack trace too soon. Since Thread.start() is async, there is no guarantee that by the time "jhsdb jstack" is run that any thread has reached the point of blocking or sleeping. However, the original failure is a bit different. "Thread-1" #14 prio=5 tid=0x000000b370384800 nid=0x9b88 waiting on condition [0x000000b37145f000] java.lang.Thread.State: TIMED_WAITING (sleeping) JavaThread state: _thread_blocked - java.lang.Thread.sleep(long) @bci=0 (Interpreted frame) - LingeredAppWithLock.lockMethod(java.lang.Object) @bci=7, line=32 (Interpreted frame) - locked <0x000000075402e508> (a java.lang.Class for LingeredAppWithLock) - LingeredAppWithLock.lambda$main$0() @bci=2, line=40 (Interpreted frame) - LingeredAppWithLock$$Lambda$2.run() @bci=0 (Interpreted frame) - java.lang.Thread.run() @bci=11, line=834 (Interpreted frame) "Thread-0" #13 prio=5 tid=0x000000b370381800 nid=0x707c waiting for monitor entry [0x000000b37135f000] java.lang.Thread.State: BLOCKED (on object monitor) JavaThread state: _thread_blocked - LingeredAppWithLock.lambda$main$0() @bci=2, line=40 (Interpreted frame) - LingeredAppWithLock$$Lambda$1.run() @bci=0 (Interpreted frame) - java.lang.Thread.run() @bci=11, line=834 (Interpreted frame) In this case Thread-1 seems to have gotten to the synchronized block before Thread-0, so it holds the lock. That should be fine, and in this case it should be Thread-0 that ends up "waiting to lock", but it's not showing that in the stack trace. My guess here is that we are once again running jstack too soon, and the thread is in the process of synchronizing on the object, but hasn't gotten to the point yet of detecting it's already locked and changing the thread's state to "waiting to lock". A short delay after starting all threads should solve this problem, although it would be nice to have a more deterministic way of synchronizing. But that's hard because we need to make sure the thread is fully blocked due to the synchronized(lock), and there's no way to set a flag after getting in that state.
29-06-2020