JDK-8276210 : Test sun/tools/jhsdb/JStackStressTest.java timed out
  • Type: Bug
  • Component: hotspot
  • Sub-Component: svc-agent
  • Affected Version: 18,19
  • Priority: P5
  • Status: Closed
  • Resolution: Cannot Reproduce
  • OS: linux
  • CPU: aarch64
  • Submitted: 2021-10-31
  • Updated: 2023-09-16
  • Resolved: 2023-09-16
Related Reports
Relates :  
JDK-8313798 - [aarch64] sun/tools/jhsdb/HeapDumpTestWithActiveProcess.java sometimes times out on aarch64
Relates :  
JDK-8313800 - AArch64: SA stack walking code having trouble finding sender frame when invoking LambdaForms is involved
Relates :  
JDK-8248675 - [aarch64] serviceability/sa/TestJhsdbJstackMixed.java fails with "Exception: sun.jvm.hotspot.debugger.UnmappedAddressException: e0a646adbd850"
Sub Tasks
JDK-8289585 :  
ProblemList sun/tools/jhsdb/JStackStressTest.java on linux-aarch64 - Resolved
JDK-8316148 :  
Remove sun/tools/jhsdb/JStackStressTest.java from problem list - Resolved
Description
###### End of all output for iteration 2 which took 1536ms
[2021-10-31T14:04:21.901852603Z] Waiting for completion for process 4123416
[2021-10-31T14:04:21.901934883Z] Waiting for completion finished for process 4123416
###### Starting jstack iteration 3 against 4123336
[2021-10-31T14:04:21.907698230Z] Gathering output for process 4123457
Timeout refired 960 times
[2021-10-31T14:20:51.687009413Z] Waiting for completion for process 4123457
Comments
Closing as "Cannot Reproduce" instead of Resolving as...
16-09-2023
This CR no longer seems to be reproducing, even before JDK-8313800 was just pushed. I'm not sure what may have fixed it, but if even the bug was potentially still there, it has likely been fixed by JDK-8313800. sun/tools/jhsdb/JStackStressTest.java has been removed from the problem list. Closing as CNR.
15-09-2023
I'm closing this as a dup of JDK-8313798, which has now been fixed. The timeouts should be gone, but there is still an underlying stack walking issue on aarch64. That could result in now getting the following exception instead of the timeout: Error occurred during stack walking: java.lang.RuntimeException: newSP(0x0000000122808220) is not above oldSP(0x000000016db520f0) That exception, and others that may be thrown on aarch64, are now covered by JDK-8313800. UPDATE: Actually I'm not closing as a dup yet. JStackStressTest.java is problem listed with this CR.
17-08-2023
Here's a log file snippet for the jdk-19+20-1298-tier6 sighting: sun/tools/jhsdb/JStackStressTest.java jhsdb jstack stderr: ###### End of all output for iteration 3 which took 1791ms [2022-04-22T18:00:14.768789543Z] Waiting for completion for process 1808306 [2022-04-22T18:00:14.768844864Z] Waiting for completion finished for process 1808306 ###### Starting jstack iteration 4 against 1808057 [2022-04-22T18:00:14.771757483Z] Gathering output for process 1808349 Timeout refired 960 times [2022-04-22T18:16:43.112292114Z] Waiting for completion for process 1808349 [2022-04-22T18:16:43.112419755Z] Waiting for completion finished for process 1808349 Output and diagnostic info for process 1808349 was saved into 'pid-1808349-output.log' jhsdb jstack stdout: Attaching to process ID 1808057, please wait... Debugger attached successfully. Server compiler detected. JVM version is 19-ea+20-1298 Deadlock Detection: No deadlocks found. "main" #1 prio=5 tid=0x0000fffe4c0256a0 nid=1808058 runnable [0x0000fffe5148d000] java.lang.Thread.State: RUNNABLE JavaThread state: _thread_in_vm - jdk.internal.jshell.tool.JShellTool$$Lambda$347+0x0000000800dd0448.<init>(jdk.internal.jshell.tool.JShellTool) @bci=6 (Interpreted frame) - java.lang.invoke.DirectMethodHandle$Holder.newInvokeSpecial(java.lang.Object, java.lang.Object) @bci=16 (Compiled frame) jhsdb jstack stderr: ###### End of all output for iteration 4 which took 988343ms [2022-04-22T18:16:43.113076639Z] Waiting for completion for process 1808349 [2022-04-22T18:16:43.113359921Z] Waiting for completion finished for process 1808349 [2022-04-22T18:16:43.113415081Z] Waiting for completion for process 1808349 [2022-04-22T18:16:43.113452162Z] Waiting for completion finished for process 1808349 [JShell] State engine terminated. [JShell] | Welcome to JShell -- Version 19-ea jshell Output: | For an introduction type: /help intro jshell> | Goodbye ----------System.err:(36/1705)---------- stdout: [Attaching to process ID 1808057, please wait... Debugger attached successfully. Server compiler detected. JVM version is 19-ea+20-1298 Deadlock Detection: No deadlocks found. "main" #1 prio=5 tid=0x0000fffe4c0256a0 nid=1808058 runnable [0x0000fffe5148d000] java.lang.Thread.State: RUNNABLE JavaThread state: _thread_in_vm - jdk.internal.jshell.tool.JShellTool$$Lambda$347+0x0000000800dd0448.<init>(jdk.internal.jshell.tool.JShellTool) @bci=6 (Interpreted frame) - java.lang.invoke.DirectMethodHandle$Holder.newInvokeSpecial(java.lang.Object, java.lang.Object) @bci=16 (Compiled frame) ]; stderr: [] exitValue = 134 java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: Expected to get exit value of [0] at JStackStressTest.testjstack(JStackStressTest.java:78) at JStackStressTest.main(JStackStressTest.java:105) at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104) at java.base/java.lang.reflect.Method.invoke(Method.java:578) at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127) at java.base/java.lang.Thread.run(Thread.java:828) Caused by: java.lang.RuntimeException: Expected to get exit value of [0] at jdk.test.lib.process.OutputAnalyzer.shouldHaveExitValue(OutputAnalyzer.java:489) at JStackStressTest.testjstack(JStackStressTest.java:70) ... 5 more JavaTest Message: Test threw exception: java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: Expected to get exit value of [0] JavaTest Message: shutting down test STATUS:Failed.`main' threw exception: java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: Expected to get exit value of [0] ----------rerun:(37/6592)*---------- <snip> result: Error. Program `/opt/mach5/mesos/work_dir/jib-master/install/jdk-19+20-1298/linux-aarch64-open.jdk/jdk-19/bin/java' timed out (timeout set to 960000ms, elapsed time including timeout handling was 1002670ms).
22-04-2022
This could be related to JDK-8248675.
02-11-2021
It looks like 3 jstack iterations were completed before the timeout. The test wants to do 4. Here's are some key log snippets: ###### Starting jstack iteration 1 against 4123336 <snipped full jstack output> ###### End of all output for iteration 1 which took 1149ms ###### Starting jstack iteration 2 against 4123336 <snipped full jstack output> ###### End of all output for iteration 2 which took 1536ms ###### Starting jstack iteration 3 against 4123336 Timeout refired 960 times jhsdb jstack stdout: Attaching to process ID 4123336, please wait... Debugger attached successfully. Server compiler detected. JVM version is 18-ea+22-1385 Deadlock Detection: No deadlocks found. "main" #1 prio=5 tid=0x0000fffc04025760 nid=4123337 runnable [0x0000fffc0ab0c000] java.lang.Thread.State: RUNNABLE JavaThread state: _thread_in_native - jdk.internal.misc.Unsafe.allocateInstance(java.lang.Class) @bci=0 (Compiled frame; information may be imprecise) - java.lang.invoke.DirectMethodHandle.allocateInstance(java.lang.Object) @bci=12, line=492 (Compiled frame) - java.lang.invoke.DirectMethodHandle$Holder.newInvokeSpecial(java.lang.Object, java.lang.Object) @bci=1 (Compiled frame) - java.lang.invoke.Invokers$Holder.linkToTargetMethod(java.lang.Object, java.lang.Object) @bci=5 (Compiled frame) ###### End of all output for iteration 3 which took 989781ms So the first 2 iterations provided full stack traces and completed quickly. The 3rd one took a very long time, timed out, but eventually completed. However, it only provided a stack trace for "main", and it is incomplete, missing the whole bottom part (beginning) of the stack trace. So I think what happened is we tried to walk the stack at a bad time and couldn't successfully walk the main thread (which is actively running at the time). Also, after this iteration in the log you see: exitValue = 134 java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: Expected to get exit value of [0] at JStackStressTest.testjstack(JStackStressTest.java:78) at JStackStressTest.main(JStackStressTest.java:105) at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104) at java.base/java.lang.reflect.Method.invoke(Method.java:577) at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127) at java.base/java.lang.Thread.run(Thread.java:833) Caused by: java.lang.RuntimeException: Expected to get exit value of [0] at jdk.test.lib.process.OutputAnalyzer.shouldHaveExitValue(OutputAnalyzer.java:489) at JStackStressTest.testjstack(JStackStressTest.java:70) ... 5 more This would seem to indicate that the jstack process exitted with an error, but in fact according to the mach5 artifacts, it is still running and has the following stack trace: "main" #1 prio=5 os_prio=0 cpu=971014.21ms elapsed=974.17s allocated=57642M defined_classes=486 tid=0x0000ffff48025b30 nid=4123460 runnable [0x0000ffff4c39d000] java.lang.Thread.State: RUNNABLE at java.util.HashMap$HashIterator.nextNode(java.base@18-ea/HashMap.java:1601) at java.util.HashMap$ValueIterator.next(java.base@18-ea/HashMap.java:1625) at sun.jvm.hotspot.types.basic.BasicTypeDataBase.findDynamicTypeForAddress(jdk.hotspot.agent@18-ea/BasicTypeDataBase.java:269) at sun.jvm.hotspot.runtime.VirtualBaseConstructor.instantiateWrapperFor(jdk.hotspot.agent@18-ea/VirtualBaseConstructor.java:104) at sun.jvm.hotspot.utilities.GrowableArray.at(jdk.hotspot.agent@18-ea/GrowableArray.java:63) at sun.jvm.hotspot.code.CodeCache.findBlobUnsafe(jdk.hotspot.agent@18-ea/CodeCache.java:105) at sun.jvm.hotspot.code.CodeCache.findBlob(jdk.hotspot.agent@18-ea/CodeCache.java:88) at sun.jvm.hotspot.runtime.Frame.isRuntimeFrame(jdk.hotspot.agent@18-ea/Frame.java:162) at sun.jvm.hotspot.runtime.Frame.realSender(jdk.hotspot.agent@18-ea/Frame.java:213) at sun.jvm.hotspot.runtime.VFrame.sender(jdk.hotspot.agent@18-ea/VFrame.java:119) at sun.jvm.hotspot.runtime.VFrame.javaSender(jdk.hotspot.agent@18-ea/VFrame.java:148) at sun.jvm.hotspot.tools.StackTrace.run(jdk.hotspot.agent@18-ea/StackTrace.java:81) at sun.jvm.hotspot.tools.StackTrace.run(jdk.hotspot.agent@18-ea/StackTrace.java:45) at sun.jvm.hotspot.tools.JStack.run(jdk.hotspot.agent@18-ea/JStack.java:67) at sun.jvm.hotspot.tools.Tool.startInternal(jdk.hotspot.agent@18-ea/Tool.java:278) at sun.jvm.hotspot.tools.Tool.start(jdk.hotspot.agent@18-ea/Tool.java:241) at sun.jvm.hotspot.tools.Tool.execute(jdk.hotspot.agent@18-ea/Tool.java:134) at sun.jvm.hotspot.tools.JStack.runWithArgs(jdk.hotspot.agent@18-ea/JStack.java:90) at sun.jvm.hotspot.SALauncher.runJSTACK(jdk.hotspot.agent@18-ea/SALauncher.java:302) at sun.jvm.hotspot.SALauncher$$Lambda$3/0x0000000800c01c30.accept(jdk.hotspot.agent@18-ea/Unknown Source) at sun.jvm.hotspot.SALauncher.main(jdk.hotspot.agent@18-ea/SALauncher.java:500) So again this makes it look like jstack is having trouble with a thread's stack trace, and is likely just stuck in some sort of loop.
02-11-2021