JDK-8278558 : sun/tools/jhsdb/HeapDumpTestWithActiveProcess.java failed with "exitValue = 134"
  • Type: Bug
  • Component: core-svc
  • Sub-Component: tools
  • Affected Version: 19
  • Priority: P4
  • Status: Closed
  • Resolution: Duplicate
  • OS: linux
  • CPU: aarch64
  • Submitted: 2021-12-10
  • Updated: 2021-12-10
  • Resolved: 2021-12-10
Related Reports
Duplicate :  
Relates :  
Description
The following test failed in the JDK19 CI:

sun/tools/jhsdb/HeapDumpTestWithActiveProcess.java

Here's a snippet from the log file:

----------System.out:(27/1221)----------
Starting Jshell
[JShell]:/opt/mach5/mesos/work_dir/jib-master/install/jdk-19+1-4/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 4209ms
Starting jmap against 3091953
[2021-12-10T16:23:52.769736121Z] Gathering output for process 3093187
Timeout refired 2400 times
[2021-12-10T17:04:38.671267751Z] Waiting for completion for process 3093187
[2021-12-10T17:04:38.671635034Z] Waiting for completion finished for process 3093187
[JShell] |  State engine terminated.
Output and diagnostic info for process 3093187 was saved into 'pid-3093187-output.log'
jhsdb jmap stdout:
Attaching to process ID 3091953, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 19-ea+1-4

jhsdb jmap stderr:

###### End of all output:
[2021-12-10T17:04:38.676980592Z] Waiting for completion for process 3093187
[2021-12-10T17:04:38.677348435Z] Waiting for completion finished for process 3093187
[2021-12-10T17:04:38.677431835Z] Waiting for completion for process 3093187
[2021-12-10T17:04:38.677515676Z] Waiting for completion finished for process 3093187
Destroying jshell
Jshell destroyed
----------System.err:(29/1368)----------
 stdout: [Attaching to process ID 3091953, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 19-ea+1-4
];
 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.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 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]

JavaTest Message: shutting down test
Comments
I've copied the sighting info from here to JDK-8247641 to increase the odds that a future sighting will land on the right bug.
10-12-2021

