JDK-8274421 : HeapDumpTestWithActiveProcess.java times out or fails with "Expected to get exit value of [0]"
  • Type: Bug
  • Component: hotspot
  • Sub-Component: svc-agent
  • Affected Version: 18,19,20,22
  • Priority: P4
  • Status: Open
  • Resolution: Unresolved
  • OS: linux
  • CPU: aarch64
  • Submitted: 2021-09-28
  • Updated: 2024-07-27
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.
Other
tbdUnresolved
Related Reports
Relates :  
JDK-8247641 - HeapDumpTestWithActiveProcess.java has multiple undetected failure modes
Description
sun/tools/jhsdb/HeapDumpTestWithActiveProcess.java timed out on linux-aarch64

----------System.out:(27/1215)----------
Starting Jshell
[JShell]:/opt/mach5/mesos/work_dir/jib-master/install/jdk-18+17-984/linux-aarch64-debug.jdk/jdk-18/fastdebug/bin/jshell
[JShell] |  Welcome to JShell -- Version 18-ea
[JShell] |  For an introduction type: /help intro
Jshell Started in 5732ms
Starting jmap against 290150
[2021-09-28T04:26:32.812775996Z] Gathering output for process 291215
Timeout refired 960 times
[2021-09-28T04:43:16.753296914Z] Waiting for completion for process 291215
[2021-09-28T04:43:16.753500234Z] Waiting for completion finished for process 291215
Output and diagnostic info for process 291215 was saved into 'pid-291215-output.log'
jhsdb jmap stdout:
Attaching to process ID 290150, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 18-ea+17-984

jhsdb jmap stderr:

###### End of all output:
[2021-09-28T04:43:16.757084483Z] Waiting for completion for process 291215
[2021-09-28T04:43:16.757192483Z] Waiting for completion finished for process 291215
[2021-09-28T04:43:16.757343204Z] Waiting for completion for process 291215
[2021-09-28T04:43:16.757399404Z] Waiting for completion finished for process 291215
[JShell] |  State engine terminated.
Destroying jshell
Jshell destroyed
----------System.err:(33/1685)----------
[JShell] Sep 28, 2021 4:26:27 AM java.util.prefs.FileSystemPreferences$1 run
[JShell] INFO: Created user preferences directory.
 stdout: [Attaching to process ID 290150, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 18-ea+17-984
];
 stderr: []
 exitValue = 134

java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: Expected to get exit value of [0]

	at JShellHeapDumpTest.launch(JShellHeapDumpTest.java:82)
	at JShellHeapDumpTest.launch(JShellHeapDumpTest.java:97)
	at JShellHeapDumpTest.testHeapDump(JShellHeapDumpTest.java:121)
	at JShellHeapDumpTest.main(JShellHeapDumpTest.java:169)
	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.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 JShellHeapDumpTest.launch(JShellHeapDumpTest.java:80)
	... 9 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]
