8321718: ProcessTools.executeProcess calls waitFor before logging

[stefank]

There is some logging printed when tests spawns processes. This logging is triggered from calls to OutputAnalyzer, when it delegates calls to LazyOutputBuffer.

If we write code like this:

ProcessBuilder pb = ProcessTools.createTestJavaProcessBuilder(...);
OutputAnalyzer output = new OutputAnalyzer(pb.start());
int exitValue = output.getExitValue();

We get the following logging:

[timestamp0] "Gathering output for process <pid>
[timestamp1] Waiting for completion for process <pid>
[timestamp2] Waiting for completion finished for process <pid>

The first line comes from the OutputAnalyzer constructor and the two other lines comes from the getExitValue call, which calls logs the above messages around the call to waitFor.

If instead write the code above as:

ProcessBuilder pb = ProcessTools.createTestJavaProcessBuilder(...);
OutputAnalyzer output = ProcessTools.executeProcess(pb);
int exitValue = output.getExitValue();

We get the same logging, but timestamp1 and timestamp2 are almost the same. This happens because there's an extra call to waitFor inside executeProcess, but that waitFor does not have the "wait for" logging. So, instead we get the logging for the no-op waitFor inside getExitValue.

I would like to propose a small workaround to solve this. The workaround is that executeProcess delegates the waitFor call to the LazyOutputBuffer via OutputAnalyzer. This is a small, limited workaround for this issue. Ideally I would like to extract the entire Process handling code out of LazyOutputBuffer and OutputAnalyzer, but the prototype for that rewrites all usages of new OutputAnalyzer(pb.start()) and stretches far and wide in the test directories, so I'm starting out with this suggestion.

We can see of this patch by looking at the timestamps generated from the included test. Without the proposed workaround:

Without

testExecuteProcessExit
[2023-12-11T11:05:41.854579260Z] Gathering output for process 2547719
[2023-12-11T11:05:44.018335073Z] Waiting for completion for process 2547719
[2023-12-11T11:05:44.018851972Z] Waiting for completion finished for process 2547719

testExecuteProcessStdout
[2023-12-11T11:05:44.049509860Z] Gathering output for process 2547741
[2023-12-11T11:05:46.227768897Z] Waiting for completion for process 2547741
[2023-12-11T11:05:46.228021173Z] Waiting for completion finished for process 2547741


testNewOutputAnalyzerExit
[2023-12-11T11:05:46.231475003Z] Gathering output for process 2547782
[2023-12-11T11:05:46.231972095Z] Waiting for completion for process 2547782
[2023-12-11T11:05:48.421324123Z] Waiting for completion finished for process 2547782

testNewOutputAnalyzerStdout
[2023-12-11T11:05:48.424801269Z] Gathering output for process 2547929

With the proposed workaround:

testExecuteProcessExit
[2023-12-11T11:06:12.203633363Z] Gathering output for process 2550961
[2023-12-11T11:06:12.285826294Z] Waiting for completion for process 2550961
[2023-12-11T11:06:14.361912745Z] Waiting for completion finished for process 2550961

testExecuteProcessStdout
[2023-12-11T11:06:14.398685794Z] Gathering output for process 2550982
[2023-12-11T11:06:14.399518617Z] Waiting for completion for process 2550982
[2023-12-11T11:06:16.595986889Z] Waiting for completion finished for process 2550982

testNewOutputAnalyzerExit
[2023-12-11T11:06:16.602218373Z] Gathering output for process 2551067
[2023-12-11T11:06:16.603176801Z] Waiting for completion for process 2551067
[2023-12-11T11:06:18.793886942Z] Waiting for completion finished for process 2551067

testNewOutputAnalyzerStdout
[2023-12-11T11:06:18.796332176Z] Gathering output for process 2551172

See how the timestamp for "Waiting for completion for process" becomes "earlier" in the "executeProcess" cases.

---

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-8321718: ProcessTools.executeProcess calls waitFor before logging (Enhancement - P4)

Reviewers

• David Holmes (@dholmes-ora - Reviewer) ⚠️ Review applies to 145e1eaa
• Jaikiran Pai (@jaikiran - Reviewer) ⚠️ Review applies to 3275136c

Reviewing

Using git

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

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

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 17052

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

Using diff file

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

Webrev

Link to Webrev Comment

[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 labels will be automatically applied to this pull request:

• core-libs
• hotspot-runtime

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

[mlbridge]

Webrevs

• 02: Full - Incremental (fcba9dbd)
• 01: Full - Incremental (3275136c)
• 00: Full (145e1eaa)

[dholmes-ora]

Looks good.

Thanks

[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:

8321718: ProcessTools.executeProcess calls waitFor before logging

Reviewed-by: dholmes, jpai

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 7 new commits pushed to the master branch:

• a5cf421: 8320360: ClassFile.parse: Some defect class files cause unexpected exceptions to be thrown
• f9aec02: 8321540: ClassSignature.parseFrom() throws StringIndexOutOfBoundsException for invalid signatures
• 7455b1b: 8322159: ThisEscapeAnalyzer crashes for erroneous code
• d4fb308: 8317846: Typo in API documentation of classes IdentityHashMap
• d786c49: 8322751: ZGC: Fix comments about marking roots
• 5852f3e: 8322027: One XMLStreamException constructor fails to initialize cause
• be0e1c7: 8297573: Parallel: Rename do_oop_nv to do_oop_work in subclasses of OopClosure

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.

[stefank]

Thanks for reviewing! I'm considering removing the test before integrating, as it currently takes >8s to run and it was mainly used to show the difference between the implementations. Do you agree that it would be OK to remove the test?

[dholmes-ora]

Do you agree that it would be OK to remove the test?

Sure that's fine.

[jaikiran]

Hello Stefan, these changes look good to me.

Like you note, the new test case in this PR, isn't needed, so can be removed.

[stefank]

Thanks for reviewing! I'll remove the test, merge, and will do some sanity checks before integrating.

[stefank]

/integrate

[openjdk]

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

• ba426d6: 8322841: Parallel: Remove unused using-declaration in MutableNUMASpace
• 18cdc90: 8322801: RISC-V: The riscv path of the debian sysroot had been changed
• fcf8368: 8322248: Fix inconsistent wording in ElementFilter.typesIn
• a678416: 8322805: Eliminate -Wparentheses warnings in x86 code
• 122bc77: 8322758: Eliminate -Wparentheses warnings in C2 code
• e9e694f: 8320275: assert(_chunk->bitmap().at(index)) failed: Bit not set at index
• da1091e: 8322807: Eliminate -Wparentheses warnings in gc code
• c2477a5: 8322868: java/io/BufferedInputStream/TransferToTrusted.java has bad copyright header
• 2cf5f01: 8322802: Add testing for ZipFile.getEntry respecting the 'Language encoding' flag
• 38042ad: 8320971: Use BufferedInputStream.buf directly when param of implTransferTo() is trusted
• ... and 9 more: https://git.openjdk.org/jdk/compare/7c1d481d6ddeb67118abbdc909884f4793343fee...master

Your commit was automatically rebased without conflicts.

[openjdk]

@stefank Pushed as commit 9ab29f8.

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