JDK-8299777 : Test runtime/NMT/BaselineWithParameter.java timed out
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 21
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • OS: windows
  • CPU: x86_64
  • Submitted: 2023-01-08
  • Updated: 2023-03-01
  • Resolved: 2023-02-21
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.
JDK 21
21 b11Fixed
Related Reports
Relates :  
JDK-8286345 - runtime/NMT/ThreadedMallocTestType.java failed with java.lang.RuntimeException, we also see "exitValue = 134" and time out
Relates :  
JDK-8010084 - Race in runtime/NMT/BaselineWithParameter.java
Description
Nothing to go on:

----------messages:(9/503)----------
command: main -XX:NativeMemoryTracking=detail BaselineWithParameter
reason: User specified action: run main/othervm -XX:NativeMemoryTracking=detail BaselineWithParameter 
started: Fri Jan 06 05:21:12 UTC 2023
Mode: othervm [/othervm specified]
Additional options from @modules: --add-modules java.base,java.management --add-exports java.base/jdk.internal.misc=ALL-UNNAMED
Timeout information:
--- Timeout information end.
finished: Fri Jan 06 05:48:08 UTC 2023
elapsed time (seconds): 1616.121
----------configuration:(4/115)----------
Boot Layer
  add modules: java.base java.management   
  add exports: java.base/jdk.internal.misc ALL-UNNAMED

----------System.out:(1/28)----------
Timeout refired 1200 times
----------System.err:(0/0)----------
Comments
So I had to dig further into this, and back in JDK 8 / hsx25 the OutputAnalyzer only processed the actual output of the process: https://hg.openjdk.org/hsx/hsx25/hotspot/file/a649f6511c04/test/testlibrary/com/oracle/java/testlibrary/OutputAnalyzer.java It requires that the Process passed to the constructor has already terminated. The issue that introduced the p.start.waitFor() was simply that the test had to wait for the baseline to be taken before requesting the summary - it had nothing to do with checking any output and no use of OutputAnalyzer was involved. The flaw with that is that unless something consumes the process output it can block - hence this issue and the fix.
22-02-2023
[~dholmes] Right. That was my understanding as well, but your earlier comment got me worried that I had missed something. Thanks.
22-02-2023
[~stefank] These days at least, OutputAnalyzer implicitly ensures the process has terminated. If you check the process output then that operation only completes when the stream pumper terminates, which means the process output has ceased and the process terminated. If you check the return value then an explicit waitFor is issued.
21-02-2023
Changeset: fef19102 Author: Stefan Karlsson <stefank@openjdk.org> Date: 2023-02-21 10:58:36 +0000 URL: https://git.openjdk.org/jdk/commit/fef1910277842303b41854c207fc4caba393adc6
21-02-2023
[~dholmes] I wonder if the issue the waitFor tried to solve was that we reused the ProcessBuilder, while the first forked process were not completely shut down. Maybe we shouldn't be reusing ProcessBuilder instances, or we need to add back the waitFor() calls *after* the usage of the OutputAnalyzer? Update: According to the documentation of ProcessBuilder.start(): "Subsequent modifications to this process builder will not affect the returned Process."
21-02-2023
BTW the waitFor() was explicitly added by this issue: JDK-8010084. I wonder if OutputAnalyzer behaved differently back then?
20-02-2023
A pull request was submitted for review. URL: https://git.openjdk.org/jdk/pull/12663 Date: 2023-02-20 13:46:46 +0000
20-02-2023
I think I know what the problem is with these NMT tests. The test forks a process and then waits for it to finish without draining the streams. The forked process then hangs when it writes to stdout/stderr because the main thread doesn't read the written data. I think this often works, because the forked process writes so little that it fits in some kind of out buffer. If I artificially increase the written data I can reproduce this hang. Adding more data to the NMT jcmd: ``` 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()) { ```
20-02-2023