I looks like the jhsdb process doing the heap dump asserted and/or timed out. The jhsdb process is 3093187, and this is the contents of pid-3093187-output.log --- ProcessLog --- cmd: /opt/mach5/mesos/work_dir/jib-master/install/jdk-19+1-4/linux-aarch64-debug.jdk/jdk-19/fastdebug/bin/jhsdb -J-Xmx768m -J-XX:MaxRAMPercentage=6.25 -J-Djava.io.tmpdir=/opt/mach5/mesos/work_dir/slaves/a2dc162d-743b-4800-9e92-31f85abb45b1-S153496/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/a5284be1-d605-41c6-87ec-ffc1a94754c1/runs/7a7e23af-f28b-4fa3-be29-7c4f7bf32f24/testoutput/test-support/jtreg_open_test_jdk_jdk_svc/tmp -J-ea -J-esa -J-XX:NativeMemoryTracking=detail jmap --binaryheap --dumpfile=/opt/mach5/mesos/work_dir/slaves/a2dc162d-743b-4800-9e92-31f85abb45b1-S153496/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/a5284be1-d605-41c6-87ec-ffc1a94754c1/runs/7a7e23af-f28b-4fa3-be29-7c4f7bf32f24/testoutput/test-support/jtreg_open_test_jdk_jdk_svc/scratch/1/jhsdb.jmap.heap.1639153428401.hprof --pid=3091953 exitvalue: 134 stderr: stdout: Attaching to process ID 3091953, please wait... Debugger attached successfully. Server compiler detected. JVM version is 19-ea+1-4 There was an hprof file produced, but it is under 1mb, so looks to be incomplete. The postmortem test support was able to run jstack on 3093187. The main thread seems to be stuck: "main" #1 prio=5 os_prio=0 cpu=2413976.54ms elapsed=2426.87s allocated=138G defined_classes=472 tid=0x0000ffff30037920 nid=3093189 runnable [0x0000ffff3444d000] java.lang.Thread.State: RUNNABLE Thread: 0x0000ffff30037920 [0x2f32c5] State: _at_safepoint _at_poll_safepoint 1 JavaThread state: _thread_blocked at sun.jvm.hotspot.types.basic.BasicTypeDataBase.findDynamicTypeForAddress(jdk.hotspot.agent@19-ea/BasicTypeDataBase.java:272) at sun.jvm.hotspot.runtime.VirtualBaseConstructor.instantiateWrapperFor(jdk.hotspot.agent@19-ea/VirtualBaseConstructor.java:104) at sun.jvm.hotspot.utilities.GrowableArray.at(jdk.hotspot.agent@19-ea/GrowableArray.java:63) at sun.jvm.hotspot.code.CodeCache.findBlobUnsafe(jdk.hotspot.agent@19-ea/CodeCache.java:105) at sun.jvm.hotspot.runtime.VFrame.newVFrame(jdk.hotspot.agent@19-ea/VFrame.java:61) at sun.jvm.hotspot.runtime.VFrame.sender(jdk.hotspot.agent@19-ea/VFrame.java:126) at sun.jvm.hotspot.runtime.VFrame.javaSender(jdk.hotspot.agent@19-ea/VFrame.java:148) at sun.jvm.hotspot.runtime.ThreadStackTrace.dumpStack(jdk.hotspot.agent@19-ea/ThreadStackTrace.java:53) at sun.jvm.hotspot.utilities.HeapHprofBinWriter.dumpStackTraces(jdk.hotspot.agent@19-ea/HeapHprofBinWriter.java:835) at sun.jvm.hotspot.utilities.HeapHprofBinWriter.write(jdk.hotspot.agent@19-ea/HeapHprofBinWriter.java:461) - locked <0x00000000d010dd50> (a sun.jvm.hotspot.utilities.HeapHprofBinWriter) at sun.jvm.hotspot.tools.JMap.writeHeapHprofBin(jdk.hotspot.agent@19-ea/JMap.java:216) at sun.jvm.hotspot.tools.JMap.run(jdk.hotspot.agent@19-ea/JMap.java:103) at sun.jvm.hotspot.tools.Tool.startInternal(jdk.hotspot.agent@19-ea/Tool.java:278) at sun.jvm.hotspot.tools.Tool.start(jdk.hotspot.agent@19-ea/Tool.java:241) at sun.jvm.hotspot.tools.Tool.execute(jdk.hotspot.agent@19-ea/Tool.java:134) at sun.jvm.hotspot.tools.JMap.main(jdk.hotspot.agent@19-ea/JMap.java:202) at sun.jvm.hotspot.SALauncher.runJMAP(jdk.hotspot.agent@19-ea/SALauncher.java:340) at sun.jvm.hotspot.SALauncher$$Lambda$4/0x0000000801003000.accept(jdk.hotspot.agent@19-ea/Unknown Source) at sun.jvm.hotspot.SALauncher.main(jdk.hotspot.agent@19-ea/SALauncher.java:500) Stack traces taken at different times show different frames in the main thread, but they are all the same from sun.jvm.hotspot.runtime.VFrame.sender() and below, so it looks like it is stuck in some loop walking the frames of a thread . This is something that was more problematic in the past, but has been mostly eliminated by adding more safeguards. However, this is still a known issue with the linux-aarch64 port. For example, see JDK-8248675, which is linux-aarch64 specific. However we also have JDK-8247641, which calls out this specific tests as having "multiple undetected failure modes", and this might just be one of the failures coming to the surface. I think the 134 exit code is just because the process timed out and was forced to core dump by the test infra. So I'm closing this as a dup of JDK-8247641.
10-12-2021