JDK-8247641 : HeapDumpTestWithActiveProcess.java has multiple undetected failure modes
  • Type: Bug
  • Component: hotspot
  • Sub-Component: svc-agent
  • Affected Version: 16,19,22
  • Priority: P4
  • Status: Open
  • Resolution: Unresolved
  • Submitted: 2020-06-15
  • Updated: 2023-10-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.
Other
tbdUnresolved
Related Reports
Duplicate :  
Relates :  
Relates :  
Relates :  
Relates :  
Description
HeapDumpTestWithActiveProcess.java is the only test we have that tries doing stack walking with an application that is still in the process of starting up. Because of this it detects a lot of bugs in SA bug due to threads being in bad states. JDK-8244383 is one such example, causing failures with "illegal bci". While addressing JDK-8244383 I added some improved error checking to the test, similar to those in ClhsdbLauncher:

            // This will detect most SA failures, including during the attach.
            output.shouldNotMatch("sun.jvm.hotspot.debugger.DebuggerException:.*$");
            // This will detect unexpected exceptions, like NPEs and asserts, that are caught
            // by sun.jvm.hotspot.CommandProcessor.
            output.shouldNotMatch("^Error: .*$");

In addition I fixed some places in SA that generate the "Error" message, but don't always ensure that it starts on a new line, which it frequently does not:

diff --git a/src/jdk.hotspot.agent/share/classes/sun/jvm/hotspot/runtime/ThreadStackTrace.java b/src/jdk.hotspot.agent/share/classes/sun/jvm/hotspot/runtime/ThreadStackTrace.java
--- a/src/jdk.hotspot.agent/share/classes/sun/jvm/hotspot/runtime/ThreadStackTrace.java
+++ b/src/jdk.hotspot.agent/share/classes/sun/jvm/hotspot/runtime/ThreadStackTrace.java
@@ -62,7 +62,7 @@
                 }
             }
         } catch (Exception e) {
-            System.out.println("Error occurred during stack walking:");
+            System.err.println("\nError: exception occurred during stack walking:");
             e.printStackTrace();
         }
     }

diff --git a/src/jdk.hotspot.agent/share/classes/sun/jvm/hotspot/tools/StackTrace.java b/src/jdk.hotspot.agent/share/classes/sun/jvm/hotspot/tools/StackTrace.java
--- a/src/jdk.hotspot.agent/share/classes/sun/jvm/hotspot/tools/StackTrace.java
+++ b/src/jdk.hotspot.agent/share/classes/sun/jvm/hotspot/tools/StackTrace.java
@@ -114,7 +114,7 @@
                             vf.printLockInfo(tty, count++);
                         }
                     } catch (Exception e) {
-                        tty.println("Error occurred during stack walking:");
+                        tty.println("\nError: Exception occurred during stack walking:");
                         e.printStackTrace();
                     }
                     tty.println();

With these changes in place, I started to see a lot more failures being detected by the test. One is JDK-8247533, which is being addressed. However, there are others that do not have separate bugs filed for them. I will list them below in separate comments.
Comments
There is a graal related failure with: sun.jvm.hotspot.utilities.AssertionFailure: illegal bci(-3) codeSize(158) (and the same stack as a failure above with "illegal bci(-916200056)"). If bci == -3 has some special meaning, that's likely a different issue to this collection of failures (and the more random-looking bci rerported here). There is also: https://bugs.openjdk.org/browse/JDK-8204209 Summary: Tolerate JVMCI placeholder bcis So we should have a similar issue for the SA, so asserts such as the one in ConstMethod.java tolerate bci down to -6.
03-10-2023

