8299777: Test runtime/NMT/BaselineWithParameter.java timed out

[stefank]

I found this issue while debugging a hang in runtime/NMT/JcmdSummaryClass.java. We have the same issue in a few other NMT tests, and the BaselineWithParameter.java is one of them.

The common pattern among these tests is that they have one main process that forks a jcmd process against itself. The forked jcmd process writes its output to stdout (and maybe stderr). The problematic part of these tests is that the main process doesn't drain the streams of the forked jcmd before it calls waitFor(). This usually works and the tests passes, and I guess that's because there's some internal buffer that the jcmd process can write to without blocking. However, if too much data gets written the process gets blocked and the test times out. I can reproduce this by artificially adding more output to the NMT jcmd with the following patch

diff --git a/src/hotspot/share/services/nmtDCmd.cpp b/src/hotspot/share/services/nmtDCmd.cpp
index f64c65c2dc8..42dbe6c1ae2 100644
--- a/src/hotspot/share/services/nmtDCmd.cpp
+++ b/src/hotspot/share/services/nmtDCmd.cpp
@@ -108,6 +108,11 @@ void NMTDCmd::execute(DCmdSource source, TRAPS) {
   // Serialize NMT query
   MutexLocker locker(THREAD, MemTracker::query_lock());
 
+  // Fill up the output
+  for (int i = 0; i < 8 * 1024; i++) {
+    output()->print_cr("Fake line: %d", i);
+  }
+
   if (_summary.value()) {
     report(true, scale_unit);
   } else if (_detail.value()) {

This is the problematic test pattern:

// Set up command line
pb.command(new String[] { JDKToolFinder.getJDKTool("jcmd"), pid, "VM.native_memory"});

// Test hangs here waiting for the jcmd process to finish,
// which it won't because nothing accepts its written output.
pb.start().waitFor();

// Verify the output - (secondary bug here, see comments below)
output = new OutputAnalyzer(pb.start());

The correct way to write these tests is simply to remove the waitFor call and let the OutputAnalyzer deal with waiting for the forked process to finish:

// Set up command line
pb.command(new String[] { JDKToolFinder.getJDKTool("jcmd"), pid, "VM.native_memory"});

// Start the process and verify the output
output = new OutputAnalyzer(pb.start());

The secondary problem with this tests is that they forks the jcmd process twice, via two calls to pb.start(). This isn't causing the hangs, but we shouldn't be doing that.

I've tested this fix by running the tests in runtime/NMT with and without the nmtDcmd.cpp patch above.

---

Progress

• Change must be properly reviewed (1 review required, with at least 1 Reviewer)
• Change must not contain extraneous whitespace
• Commit message must refer to an issue

Issue

• JDK-8299777: Test runtime/NMT/BaselineWithParameter.java timed out

Reviewers

• Gerard Ziemski (@gerard-ziemski - Committer)
• Ioi Lam (@iklam - Reviewer)
• David Holmes (@dholmes-ora - Reviewer)

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.org/jdk pull/12663/head:pull/12663
$ git checkout pull/12663

Update a local copy of the PR:
$ git checkout pull/12663
$ git pull https://git.openjdk.org/jdk pull/12663/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 12663

View PR using the GUI difftool:
$ git pr show -t 12663

Using diff file

Download this PR as a diff file:
https://git.openjdk.org/jdk/pull/12663.diff

[bridgekeeper]

👋 Welcome back stefank! A progress list of the required criteria for merging this PR into master will be added to the body of your pull request. There are additional pull request commands available for use with this pull request.

[openjdk]

@stefank The following label will be automatically applied to this pull request:

• hotspot-runtime

When this pull request is ready to be reviewed, an "RFR" email will be sent to the corresponding mailing list. If you would like to change these labels, use the /label pull request command.

[mlbridge]

Webrevs

• 00: Full (519bffff)

[gerard-ziemski]

Thank you so much for finding and fixing this!

I have a list of hanging tests, which I will need to check now to see if they follow the same bad usage pattern - see https://bugs.openjdk.org/browse/JDK-8299555

[iklam]

LGTM

[openjdk]

@stefank This change now passes all automated pre-integration checks.

ℹ️ This project also has non-automated pre-integration requirements. Please see the file CONTRIBUTING.md for details.

After integration, the commit message for the final commit will be:

8299777: Test runtime/NMT/BaselineWithParameter.java timed out

Reviewed-by: gziemski, iklam, dholmes

You can use pull request commands such as /summary, /contributor and /issue to adjust it as needed.

At the time when this comment was updated there had been 9 new commits pushed to the master branch:

• 36a0822: 8302369: Reduce the stack size of the C1 compiler
• 0bf3a53: 8302599: Extend ASan support to Microsoft Visual C++
• c7517b3: 8302525: Write a test to check various components send Events while mouse and key are used simultaneously
• 9a79722: 8299234: JMX Repository.query performance
• e47e9ec: 8300658: memory_and_swap_limit() reporting wrong values on systems with swapaccount=0
• 7cf7e0a: 8302070: Factor null-check into load_klass() calls
• e731695: 8302882: Newly added test javax/swing/JFileChooser/JFileChooserFontReset.java fails with HeadlessException
• b5a7426: 8301749: Tracking malloc pooled memory size
• 6ac5e05: 8302068: Serial: Refactor oop closures used in Young GC

Please see this link for an up-to-date comparison between the source branch of this pull request and the master branch.
As there are no conflicts, your changes will automatically be rebased on top of these commits when integrating. If you prefer to avoid this automatic rebasing, please check the documentation for the /integrate command for further details.

➡️ To integrate this PR with the above commit message to the master branch, type /integrate in a new comment.

[dholmes-ora]

Fixup looks good. Good catch.

Thanks.

[stefank]

Thanks for the reviews!
/integrate

[openjdk]

Going to push as commit fef1910.
Since your change was applied there have been 21 commits pushed to the master branch:

• 622f560: 8302886: Parallel: Remove unimplemented methods in ParCompactionManager
• 9fd77c7: 8302868: Serial: Remove CardTableRS::initialize
• f35cf79: 8302867: G1: Removing unused variable in G1CardTable::initialize
• 63a3501: 8302741: ZGC: Remove Universe::verify calls
• 9145670: 8301661: Enhance os::pd_print_cpu_info on macOS and Windows
• aa10f0d: 8302151: BMPImageReader throws an exception reading BMP images
• 16a4f02: 8302150: Speed up compiler/codegen/Test7100757.java
• 17274c7: 8302146: Move TestOverloadCompileQueues.java to tier3
• 29f392e: 8299522: Incorrect size of Approve button in custom JFileChooser
• 43c71dd: 8302453: RISC-V: Add support for small width vector operations
• ... and 11 more: https://git.openjdk.org/jdk/compare/71cf7c4409025c87ac786a54171f00de69fe5317...master

Your commit was automatically rebased without conflicts.

[openjdk]

@stefank Pushed as commit fef1910.

💡 You may see a message that your pull request was closed with unmerged commits. This can be safely ignored.