Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer [v4]

2024-02-26 Thread Daniel Fuchs
On Mon, 15 Jan 2024 08:36:43 GMT, Stefan Karlsson  wrote:

>> Tests using ProcessTools.executeProcess gets the following output written to 
>> stdout:
>> [2023-11-24T09:58:16.797540608Z] Gathering output for process 2517117
>> [2023-11-24T09:58:23.070781345Z] Waiting for completion for process 2517117
>> [2023-11-24T09:58:23.071045055Z] Waiting for completion finished for process 
>> 2517117
>> 
>> This might be good for some use cases and debugging, but some tests spawns a 
>> large number of processes and for those this output fills up the log files.
>> 
>> I propose that we add a way to turn of this output for tests where we find 
>> this output to be too noisy.
>
> Stefan Karlsson has updated the pull request incrementally with one 
> additional commit since the last revision:
> 
>   Update copyright years

Hi Stefan - I see that this is an opt-in, so LGTM

-

Marked as reviewed by dfuchs (Reviewer).

PR Review: https://git.openjdk.org/jdk/pull/16807#pullrequestreview-1901818783


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer [v4]

2024-01-15 Thread Stefan Karlsson
> Tests using ProcessTools.executeProcess gets the following output written to 
> stdout:
> [2023-11-24T09:58:16.797540608Z] Gathering output for process 2517117
> [2023-11-24T09:58:23.070781345Z] Waiting for completion for process 2517117
> [2023-11-24T09:58:23.071045055Z] Waiting for completion finished for process 
> 2517117
> 
> This might be good for some use cases and debugging, but some tests spawns a 
> large number of processes and for those this output fills up the log files.
> 
> I propose that we add a way to turn of this output for tests where we find 
> this output to be too noisy.

Stefan Karlsson has updated the pull request incrementally with one additional 
commit since the last revision:

  Update copyright years

-

Changes:
  - all: https://git.openjdk.org/jdk/pull/16807/files
  - new: https://git.openjdk.org/jdk/pull/16807/files/9a43b2c9..4fb2fc21

Webrevs:
 - full: https://webrevs.openjdk.org/?repo=jdk=16807=03
 - incr: https://webrevs.openjdk.org/?repo=jdk=16807=02-03

  Stats: 2 lines in 2 files changed: 0 ins; 0 del; 2 mod
  Patch: https://git.openjdk.org/jdk/pull/16807.diff
  Fetch: git fetch https://git.openjdk.org/jdk.git pull/16807/head:pull/16807

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


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer [v3]

2024-01-12 Thread Leonid Mesnik
On Fri, 5 Jan 2024 09:07:57 GMT, Stefan Karlsson  wrote:

>> Tests using ProcessTools.executeProcess gets the following output written to 
>> stdout:
>> [2023-11-24T09:58:16.797540608Z] Gathering output for process 2517117
>> [2023-11-24T09:58:23.070781345Z] Waiting for completion for process 2517117
>> [2023-11-24T09:58:23.071045055Z] Waiting for completion finished for process 
>> 2517117
>> 
>> This might be good for some use cases and debugging, but some tests spawns a 
>> large number of processes and for those this output fills up the log files.
>> 
>> I propose that we add a way to turn of this output for tests where we find 
>> this output to be too noisy.
>
> Stefan Karlsson has updated the pull request with a new target base due to a 
> merge or a rebase. The pull request now contains three commits:
> 
>  - Merge remote-tracking branch 'upstream/master' into 
> 8320699_OutputAnalyzer_progress_logging
>  - Update OutputBuffer.java copyright years
>  - 8320699: Add parameter to skip progress logging of OutputAnalyzer

I think that commit is going to have date in 2024. So any check is going to 
compare this date and copyright year. It shouldn't cause fail i CI and files 
are going to be updated later with  verification scripts.

-

PR Comment: https://git.openjdk.org/jdk/pull/16807#issuecomment-1889709770


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer [v3]

2024-01-12 Thread Stefan Karlsson
On Fri, 12 Jan 2024 01:10:49 GMT, Leonid Mesnik  wrote:

