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

[Kevin Walls]

Thanks David -

Yes there are situations where hs_err fails, and few people are sadder 
than me
when that happens 8-) , so I was thinking about how scared to be by the 
comment.

With the safety net of the error handler for the steps of the hs_err file
(which works well, we see it invoked frequently), it looks reasonable to use
%f as we might do other slightly questionable things for a signal handler.

Corrupting locale information or floating point state might possibly cause
problems, but if I cause a fake crash in print_date_and_time the error
handler recovers and the report continues.


Thinking about printing with two ints, seconds and fractions:
I don't see anything already that returns such a time in two components 
in the
JVM, so we might implement a new form of os::javaTimeNanos() or similar that
returns the two parts, and do that on each platform.

I didn't yet come up with anything to do in os::print_date_and_time()
which will take the fractional part of the double, and print just the 
fraction
as an int, without using any library / %f facilities.

If you're still concerned I could revisit these or some other idea.

Genuine laugh out loud moment for me, I backported the elapsed time 
logging from
6u4 to 5u19  (https://bugs.openjdk.java.net/browse/JDK-6447157) (2007).
(I said before jdk5 was created, I should have said before it was in 
mercurial.)

Thanks
Kevin


On 03/03/2020 01:11, David Holmes wrote:
> 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);
>>>  }
>>>
>>>