RFR: 8321718: ProcessTools.executeProcess calls waitFor before logging [v3]

Stefan Karlsson stefank at openjdk.org
Tue Jan 2 15:26:03 UTC 2024


> 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...

Stefan Karlsson has updated the pull request with a new target base due to a merge or a rebase. The incremental webrev excludes the unrelated changes brought in by the merge/rebase. The pull request contains five additional commits since the last revision:

 - Merge remote-tracking branch 'upstream/master' into executeProcessLogging
 - Remove temporary test
 - Typo
 - Whitespace cleanups
 - 8321718: ProcessTools.executeProcess calls waitFor before logging

-------------

Changes:
  - all: https://git.openjdk.org/jdk/pull/17052/files
  - new: https://git.openjdk.org/jdk/pull/17052/files/3275136c..fcba9dbd

Webrevs:
 - full: https://webrevs.openjdk.org/?repo=jdk&pr=17052&range=02
 - incr: https://webrevs.openjdk.org/?repo=jdk&pr=17052&range=01-02

  Stats: 5347 lines in 349 files changed: 3069 ins; 1071 del; 1207 mod
  Patch: https://git.openjdk.org/jdk/pull/17052.diff
  Fetch: git fetch https://git.openjdk.org/jdk.git pull/17052/head:pull/17052

PR: https://git.openjdk.org/jdk/pull/17052


More information about the core-libs-dev mailing list