Moved here from JDK-8274421: Daniel Daugherty added a comment - 2023-09-21 11:59 Here's a log file snippet from the jdk-22+16-1248-tier5 sighting: sun/tools/jhsdb/HeapDumpTestWithActiveProcess.java #section:main ----------messages:(7/367)---------- command: main JShellHeapDumpTest nosleep reason: User specified action: run main/timeout=240 JShellHeapDumpTest nosleep started: Thu Sep 21 10:21:02 UTC 2023 Mode: othervm [test requires non-default system module] Additional options from @modules: --add-modules jdk.hotspot.agent,java.management finished: Thu Sep 21 10:21:16 UTC 2023 elapsed time (seconds): 13.714 ----------configuration:(3/61)---------- Boot Layer add modules: jdk.hotspot.agent java.management ----------System.out:(42/3118)---------- Starting Jshell [JShell]:/opt/mach5/mesos/work_dir/jib-master/install/jdk-22+16-1248/linux-x64-debug.jdk/jdk-22/fastdebug/bin/jshell -J-Xmx768m -J-XX:MaxRAMPercentage=4.16667 -J-Dtest.boot.jdk=/opt/mach5/mesos/work_dir/jib-master/install/jdk/20/36/bundles/linux-x64/jdk-20_linux-x64_bin.tar.gz/jdk-20 -J-Djava.io.tmpdir=/opt/mach5/mesos/work_dir/slaves/cd627e65-f015-4fb1-a1d2-b6c9b8127f98-S183077/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/6a34a06f-6a2a-4cef-9b77-a212ac6266de/runs/d5704209-7f2c-4b51-bb6f-17a64a963afa/testoutput/test-support/jtreg_open_test_jdk_svc_tools/tmp -J-ea -J-esa -J-Duser.language=en -J-Duser.country=US [JShell] | Welcome to JShell -- Version 22-ea [JShell] | For an introduction type: /help intro Jshell Started in 5300ms Starting jmap against 1638475 [2023-09-21T10:21:08.597848856Z] Gathering output for process 1638989 [2023-09-21T10:21:15.943268709Z] Waiting for completion for process 1638989 [2023-09-21T10:21:15.943539473Z] Waiting for completion finished for process 1638989 Output and diagnostic info for process 1638989 was saved into 'pid-1638989-output.log' jhsdb jmap stdout: Attaching to process ID 1638475, please wait... Debugger attached successfully. Server compiler detected. JVM version is 22-ea+16-1248 jhsdb jmap stderr: sun.jvm.hotspot.utilities.AssertionFailure: illegal bci(-916200056) codeSize(15) at jdk.hotspot.agent/sun.jvm.hotspot.utilities.Assert.that(Assert.java:32) at jdk.hotspot.agent/sun.jvm.hotspot.oops.ConstMethod.getLineNumberFromBCI(ConstMethod.java:321) at jdk.hotspot.agent/sun.jvm.hotspot.oops.Method.getLineNumberFromBCI(Method.java:287) at jdk.hotspot.agent/sun.jvm.hotspot.utilities.HeapHprofBinWriter.dumpStackFrame(HeapHprofBinWriter.java:867) at jdk.hotspot.agent/sun.jvm.hotspot.utilities.HeapHprofBinWriter.dumpStackTraces(HeapHprofBinWriter.java:846) at jdk.hotspot.agent/sun.jvm.hotspot.utilities.HeapHprofBinWriter.write(HeapHprofBinWriter.java:460) at jdk.hotspot.agent/sun.jvm.hotspot.tools.JMap.writeHeapHprofBin(JMap.java:216) at jdk.hotspot.agent/sun.jvm.hotspot.tools.JMap.run(JMap.java:103) at jdk.hotspot.agent/sun.jvm.hotspot.tools.Tool.startInternal(Tool.java:278) at jdk.hotspot.agent/sun.jvm.hotspot.tools.Tool.start(Tool.java:241) at jdk.hotspot.agent/sun.jvm.hotspot.tools.Tool.execute(Tool.java:134) at jdk.hotspot.agent/sun.jvm.hotspot.tools.JMap.main(JMap.java:202) at jdk.hotspot.agent/sun.jvm.hotspot.SALauncher.runJMAP(SALauncher.java:340) at jdk.hotspot.agent/sun.jvm.hotspot.SALauncher.main(SALauncher.java:500) ###### End of all output which took 7385ms [2023-09-21T10:21:15.958302750Z] Waiting for completion for process 1638989 [2023-09-21T10:21:15.960886400Z] Waiting for completion finished for process 1638989 [2023-09-21T10:21:15.961211586Z] Waiting for completion for process 1638989 [2023-09-21T10:21:15.961365368Z] Waiting for completion finished for process 1638989 [2023-09-21T10:21:15.980454799Z] Waiting for completion for process 1638989 [2023-09-21T10:21:15.980617447Z] Waiting for completion finished for process 1638989 Destroying jshell Jshell destroyed ----------System.err:(41/2706)---------- stdout: [Attaching to process ID 1638475, please wait... Debugger attached successfully. Server compiler detected. JVM version is 22-ea+16-1248 ]; stderr: [sun.jvm.hotspot.utilities.AssertionFailure: illegal bci(-916200056) codeSize(15) at jdk.hotspot.agent/sun.jvm.hotspot.utilities.Assert.that(Assert.java:32) at jdk.hotspot.agent/sun.jvm.hotspot.oops.ConstMethod.getLineNumberFromBCI(ConstMethod.java:321) at jdk.hotspot.agent/sun.jvm.hotspot.oops.Method.getLineNumberFromBCI(Method.java:287) at jdk.hotspot.agent/sun.jvm.hotspot.utilities.HeapHprofBinWriter.dumpStackFrame(HeapHprofBinWriter.java:867) at jdk.hotspot.agent/sun.jvm.hotspot.utilities.HeapHprofBinWriter.dumpStackTraces(HeapHprofBinWriter.java:846) at jdk.hotspot.agent/sun.jvm.hotspot.utilities.HeapHprofBinWriter.write(HeapHprofBinWriter.java:460) at jdk.hotspot.agent/sun.jvm.hotspot.tools.JMap.writeHeapHprofBin(JMap.java:216) at jdk.hotspot.agent/sun.jvm.hotspot.tools.JMap.run(JMap.java:103) at jdk.hotspot.agent/sun.jvm.hotspot.tools.Tool.startInternal(Tool.java:278) at jdk.hotspot.agent/sun.jvm.hotspot.tools.Tool.start(Tool.java:241) at jdk.hotspot.agent/sun.jvm.hotspot.tools.Tool.execute(Tool.java:134) at jdk.hotspot.agent/sun.jvm.hotspot.tools.JMap.main(JMap.java:202) at jdk.hotspot.agent/sun.jvm.hotspot.SALauncher.runJMAP(SALauncher.java:340) at jdk.hotspot.agent/sun.jvm.hotspot.SALauncher.main(SALauncher.java:500) ] exitValue = 1 java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: Expected to get exit value of [0], exit value is: [1] at JShellHeapDumpTest.launch(JShellHeapDumpTest.java:84) at JShellHeapDumpTest.launch(JShellHeapDumpTest.java:99) at JShellHeapDumpTest.testHeapDump(JShellHeapDumpTest.java:135) at JShellHeapDumpTest.main(JShellHeapDumpTest.java:196) at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) at java.base/java.lang.reflect.Method.invoke(Method.java:580) at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138) at java.base/java.lang.Thread.run(Thread.java:1570) Caused by: java.lang.RuntimeException: Expected to get exit value of [0], exit value is: [1] at jdk.test.lib.process.OutputAnalyzer.shouldHaveExitValue(OutputAnalyzer.java:490) at JShellHeapDumpTest.launch(JShellHeapDumpTest.java:82) ... 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: [1] 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: [1] ----------rerun:(38/7027)*----------
22-09-2023

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
10-12-2021

