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

[Kim Barrett]

> On May 30, 2019, at 12:42 AM, David Holmes <david.holmes at oracle.com> wrote:
> 
> Adding back hotspot-dev. I don't think Kim saw this.

I did see it, though nearly missed, and not spotted until late evening.  Thanks for making sure…

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