When running our CI tests we have a failure handler registered that will try to
capture the state of the process when we hit a timeout. It is important to get
thread dumps when the process hangs, and to make sure that we get one as fast
as possible we have recently updated the failure handler to start by taking an
initial Java thread dump.
That all works well for Java-level deadlocks and hangs. However, it doesn't
work well when it is the JVM that is hanging. When that happens, the requested
Java thread dump will likely be blocked and time out.
We have two distinct scenarios:
1) The JVM is truly deadlocked trying to reach a global safepoint, or there's a
deadlock inside a safepoint operation.
jstack and many jcmd actions will hang and time out, one at a time. This takes
minutes and after that we will proceed to use the native tools to inspect the
process and dump native stack traces. This scenario is "fine" in the sense that
we probably will get to the native dumping of stack traces eventually.
2) The JVM is not deadlocked, but something is either taking a very long time
to reach a safepoint, or there's a safepoint operation that is taking a very
long time, like a problematic GC verification pass.
In situations like this, the thread dumping and other jcmds will also hang and
time out, one at a time, until the long operation completes and the test can
continue to run. When that happens, a few of the jcmds could complete, the test
could also complete, and the process could move on and exit. If this happens,
the failure handler doesn't get to the native stack trace dumping, which is
crucial when debugging JVM hangs.
My proposal is that we make a slight adjustment to the test failure handler and
make it so that it starts the process inspection by taking one native thread
dump, before it moves on to take the Java thread dump.
It's worth noting that the JVM process is frozen when we take the native thread
dump, so the Java code is not running ahead while it is performed. This should
minimize the risk that we'll miss important information in the Java thread
dump. This is in contrast to the situation we have when we take the Java thread
dump, where the JVM can continue running up until the thread dump safepoint
operation, and some threads will even run non-Java code concurrently with the
Java thread dumper.
After this change the processes.html shows something like this:
- test_processes
- 5337
- initial-native-stack
<The initial native thread stack dump>
- common
- thread_dump
<The Java thread dump>
- jinfo
- jcmd
- ...
- mac
- ...
- stack
- iteration_0
<Native thread stack dump>
- iteration_1
- ...
- ...
The `sectionPathOverride` part of the patch makes it so that the we don't get
something simlar to this:
- 5337
- mac-initial-native-stack
- stack
- iteration_0
<The initial native thread stack dump>
- ...
Testing of this has been manually triggering timeouts on Linux, Mac, and
Windows.
---------
- [x] I confirm that I make this contribution in accordance with the [OpenJDK
Interim AI Policy](https://openjdk.org/legal/ai).
-------------
Commit messages:
- 8395909: Make the test failure_handler take an early native thread stack dump
Changes: https://git.openjdk.org/jdk/pull/33591/files
Webrev: https://webrevs.openjdk.org/?repo=jdk&pr=33591&range=00
Issue: https://bugs.openjdk.org/browse/JDK-8395909
Stats: 155 lines in 5 files changed: 152 ins; 0 del; 3 mod
Patch: https://git.openjdk.org/jdk/pull/33591.diff
Fetch: git fetch https://git.openjdk.org/jdk.git pull/33591/head:pull/33591
PR: https://git.openjdk.org/jdk/pull/33591