sun/tools/jhsdb/HeapDumpTestWithActiveProcess.java failed on linux-aarch64 due to getting stuck walking the stack during the heap dump. See JDK-8278558 for details.
10-12-2021

I ran into any instance of the above newWrongTypeException, but this one did not dump any frames first: "main" #1 prio=5 tid=0x0000020b164d2a60 nid=0x22e4 runnable [0x0000004f233fe000] java.lang.Thread.State: RUNNABLE JavaThread state: _thread_in_java CurrentFrameGuess: choosing last Java frame: sp = 0x0000004f233fefa8, fp = 0x0000004f233fefc8 That means it did not go through X86Frame.sender(). Here's the code in StackTrace.run(): JavaThread cur = threads.getJavaThreadAt(i); if (cur.isJavaThread()) { cur.printThreadInfoOn(tty); try { int count = 0; for (JavaVFrame vf = cur.getLastJavaVFrameDbg(); vf != null; vf = vf.javaSender()) { Method method = vf.getMethod(); Following getLastJavaVFrameDbg() and ending up in AMD64CurrentFrameGuess.run(), the above message in the output (I had enabled DEBUG logging) indicates that the frame was derived using thread.getLastJavaSP() and thread.getLastJavaFP(): setValues(thread.getLastJavaSP(), thread.getLastJavaFP(), null); And later on when the X86Frame is created it gets the pc using: this.pc = raw_sp.getAddressAt(-1 * VM.getVM().getAddressSize()); So it must have fetched an interpreter pc, yet the Method in the frame is not valid. This may be similar to JDK-8244383, for which I have a fix in place that is resolving most issues, but the path taken here avoids any of the fixes I've put in AMD64CurrentFrameGuess. When you see the "choosing last Java frame" message with no others before it, that means either sp == null or pc is not a java pc. We then rely on the sp and fp from the hotspot set_last_java_frame() call (I'm not sure why we don't also look at pc). I wonder if the thread is just in some sort of inconsistent state w.r.t. calls to set/reset_last_Java_frame. Maybe last_java_frame is no longer valid, but hasn't been reset yet. We should also consider using the pc when not null in the following AMD64CurrentFrameGuess code: setValues(thread.getLastJavaSP(), thread.getLastJavaFP(), null); So replace the null pc with thread.getLastJavaPC().
16-06-2020

