RFR: 8219149: ProcessTools.ProcessBuilder should print timing info for subprocesses

[Roger Riggs]

Hi Kim,

To ensure you see some messages in the case of timeouts, it would be
useful to call System.out.flush() after printing the message in 
logProcess().

I'm ok with the timestamps, as is, though the Duration might be useful in
some cases.

+1, Roger


On 05/30/2019 12:42 AM, David Holmes wrote:
> Adding back hotspot-dev. I don't think Kim saw this.
>
> David
>
> On 30/05/2019 4:04 am, Roger Riggs wrote:
>> Hi Kim,
>>
>> In the normal output less output is cleaner.
>> It would be more useful to have the Duration of the wait and end time 
>> of the wait.
>> (It saves the reader doing subtraction of times).
>>
>> +          Instant start = Instant.now();
>> +          boolean aborted = true;
>> +          try {
>> +              int result = p.waitFor();
>> +              aborted = false;
>> +              return result;
>> +          } finally {
>> +              Duration dur = Duration.between(start, Instant.now());
>> +              if (aborted) {
>> +                  logProgress("Waiting for completion FAILED after: 
>> " + dur);
>> +              } else {
>> +                  logProgress("Waiting for completion finished 
>> after: " + dur);
>> +              }
>> +          }
>>
>> Or something like that.
>>
>> Roger
>>
>>
>> On 05/29/2019 01:24 PM, Kim Barrett wrote:
>>> [I’m not completely sure where this RFR should be sent, but 
>>> core-libs-dev
>>> and hotspot-dev seems likely to get reasonable coverage of those who
>>> might care.]
>>>
>>> Please review this change to the test library to add some "logging"
>>> output to tests that spawn a child process to perform the test and
>>> then analyze that child's output.  We are seeing occasional timeouts
>>> in such tests whose cause is hard to pin down.  It's not clear whether
>>> the excess time is in the child or instead some problem in the testing
>>> framework.  The new logging output provides timestamps for (1) the
>>> start of output collection from the child, (2) the start of waiting
>>> for the child to terminate, and (3) the child's termination. This
>>> should be enough to determine whether the child is taking too long,
>>> and hint at where (e.g. termination or not).
>>>
>>> CR:
>>> https://bugs.openjdk.java.net/browse/JDK-8219149
>>>
>>> Webrev:
>>> http://cr.openjdk.java.net/~kbarrett/8219149/open.00/
>>>
>>> Testing:
>>> Local hs-tier1 and verified the expected logging output is present.
>>> mach5 tier1-3 to ensure there aren't any "obvious" unexpected problems
>>> caused by the new logging.  (It seems unlikely, but...)
>>>
>>>
>>