RFR(S): 8240295: hs_err elapsed time in seconds is not accurate enough

[David Holmes]

Hi Kevin,

On 2/03/2020 8:48 pm, Kevin Walls wrote:
> Oops, and with the bug ID in the title and JBS link:
> https://bugs.openjdk.java.net/browse/JDK-8240295
> 
> 
> On 02/03/2020 10:47, Kevin Walls wrote:
>> Hi,
>>
>> (s11y and runtime opinions both relevant)
>>
>> A few times in the last month I've really wanted to compare the Events 
>> logged in the hs_err file, and the time of the JVM's crash.
>>
>> "elapsed time" in hs_err is only accurate to one second, and has been 
>> since before jdk5 was created.
>>
>> The diff below changes the format string and uses the non-rounded time 
>> value (I don't see a need to change the other integer arithmetic 
>> here), and we can enjoy hs_errs with detail like:
>>
>> ...
>> Time: Mon Mar  2 09:57:13 2020 UTC elapsed time: 5.490135 seconds (0d 
>> 0h 0m 5s)
>> ...
>>
>> Thanks
>> Kevin
>>
>>
>> /jdk/open$ hg diff
>> diff --git a/src/hotspot/share/runtime/os.cpp 
>> b/src/hotspot/share/runtime/os.cpp
>> --- a/src/hotspot/share/runtime/os.cpp
>> +++ b/src/hotspot/share/runtime/os.cpp
>> @@ -1016,9 +1016,8 @@
>>    }
>>
>>    double t = os::elapsedTime();
>> -  // NOTE: It tends to crash after a SEGV if we want to 
>> printf("%f",...) in
>> -  //       Linux. Must be a bug in glibc ? Workaround is to round "t" 
>> to int
>> -  //       before printf. We lost some precision, but who cares?
>> +  // NOTE: a crash using printf("%f",...) on Linux was historically 
>> noted here
>> +  //       (before the jdk5 repo was created).

Just because it is old doesn't mean it no longer applies. printf is not 
async-signal-safe - we know that but we try to use it anyway. Maybe %f 
is even less async-signal-safe?

This may get through testing okay but cause problems with real crashes 
in the field.

What about breaking the time up into two ints: seconds and nanos?

Cheers,
David
-----

>>    int eltime = (int)t;  // elapsed time in seconds
>>
>>    // print elapsed time in a human-readable format:
>> @@ -1029,7 +1028,7 @@
>>    int elmins = (eltime - day_secs - hour_secs) / secs_per_min;
>>    int minute_secs = elmins * secs_per_min;
>>    int elsecs = (eltime - day_secs - hour_secs - minute_secs);
>> -  st->print_cr(" elapsed time: %d seconds (%dd %dh %dm %ds)", eltime, 
>> eldays, elhours, elmins, elsecs);
>> +  st->print_cr(" elapsed time: %f seconds (%dd %dh %dm %ds)", t, 
>> eldays, elhours, elmins, elsecs);
>>  }
>>
>>