> Needed to update copyrights now.

Even when the code was written in 2023?

-

PR Comment: https://git.openjdk.org/jdk/pull/16807#issuecomment-1888699636


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer [v3]

2024-01-11 Thread Leonid Mesnik
On Fri, 5 Jan 2024 09:07:57 GMT, Stefan Karlsson  wrote:

>> Tests using ProcessTools.executeProcess gets the following output written to 
>> stdout:
>> [2023-11-24T09:58:16.797540608Z] Gathering output for process 2517117
>> [2023-11-24T09:58:23.070781345Z] Waiting for completion for process 2517117
>> [2023-11-24T09:58:23.071045055Z] Waiting for completion finished for process 
>> 2517117
>> 
>> This might be good for some use cases and debugging, but some tests spawns a 
>> large number of processes and for those this output fills up the log files.
>> 
>> I propose that we add a way to turn of this output for tests where we find 
>> this output to be too noisy.
>
> Stefan Karlsson has updated the pull request with a new target base due to a 
> merge or a rebase. The pull request now contains three commits:
> 
>  - Merge remote-tracking branch 'upstream/master' into 
> 8320699_OutputAnalyzer_progress_logging
>  - Update OutputBuffer.java copyright years
>  - 8320699: Add parameter to skip progress logging of OutputAnalyzer

Needed to update copyrights now.

-

Marked as reviewed by lmesnik (Reviewer).

PR Review: https://git.openjdk.org/jdk/pull/16807#pullrequestreview-1817096686


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer [v3]

2024-01-05 Thread Jaikiran Pai
On Fri, 5 Jan 2024 09:07:57 GMT, Stefan Karlsson  wrote:

>> Tests using ProcessTools.executeProcess gets the following output written to 
>> stdout:
>> [2023-11-24T09:58:16.797540608Z] Gathering output for process 2517117
>> [2023-11-24T09:58:23.070781345Z] Waiting for completion for process 2517117
>> [2023-11-24T09:58:23.071045055Z] Waiting for completion finished for process 
>> 2517117
>> 
>> This might be good for some use cases and debugging, but some tests spawns a 
>> large number of processes and for those this output fills up the log files.
>> 
>> I propose that we add a way to turn of this output for tests where we find 
>> this output to be too noisy.
>
> Stefan Karlsson has updated the pull request with a new target base due to a 
> merge or a rebase. The pull request now contains three commits:
> 
>  - Merge remote-tracking branch 'upstream/master' into 
> 8320699_OutputAnalyzer_progress_logging
>  - Update OutputBuffer.java copyright years
>  - 8320699: Add parameter to skip progress logging of OutputAnalyzer

Still looks fine.

-

Marked as reviewed by jpai (Reviewer).

PR Review: https://git.openjdk.org/jdk/pull/16807#pullrequestreview-1807268366


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer [v3]

2024-01-05 Thread Stefan Karlsson
> Tests using ProcessTools.executeProcess gets the following output written to 
> stdout:
> [2023-11-24T09:58:16.797540608Z] Gathering output for process 2517117
> [2023-11-24T09:58:23.070781345Z] Waiting for completion for process 2517117
> [2023-11-24T09:58:23.071045055Z] Waiting for completion finished for process 
> 2517117
> 
> This might be good for some use cases and debugging, but some tests spawns a 
> large number of processes and for those this output fills up the log files.
> 
> I propose that we add a way to turn of this output for tests where we find 
> this output to be too noisy.

Stefan Karlsson has updated the pull request with a new target base due to a 
merge or a rebase. The pull request now contains three commits:

 - Merge remote-tracking branch 'upstream/master' into 
8320699_OutputAnalyzer_progress_logging
 - Update OutputBuffer.java copyright years
 - 8320699: Add parameter to skip progress logging of OutputAnalyzer

-

Changes: https://git.openjdk.org/jdk/pull/16807/files
 Webrev: https://webrevs.openjdk.org/?repo=jdk=16807=02
  Stats: 24 lines in 2 files changed: 21 ins; 0 del; 3 mod
  Patch: https://git.openjdk.org/jdk/pull/16807.diff
  Fetch: git fetch https://git.openjdk.org/jdk.git pull/16807/head:pull/16807

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


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer [v2]