With this failure it looks like X86Frame.sender() managed not to assert, but it resulted in returning an invalid InterpretedVFrame: Error: Exception occurred during stack walking: sun.jvm.hotspot.types.WrongTypeException: No suitable match for type of address 0x000000070a41c928 at jdk.hotspot.agent/sun.jvm.hotspot.runtime.InstanceConstructor.newWrongTypeException(InstanceConstructor.java:62) at jdk.hotspot.agent/sun.jvm.hotspot.runtime.VirtualBaseConstructor.instantiateWrapperFor(VirtualBaseConstructor.java:111) at jdk.hotspot.agent/sun.jvm.hotspot.oops.Metadata.instantiateWrapperFor(Metadata.java:76) at jdk.hotspot.agent/sun.jvm.hotspot.runtime.Frame.getInterpreterFrameMethod(Frame.java:371) at jdk.hotspot.agent/sun.jvm.hotspot.runtime.InterpretedVFrame.getMethod(InterpretedVFrame.java:36) at jdk.hotspot.agent/sun.jvm.hotspot.tools.StackTrace.run(StackTrace.java:82) at jdk.hotspot.agent/sun.jvm.hotspot.tools.StackTrace.run(StackTrace.java:45) at jdk.hotspot.agent/sun.jvm.hotspot.tools.JStack.run(JStack.java:67) at jdk.hotspot.agent/sun.jvm.hotspot.utilities.HeapHprofBinWriter.dumpStackTraces(HeapHprofBinWriter.java:711) at jdk.hotspot.agent/sun.jvm.hotspot.utilities.HeapHprofBinWriter.write(HeapHprofBinWriter.java:440) at jdk.hotspot.agent/sun.jvm.hotspot.tools.JMap.writeHeapHprofBin(JMap.java:182) at jdk.hotspot.agent/sun.jvm.hotspot.tools.JMap.run(JMap.java:97) at jdk.hotspot.agent/sun.jvm.hotspot.tools.Tool.startInternal(Tool.java:262) at jdk.hotspot.agent/sun.jvm.hotspot.tools.Tool.start(Tool.java:225) at jdk.hotspot.agent/sun.jvm.hotspot.tools.Tool.execute(Tool.java:118) at jdk.hotspot.agent/sun.jvm.hotspot.tools.JMap.main(JMap.java:176) at jdk.hotspot.agent/sun.jvm.hotspot.SALauncher.runJMAP(SALauncher.java:331) at jdk.hotspot.agent/sun.jvm.hotspot.SALauncher.main(SALauncher.java:483) "main" #1 prio=5 tid=0x00007febf8801020 nid=0x1a03 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE JavaThread state: _thread_in_java CurrentFrameGuess: frame <= oldFrame: sp: 0x0000000104d8ce68, unextendedSP: 0x0000000104d8ce68, fp: 0x0000000000000001, pc: 0x000000070a41c928 CurrentFrameGuess: Choosing sp = 0x0000000104d8cd70, pc = 0x00000001179ca9e7 - java.nio.ByteBuffer.position(int) @bci=0, line=1369 (Compiled frame; information may be imprecise)
16-06-2020

