On Tue, 12 Dec 2023 09:01:08 GMT, Stefan Karlsson <stef...@openjdk.org> wrote:
>> 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 >> >> >> testNewOutp... > > Stefan Karlsson has updated the pull request incrementally with one > additional commit since the last revision: > > Typo Thanks for reviewing! I'll remove the test, merge, and will do some sanity checks before integrating. ------------- PR Comment: https://git.openjdk.org/jdk/pull/17052#issuecomment-1874162036