2023-12-03 Thread David Holmes
On Thu, 30 Nov 2023 16:23:39 GMT, Stefan Karlsson  wrote:

>> Tests using ProcessTools.executeProcess gets the following output written to 
>> stdout:
>> [2023-11-24T09:58:16.797540608Z] Gathering output for process 2517117
>> [2023-11-24T09:58:23.070781345Z] Waiting for completion for process 2517117
>> [2023-11-24T09:58:23.071045055Z] Waiting for completion finished for process 
>> 2517117
>> 
>> This might be good for some use cases and debugging, but some tests spawns a 
>> large number of processes and for those this output fills up the log files.
>> 
>> I propose that we add a way to turn of this output for tests where we find 
>> this output to be too noisy.
>
> Stefan Karlsson has updated the pull request incrementally with one 
> additional commit since the last revision:
> 
>   Update OutputBuffer.java copyright years

Okay.

Thanks

-

Marked as reviewed by dholmes (Reviewer).

PR Review: https://git.openjdk.org/jdk/pull/16807#pullrequestreview-1761525078


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer [v2]

2023-11-30 Thread Jaikiran Pai
On Thu, 30 Nov 2023 16:23:39 GMT, Stefan Karlsson  wrote:

>> Tests using ProcessTools.executeProcess gets the following output written to 
>> stdout:
>> [2023-11-24T09:58:16.797540608Z] Gathering output for process 2517117
>> [2023-11-24T09:58:23.070781345Z] Waiting for completion for process 2517117
>> [2023-11-24T09:58:23.071045055Z] Waiting for completion finished for process 
>> 2517117
>> 
>> This might be good for some use cases and debugging, but some tests spawns a 
>> large number of processes and for those this output fills up the log files.
>> 
>> I propose that we add a way to turn of this output for tests where we find 
>> this output to be too noisy.
>
> Stefan Karlsson has updated the pull request incrementally with one 
> additional commit since the last revision:
> 
>   Update OutputBuffer.java copyright years

These changes look good to me. Please wait for another review before 
integrating.

-

Marked as reviewed by jpai (Reviewer).

PR Review: https://git.openjdk.org/jdk/pull/16807#pullrequestreview-1758849913


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer

2023-11-30 Thread Stefan Karlsson
On Thu, 30 Nov 2023 12:19:33 GMT, Jaikiran Pai  wrote:

> Hello Stefan,
> 
> > The test were I want to use this is a long-running stress test that is 
> > known to be good at shaking out JVM hangs. It has been written to provide 
> > its own output about spawned processes and what they are doing, and have 
> > that info written to appropriate files. For me, the OutputAnalyzer logging 
> > just adds redundant output to the streams where I don't want the 
> > information.
> 
> Thank you for that context. What you are then proposing is for a way to reuse 
> this utility class in specific tests, like the one you are working on, 
> without needing the progress logs. So the idea isn't really to use this new 
> API in all newly developed tests which use this `ProcessTools` library. Plus 
> the implementation in this PR, retains the existing behaviour of logging the 
> progress by default, which is a good thing.

Yes, you summarize this well.

> 
> Given that context, I don't have any objection in introducing this 
> enhancemnet. During future reviews, I think, it wouldn't be too difficult to 
> catch misuses of this new API in newer tests where the progress logs 
> shouldn't be disabled.

Yes, I agree. It would be quite obvious if someone tries to turn this off.

> 
> As for whether this "config" should be externalized - I think it shouldn't 
> be, since whether or not the progress logs will be excessive and too 
> distracting (and thus need to be disabled) would be known at test development 
> time itself.

I agree.

> The copyright year on OutputBuffer.java will need an update.

Fixed.

Thanks for taking a look at this!

-

PR Comment: https://git.openjdk.org/jdk/pull/16807#issuecomment-1834103958


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer [v2]