Failures are most common on OSX for some reason. Here's an example. There are other asserts and also NPEs that can happen, but they all seem to filter through X86Frame.sender() and seem to be related to threads in a compiler frame: Error: Exception occurred during stack walking: sun.jvm.hotspot.utilities.AssertionFailure: sanity check at jdk.hotspot.agent/sun.jvm.hotspot.utilities.Assert.that(Assert.java:32) at jdk.hotspot.agent/sun.jvm.hotspot.runtime.RegisterMap.setLocation(RegisterMap.java:160) at jdk.hotspot.agent/sun.jvm.hotspot.compiler.ImmutableOopMapSet.updateRegisterMap(ImmutableOopMapSet.java:303) at jdk.hotspot.agent/sun.jvm.hotspot.runtime.x86.X86Frame.senderForCompiledFrame(X86Frame.java:401) at jdk.hotspot.agent/sun.jvm.hotspot.runtime.x86.X86Frame.sender(X86Frame.java:292) at jdk.hotspot.agent/sun.jvm.hotspot.runtime.Frame.sender(Frame.java:207) at jdk.hotspot.agent/sun.jvm.hotspot.runtime.Frame.realSender(Frame.java:212) at jdk.hotspot.agent/sun.jvm.hotspot.runtime.VFrame.sender(VFrame.java:119) at jdk.hotspot.agent/sun.jvm.hotspot.runtime.CompiledVFrame.sender(CompiledVFrame.java:185) at jdk.hotspot.agent/sun.jvm.hotspot.runtime.VFrame.javaSender(VFrame.java:143) at jdk.hotspot.agent/sun.jvm.hotspot.tools.StackTrace.run(StackTrace.java:81) at jdk.hotspot.agent/sun.jvm.hotspot.tools.StackTrace.run(StackTrace.java:45) at jdk.hotspot.agent/sun.jvm.hotspot.tools.JStack.run(JStack.java:67) at jdk.hotspot.agent/sun.jvm.hotspot.utilities.HeapHprofBinWriter.dumpStackTraces(HeapHprofBinWriter.java:711) at jdk.hotspot.agent/sun.jvm.hotspot.utilities.HeapHprofBinWriter.write(HeapHprofBinWriter.java:440) at jdk.hotspot.agent/sun.jvm.hotspot.tools.JMap.writeHeapHprofBin(JMap.java:182) at jdk.hotspot.agent/sun.jvm.hotspot.tools.JMap.run(JMap.java:97) at jdk.hotspot.agent/sun.jvm.hotspot.tools.Tool.startInternal(Tool.java:262) at jdk.hotspot.agent/sun.jvm.hotspot.tools.Tool.start(Tool.java:225) at jdk.hotspot.agent/sun.jvm.hotspot.tools.Tool.execute(Tool.java:118) at jdk.hotspot.agent/sun.jvm.hotspot.tools.JMap.main(JMap.java:176) at jdk.hotspot.agent/sun.jvm.hotspot.SALauncher.runJMAP(SALauncher.java:331) at jdk.hotspot.agent/sun.jvm.hotspot.SALauncher.main(SALauncher.java:483) Note jstack output when the above happens looks like: "Thread-1" #23 daemon prio=5 tid=0x00007fb3a18b0e20 nid=0x8a03 waiting on condition [0x000070000b59d000] java.lang.Thread.State: RUNNABLE JavaThread state: _thread_blocked CurrentFrameGuess: choosing last Java frame: sp = 0x000070000b59da90, fp = 0x000070000b59df00 - java.util.HashSet.<init>(int, float, boolean) @bci=5, line=163 (Compiled frame) - java.util.LinkedHashSet.<init>() @bci=6, line=155 (Compiled frame) - jdk.jshell.SourceCodeAnalysisImpl.lambda$addClassName2Map$63(java.lang.String) @bci=4, line=1832 (Compiled frame) - jdk.jshell.SourceCodeAnalysisImpl$$Lambda$335+0x0000000800d47d40.apply(java.lang.Object) @bci=4 (Compiled frame) - java.util.HashMap.computeIfAbsent(java.lang.Object, java.util.function.Function) @bci=202, line=1224 (Compiled frame) Getting this output requires the following at the start of HeapHprofBinWriter.dumpStackTraces(): JStack jstack = new JStack(false, true); jstack.run();
15-06-2020