Comments
Yup! I was way too focused on the "Expected to get exit value of [0]" part of the failure... I have relinked the jdk-22+16-1248-tier5 sighting to JDK-8247641 and I have move my sighting entries from this bug to JDK-8247641. Thanks for catching my goof!!
22-09-2023
The synopsis does cover "Expected to get exit value of [0], exit value is: [1]". However, we haven't seen "illegal bci" much since JDK-8244383 was fixed, but JDK-8244383 does warn that it still pops up once in a great while. In JDK-8244383 I also commented that "I think this is the same issue as JDK-8247641", so maybe it should go there. :)
22-09-2023
[~dcubed] The Illegal bci error would seem to be a different failure mode to those in this bug report. Perhaps JDK-8247641 would be more suitable?
22-09-2023
Here's a log file snippet from the jdk-20+9-472-tier5 sighting: sun/tools/jhsdb/HeapDumpTestWithActiveProcess.java #section:main ----------messages:(7/342)---------- command: main JShellHeapDumpTest nosleep reason: User specified action: run main/timeout=240 JShellHeapDumpTest nosleep Mode: othervm [test requires non-default system module] Additional options from @modules: --add-modules jdk.hotspot.agent,java.management Timeout information: --- Timeout information end. elapsed time (seconds): 1076.791 ----------configuration:(3/61)---------- Boot Layer add modules: jdk.hotspot.agent java.management ----------System.out:(30/1434)---------- Starting Jshell [JShell]:/opt/mach5/mesos/work_dir/jib-master/install/jdk-20+9-472/linux-aarch64-debug.jdk/jdk-20/fastdebug/bin/jshell [JShell] | Welcome to JShell -- Version 20-ea [JShell] | For an introduction type: /help intro Jshell Started in 5054ms Starting jmap against 1663188 [2022-08-01T06:43:02.621878534Z] Gathering output for process 1663398 Timeout refired 960 times [JShell] | State engine terminated. [2022-08-01T07:00:39.625789171Z] Waiting for completion for process 1663398 [2022-08-01T07:00:39.625992811Z] Waiting for completion finished for process 1663398 Output and diagnostic info for process 1663398 was saved into 'pid-1663398-output.log' jhsdb jmap stdout: Attaching to process ID 1663188, please wait... Debugger attached successfully. Server compiler detected. JVM version is 20-ea+9-472 InstanceStackChunkKlass: InstanceStackChunkKlass jhsdb jmap stderr: ###### End of all output: [2022-08-01T07:00:39.629983530Z] Waiting for completion for process 1663398 [2022-08-01T07:00:39.630171210Z] Waiting for completion finished for process 1663398 [2022-08-01T07:00:39.630257250Z] Waiting for completion for process 1663398 [2022-08-01T07:00:39.630321690Z] Waiting for completion finished for process 1663398 [2022-08-01T07:00:39.645160888Z] Waiting for completion for process 1663398 [2022-08-01T07:00:39.645275568Z] Waiting for completion finished for process 1663398 Destroying jshell Jshell destroyed ----------System.err:(27/1505)---------- stdout: [Attaching to process ID 1663188, please wait... Debugger attached successfully. Server compiler detected. JVM version is 20-ea+9-472 InstanceStackChunkKlass: InstanceStackChunkKlass ]; stderr: [] exitValue = 134 java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: Expected to get exit value of [0], exit value is: [134] at JShellHeapDumpTest.launch(JShellHeapDumpTest.java:82) at JShellHeapDumpTest.launch(JShellHeapDumpTest.java:97) at JShellHeapDumpTest.testHeapDump(JShellHeapDumpTest.java:133) at JShellHeapDumpTest.main(JShellHeapDumpTest.java:184) 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:1589) Caused by: java.lang.RuntimeException: Expected to get exit value of [0], exit value is: [134] at jdk.test.lib.process.OutputAnalyzer.shouldHaveExitValue(OutputAnalyzer.java:490) at JShellHeapDumpTest.launch(JShellHeapDumpTest.java:80) ... 7 more JavaTest Message: Test threw exception: java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: Expected to get exit value of [0], exit value is: [134] 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], exit value is: [134] ----------rerun:(37/6619)*---------- <snip> result: Error. Program `/opt/mach5/mesos/work_dir/jib-master/install/jdk-20+9-472/linux-aarch64-debug.jdk/jdk-20/fastdebug/bin/java' timed out (timeout set to 960000ms, elapsed time including timeout handling was 1076789ms).
02-08-2022
Here's a log file snippet from the jdk-19+15-895-tier6 sighting: sun/tools/jhsdb/HeapDumpTestWithActiveProcess.java ----------System.out:(27/1227)---------- Starting Jshell [JShell]:/opt/mach5/mesos/work_dir/jib-master/install/jdk-19+15-895/linux-aarch64-debug.jdk/jdk-19/fastdebug/bin/jshell [JShell] | Welcome to JShell -- Version 19-ea [JShell] | For an introduction type: /help intro Jshell Started in 4781ms Starting jmap against 2139254 [2022-03-19T11:29:51.221751844Z] Gathering output for process 2139539 Timeout refired 2400 times [2022-03-19T12:10:36.105200515Z] Waiting for completion for process 2139539 [2022-03-19T12:10:36.105574076Z] Waiting for completion finished for process 2139539 Output and diagnostic info for process 2139539 was saved into 'pid-2139539-output.log' jhsdb jmap stdout: Attaching to process ID 2139254, please wait... Debugger attached successfully. Server compiler detected. JVM version is 19-ea+15-895 jhsdb jmap stderr: ###### End of all output: [2022-03-19T12:10:36.110045406Z] Waiting for completion for process 2139539 [2022-03-19T12:10:36.110157487Z] Waiting for completion finished for process 2139539 [2022-03-19T12:10:36.110233407Z] Waiting for completion for process 2139539 [2022-03-19T12:10:36.110291447Z] Waiting for completion finished for process 2139539 [JShell] | State engine terminated. Destroying jshell Jshell destroyed ----------System.err:(31/1500)---------- [JShell] Mar 19, 2022 11:29:46 AM java.util.prefs.FileSystemPreferences$1 run [JShell] INFO: Created user preferences directory. stdout: [Attaching to process ID 2139254, please wait... Debugger attached successfully. Server compiler detected. JVM version is 19-ea+15-895 ]; stderr: [] exitValue = 134 java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: Expected to get exit value of [0] at JShellHeapDumpTest.launch(JShellHeapDumpTest.java:82) at JShellHeapDumpTest.launch(JShellHeapDumpTest.java:97) at JShellHeapDumpTest.testHeapDump(JShellHeapDumpTest.java:133) at JShellHeapDumpTest.main(JShellHeapDumpTest.java:184) 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:828) Caused by: java.lang.RuntimeException: Expected to get exit value of [0] at jdk.test.lib.process.OutputAnalyzer.shouldHaveExitValue(OutputAnalyzer.java:489) at JShellHeapDumpTest.launch(JShellHeapDumpTest.java:80) ... 7 more JavaTest Message: Test threw exception: java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: Expected to get exit value of [0]
19-03-2022
The jmap process seems to be stuck walking the stack of the target process, causing the test process that launched the jmap process to eventually time out. Here's the stack for the jmap process: "main" #1 prio=5 os_prio=0 cpu=975856.03ms elapsed=984.50s allocated=60736M defined_classes=488 tid=0x0000ffff18028d40 nid=291217 runnable [0x0000ffff1daad000] java.lang.Thread.State: RUNNABLE Thread: 0x0000ffff18028d40 [0x47191] State: _at_safepoint _at_poll_safepoint 1 JavaThread state: _thread_blocked at sun.jvm.hotspot.types.basic.BasicTypeDataBase.findDynamicTypeForAddress(jdk.hotspot.agent@18-ea/BasicTypeDataBase.java:272) 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.isCompiledFrame(jdk.hotspot.agent@18-ea/Frame.java:154) at sun.jvm.hotspot.runtime.Frame.isJavaFrame(jdk.hotspot.agent@18-ea/Frame.java:134) at sun.jvm.hotspot.runtime.Frame.isFirstFrame(jdk.hotspot.agent@18-ea/Frame.java:178) at sun.jvm.hotspot.runtime.VFrame.sender(jdk.hotspot.agent@18-ea/VFrame.java:116) at sun.jvm.hotspot.runtime.VFrame.javaSender(jdk.hotspot.agent@18-ea/VFrame.java:148) at sun.jvm.hotspot.runtime.ThreadStackTrace.dumpStack(jdk.hotspot.agent@18-ea/ThreadStackTrace.java:53) at sun.jvm.hotspot.utilities.HeapHprofBinWriter.dumpStackTraces(jdk.hotspot.agent@18-ea/HeapHprofBinWriter.java:749) at sun.jvm.hotspot.utilities.HeapHprofBinWriter.write(jdk.hotspot.agent@18-ea/HeapHprofBinWriter.java:465) - locked <0x00000000d0335b88> (a sun.jvm.hotspot.utilities.HeapHprofBinWriter) at sun.jvm.hotspot.tools.JMap.writeHeapHprofBin(jdk.hotspot.agent@18-ea/JMap.java:216) at sun.jvm.hotspot.tools.JMap.run(jdk.hotspot.agent@18-ea/JMap.java:103) 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.JMap.main(jdk.hotspot.agent@18-ea/JMap.java:202) at sun.jvm.hotspot.SALauncher.runJMAP(jdk.hotspot.agent@18-ea/SALauncher.java:340) at sun.jvm.hotspot.SALauncher$$Lambda$4/0x0000000801002000.accept(jdk.hotspot.agent@18-ea/Unknown Source) at sun.jvm.hotspot.SALauncher.main(jdk.hotspot.agent@18-ea/SALauncher.java:500) This is the code it is stuck in: while (superClass != baseType && superClass != null) { superClass = superClass.getSuperclass(); } Somehow we've ended up with a class circularity. Probably VM data is being read while in an inconsistent state, and sanity checks are failing to detect this.
28-09-2021
This seems related to JDK-8247641, but will keep this open as a separate bug for now.
28-09-2021