2023-11-30 Thread Stefan Karlsson
> Tests using ProcessTools.executeProcess gets the following output written to 
> stdout:
> [2023-11-24T09:58:16.797540608Z] Gathering output for process 2517117
> [2023-11-24T09:58:23.070781345Z] Waiting for completion for process 2517117
> [2023-11-24T09:58:23.071045055Z] Waiting for completion finished for process 
> 2517117
> 
> This might be good for some use cases and debugging, but some tests spawns a 
> large number of processes and for those this output fills up the log files.
> 
> I propose that we add a way to turn of this output for tests where we find 
> this output to be too noisy.

Stefan Karlsson has updated the pull request incrementally with one additional 
commit since the last revision:

  Update OutputBuffer.java copyright years

-

Changes:
  - all: https://git.openjdk.org/jdk/pull/16807/files
  - new: https://git.openjdk.org/jdk/pull/16807/files/d5b13dce..d0091eb6

Webrevs:
 - full: https://webrevs.openjdk.org/?repo=jdk=16807=01
 - incr: https://webrevs.openjdk.org/?repo=jdk=16807=00-01

  Stats: 1 line in 1 file changed: 0 ins; 0 del; 1 mod
  Patch: https://git.openjdk.org/jdk/pull/16807.diff
  Fetch: git fetch https://git.openjdk.org/jdk.git pull/16807/head:pull/16807

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


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer

2023-11-30 Thread Jaikiran Pai
On Fri, 24 Nov 2023 10:34:02 GMT, Stefan Karlsson  wrote:

> Tests using ProcessTools.executeProcess gets the following output written to 
> stdout:
> [2023-11-24T09:58:16.797540608Z] Gathering output for process 2517117
> [2023-11-24T09:58:23.070781345Z] Waiting for completion for process 2517117
> [2023-11-24T09:58:23.071045055Z] Waiting for completion finished for process 
> 2517117
> 
> This might be good for some use cases and debugging, but some tests spawns a 
> large number of processes and for those this output fills up the log files.
> 
> I propose that we add a way to turn of this output for tests where we find 
> this output to be too noisy.

Hello Stefan,

> The test were I want to use this is a long-running stress test that is known 
> to be good at shaking out JVM hangs. It has been written to provide its own 
> output about spawned processes and what they are doing, and have that info 
> written to appropriate files. For me, the OutputAnalyzer logging just adds 
> redundant output to the streams where I don't want the information.

Thank you for that context. What you are then proposing is for a way to reuse 
this utility class in specific tests, like the one you are working on, without 
needing the progress logs. So the idea isn't really to use this new API in all 
newly developed tests which use this `ProcessTools` library. Plus the 
implementation in this PR, retains the existing behaviour of logging the 
progress by default, which is a good thing.

Given that context, I don't have any objection in introducing this enhancemnet. 
During future reviews, I think, it wouldn't be too difficult to catch misuses 
of this new API in newer tests where the progress logs shouldn't be disabled.

As for whether this "config" should be externalized - I think it shouldn't be, 
since whether or not the progress logs will be excessive and too distracting 
(and thus need to be disabled) would be known at test development time itself.

The copyright year on `OutputBuffer.java` will need an update.

-

PR Comment: https://git.openjdk.org/jdk/pull/16807#issuecomment-1833660673
PR Comment: https://git.openjdk.org/jdk/pull/16807#issuecomment-1833664072


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer

2023-11-30 Thread Jaikiran Pai
On Mon, 27 Nov 2023 08:27:25 GMT, Stefan Karlsson  wrote:

> So, I think you have found a separate issue.

I'll open a separate issue for that and propose a change.

-

PR Comment: https://git.openjdk.org/jdk/pull/16807#issuecomment-1833661517


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer

2023-11-27 Thread Stefan Karlsson
On Fri, 24 Nov 2023 17:01:29 GMT, Jaikiran Pai  wrote:

> Hello Stefan, I agree with David that I have found these logs to be useful - 
> it shows that process launched by the test hasn't yet finished and is being 
> waited upon. The log message when written will have a timestamp and can then 
> also help to quickly understand how long it could have taken for this process 
> to complete.

The test were I want to use this is a long-running stress test that is known to 
be good at shaking out JVM hangs. It has been written to provide its own output 
about spawned processes and what they are doing, and have that info written to 
appropriate files. For me, the OutputAnalyzer logging just adds redundant 
output to the streams where I don't want the information.

When we do have JVM hangs in these larger tests it's usually is easier to look 
at the output generated from 
[test/failure_handler](https://github.com/openjdk/jdk/tree/master/test/failure_handler).

-

PR Comment: https://git.openjdk.org/jdk/pull/16807#issuecomment-1827410018


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer

2023-11-27 Thread Stefan Karlsson
On Fri, 24 Nov 2023 17:13:30 GMT, Jaikiran Pai  wrote:

> Other than a quick local test run, I haven't tested it for anything else. It 
> did improve the situation in one of my test and it now only logs it once. In 
> the setup that you are seeing this large amount of logging, would you be able 
> to see if this change helps there too?

The place where I would like to use it we repeatedly spawn a number of 
different processes to inspect the JVM and the OS. So, I think you have found a 
separate issue.

-

PR Comment: https://git.openjdk.org/jdk/pull/16807#issuecomment-1827352788


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer

2023-11-24 Thread David Holmes
On Fri, 24 Nov 2023 17:13:30 GMT, Jaikiran Pai  wrote:

>> Tests using ProcessTools.executeProcess gets the following output written to 
>> stdout:
>> [2023-11-24T09:58:16.797540608Z] Gathering output for process 2517117
>> [2023-11-24T09:58:23.070781345Z] Waiting for completion for process 2517117
>> [2023-11-24T09:58:23.071045055Z] Waiting for completion finished for process 
>> 2517117
>> 
>> This might be good for some use cases and debugging, but some tests spawns a 
>> large number of processes and for those this output fills up the log files.
>> 
>> I propose that we add a way to turn of this output for tests where we find 
>> this output to be too noisy.
>
> Perhaps this would help improve/fix the log flooding:
> 
> 
> diff --git a/test/lib/jdk/test/lib/process/OutputBuffer.java 
> b/test/lib/jdk/test/lib/process/OutputBuffer.java
> index 3741ccbe2ff..02aedf29f6a 100644
> --- a/test/lib/jdk/test/lib/process/OutputBuffer.java
> +++ b/test/lib/jdk/test/lib/process/OutputBuffer.java
> @@ -120,6 +120,7 @@ public String get() {
>  private final StreamTask outTask;
>  private final StreamTask errTask;
>  private final Process p;
> +private volatile Integer processExitCode; // null represents process 
> hasn't yet exited
>  
>  private final void logProgress(String state) {
>  System.out.println("[" + Instant.now().toString() + "] " + state
> @@ -146,14 +147,18 @@ public String getStderr() {
>  
>  @Override
>  public int getExitValue() {
> +  Integer exitCode = this.processExitCode;
> +  if (exitCode != null) {
> +return exitCode;
> +  }
>try {
>logProgress("Waiting for completion");
>boolean aborted = true;
>try {
> -  int result = p.waitFor();
> +  processExitCode = exitCode = p.waitFor();
>logProgress("Waiting for completion finished");
>aborted = false;
> -  return result;
> +  return exitCode;
>} finally {
>if (aborted) {
>logProgress("Waiting for completion FAILED");
> 
> 
> Other than a quick local test run, I haven't tested it for anything else. It 
> did improve the situation in one of my test and it now only logs it once. In 
> the setup that you are seeing this large amount of logging, would you be able 
> to see if this change helps there too?

@jaikiran that looks like a good fix to me. It doesn't make sense to keep 
repeating the logging on every `getExitValue` call. Good find!

-

PR Comment: https://git.openjdk.org/jdk/pull/16807#issuecomment-1826150703


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer

2023-11-24 Thread Jaikiran Pai
On Fri, 24 Nov 2023 10:34:02 GMT, Stefan Karlsson  wrote:

> Tests using ProcessTools.executeProcess gets the following output written to 
> stdout:
> [2023-11-24T09:58:16.797540608Z] Gathering output for process 2517117
> [2023-11-24T09:58:23.070781345Z] Waiting for completion for process 2517117
> [2023-11-24T09:58:23.071045055Z] Waiting for completion finished for process 
> 2517117
> 
> This might be good for some use cases and debugging, but some tests spawns a 
> large number of processes and for those this output fills up the log files.
> 
> I propose that we add a way to turn of this output for tests where we find 
> this output to be too noisy.

Perhaps this would help improve/fix the log flooding:


diff --git a/test/lib/jdk/test/lib/process/OutputBuffer.java 
b/test/lib/jdk/test/lib/process/OutputBuffer.java
index 3741ccbe2ff..02aedf29f6a 100644
--- a/test/lib/jdk/test/lib/process/OutputBuffer.java
+++ b/test/lib/jdk/test/lib/process/OutputBuffer.java
@@ -120,6 +120,7 @@ public String get() {
 private final StreamTask outTask;
 private final StreamTask errTask;
 private final Process p;
+private volatile Integer processExitCode; // null represents process 
hasn't yet exited
 
 private final void logProgress(String state) {
 System.out.println("[" + Instant.now().toString() + "] " + state
@@ -146,14 +147,18 @@ public String getStderr() {
 
 @Override
 public int getExitValue() {
+  Integer exitCode = this.processExitCode;
+  if (exitCode != null) {
+return exitCode;
+  }
   try {
   logProgress("Waiting for completion");
   boolean aborted = true;
   try {
-  int result = p.waitFor();
+  processExitCode = exitCode = p.waitFor();
   logProgress("Waiting for completion finished");
   aborted = false;
-  return result;
+  return exitCode;
   } finally {
   if (aborted) {
   logProgress("Waiting for completion FAILED");


Other than a quick local test run, I haven't tested it for anything else. It 
did improve the situation in one of my test and it now only logs it once. In 
the setup that you are seeing this large amount of logging, would you be able 
to see if this change helps there too?

-

PR Comment: https://git.openjdk.org/jdk/pull/16807#issuecomment-1825932899


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer

2023-11-24 Thread Jaikiran Pai
On Fri, 24 Nov 2023 10:34:02 GMT, Stefan Karlsson  wrote:

> Tests using ProcessTools.executeProcess gets the following output written to 
> stdout:
> [2023-11-24T09:58:16.797540608Z] Gathering output for process 2517117
> [2023-11-24T09:58:23.070781345Z] Waiting for completion for process 2517117
> [2023-11-24T09:58:23.071045055Z] Waiting for completion finished for process 
> 2517117
> 
> This might be good for some use cases and debugging, but some tests spawns a 
> large number of processes and for those this output fills up the log files.
> 
> I propose that we add a way to turn of this output for tests where we find 
> this output to be too noisy.

Hello Stefan, I agree with David that I have found these logs to be useful - it 
shows that process launched by the test hasn't yet finished and is being waited 
upon. The log message when written will have a timestamp and can then also help 
to quickly understand how long it could have taken for this process to complete.

> Right now I much more annoyed by the log files filling up with thousands upon 
> thousands lines of noise, making it harder to actually find the status of the 
> test.

This I agree with. It's a co-incidence that just this week when I was looking 
at some test logs I happened to see such large amount of unexpected logging 
(not thousands, but large enough). For example:


[2023-11-24T11:47:54.557561Z] Waiting for completion for process 24909
[2023-11-24T11:47:54.557873Z] Waiting for completion finished for process 24909
[2023-11-24T11:47:54.612609Z] Waiting for completion for process 24909
[2023-11-24T11:47:54.612682Z] Waiting for completion finished for process 24909
[2023-11-24T11:47:54.614500Z] Waiting for completion for process 24909
[2023-11-24T11:47:54.614542Z] Waiting for completion finished for process 24909
[2023-11-24T11:47:54.640945Z] Waiting for completion for process 24909
[2023-11-24T11:47:54.641115Z] Waiting for completion finished for process 24909

I wonder if something else is going on here, because looking at these logs 
messages it says that it has finished waiting for a process 24909, yet it keeps 
repeating those messages. I would have expected it to stop logging after the 
first:


Waiting for completion finished for process 24909

I haven't yet had a chance to look at the code to see if there's some bug which 
is contributing to this extensive logging.

-

PR Comment: https://git.openjdk.org/jdk/pull/16807#issuecomment-1825923223


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer

2023-11-24 Thread Thomas Stuefe
On Fri, 24 Nov 2023 10:34:02 GMT, Stefan Karlsson  wrote:

> Tests using ProcessTools.executeProcess gets the following output written to 
> stdout:
> [2023-11-24T09:58:16.797540608Z] Gathering output for process 2517117
> [2023-11-24T09:58:23.070781345Z] Waiting for completion for process 2517117
> [2023-11-24T09:58:23.071045055Z] Waiting for completion finished for process 
> 2517117
> 
> This might be good for some use cases and debugging, but some tests spawns a 
> large number of processes and for those this output fills up the log files.
> 
> I propose that we add a way to turn of this output for tests where we find 
> this output to be too noisy.

I'm fine with this, but would prefer a global switch instead of hard-coding the 
value per test and handing it down.

-

PR Comment: https://git.openjdk.org/jdk/pull/16807#issuecomment-1825910975


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer

2023-11-24 Thread Stefan Karlsson
On Fri, 24 Nov 2023 13:06:05 GMT, David Holmes  wrote:

> I can't help but feel that if you disable this output then you are going to 
> be missing it in the cases that you need it! Something will go wrong and 
> there won't be enough info in the log to know what it was.

My experience is that I won't need it. I've been able to identify numerous 
hangs, deadlocks, timeouts in the stress tests where I want to use this. Right 
now I much more annoyed by the log files filling up with thousands upon 
thousands lines of noise, making it harder to actually find the status of the 
test.

An alternative to this could be to redirect the output to another file.

-

PR Comment: https://git.openjdk.org/jdk/pull/16807#issuecomment-1825888462


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer

2023-11-24 Thread David Holmes
On Fri, 24 Nov 2023 10:34:02 GMT, Stefan Karlsson  wrote:

> Tests using ProcessTools.executeProcess gets the following output written to 
> stdout:
> [2023-11-24T09:58:16.797540608Z] Gathering output for process 2517117
> [2023-11-24T09:58:23.070781345Z] Waiting for completion for process 2517117
> [2023-11-24T09:58:23.071045055Z] Waiting for completion finished for process 
> 2517117
> 
> This might be good for some use cases and debugging, but some tests spawns a 
> large number of processes and for those this output fills up the log files.
> 
> I propose that we add a way to turn of this output for tests where we find 
> this output to be too noisy.

I can't help but feel that if you disable this output then you are going to be 
missing it in the cases that you need it! Something will go wrong and there 
won't be enough info in the log to know what it was.

-

PR Comment: https://git.openjdk.org/jdk/pull/16807#issuecomment-1825651785


Re: RFR: 8320699: Add parameter to skip progress logging of OutputAnalyzer

2023-11-24 Thread Stefan Karlsson
On Fri, 24 Nov 2023 10:34:02 GMT, Stefan Karlsson  wrote:

> Tests using ProcessTools.executeProcess gets the following output written to 
> stdout:
> [2023-11-24T09:58:16.797540608Z] Gathering output for process 2517117
> [2023-11-24T09:58:23.070781345Z] Waiting for completion for process 2517117
> [2023-11-24T09:58:23.071045055Z] Waiting for completion finished for process 
> 2517117
> 
> This might be good for some use cases and debugging, but some tests spawns a 
> large number of processes and for those this output fills up the log files.
> 
> I propose that we add a way to turn of this output for tests where we find 
> this output to be too noisy.

This has been tested with an Oracle-internal stress tests.

-

PR Comment: https://git.openjdk.org/jdk/pull/16807#issuecomment-1825466825