RFR (M): 8235741: Inappropriate uses of os::javaTimeMillis()

[David Holmes]

Hi Erik,

On 16/01/2020 9:54 pm, Erik Gahlin wrote:
> HI David,
> 
> I'm reasonable convinced the JFR code works as before. We should 
> probably rewrite the code, but it's outside the scope of this bug.

Great! Thanks for taking a detailed look at that part.

David

> Thanks for fixing
> Erik
> 
> On 2020-01-16 05:26, David Holmes wrote:
>> While awaiting further comments/feedback I've made some updates:
>>
>> - added comments to existing use of javaTimeMillis() where it wasn't 
>> (fairly) obvious why it was being used
>> - fixed now incorrect comment pointed out by Kim
>> - copied os_per_linux.cpp changes to os_perf_aix.cpp (optimistically 
>> hoping for a thumbs up from Erik G. on this part :) ).
>>
>> Full and incr webrevs at:
>>
>> http://cr.openjdk.java.net/~dholmes/8235741/webrev.v2/
>> http://cr.openjdk.java.net/~dholmes/8235741/webrev.v2-incr/
>>
>> Thanks,
>> David
>>
>> On 15/01/2020 5:12 pm, David Holmes wrote:
>>> Hi Kim,
>>>
>>> Thanks for taking a look at this.
>>>
>>> On 15/01/2020 4:24 pm, Kim Barrett wrote:
>>>>> On Jan 13, 2020, at 2:13 AM, David Holmes <david.holmes at oracle.com> 
>>>>> wrote:
>>>>>
>>>>> webrev: http://cr.openjdk.java.net/~dholmes/8235741/webrev/
>>>>> bug: https://bugs.openjdk.java.net/browse/JDK-8235741
>>>>>
>>>>> Full details in the bug report about the existing uses of 
>>>>> javaTimeMillis(), many of which just want an elapsed time in ms and 
>>>>> so should be using javaTimeNanos() and convert to ms. This covers 
>>>>> areas all across the VM.
>>>>>
>>>>> Only non-simple change is in os_perf_linux.cpp (and the same code 
>>>>> will be in os_perf_aix.cpp once it has been validated). There we 
>>>>> are tracking an elapsed time in ms but relative to the boot time, 
>>>>> which is seconds since the epoch. Consequently the first interval 
>>>>> has to be calculated using javaTimeMillis, but after that we can 
>>>>> use javaTimeNanos (using a new 'first time' captured at the same 
>>>>> time we used javaTimeMillis). I think I have the logic right but 
>>>>> other than through JFR this code seems unused and I have limited 
>>>>> means of testing it. The JFR test 
>>>>> jdk/jfr/event/os/TestThreadContextSwitches.java exercises the code 
>>>>> but the results of running that test seems to exhibit arbitrary 
>>>>> randomness in the rates reported - e.g. 0 to 16000Hz - both with 
>>>>> and without my change, so not really that useful. Stefan K. 
>>>>> suggested a gtest which I may look into - though it is frustrating 
>>>>> to have to expend such effort to validate this.
>>>>>
>>>>> Other testing tiers 1-3.
>>>>>
>>>>> Thanks,
>>>>> David
>>>>
>>>> Thanks for the audit of uses of os::javaTimeMillis() in the bug report.
>>>> I wonder if some of that ought to be captured as comments in the
>>>> relevant code.  It's not always obvious to me that an external time
>>>> base is involved and thus making javaTimeMillis not a mistake.
>>>
>>> Okay, I will add comments to the other uses of currentTimeMillis().
>>>
>>>> There are a lot of places where conversions from nanoseconds to
>>>> milliseconds are being done to maintain existing units.  Some of those
>>>> places look like they could just as well be in nanoseconds. But I can
>>>> see how changing the units for some of those could lead to a lot of
>>>> fannout, so okay.
>>>
>>> Yes I tried to minimise the changes. In many cases a granularity of 
>>> ms seems somewhat arbitrary.
>>>
>>>> ------------------------------------------------------------------------------ 
>>>>
>>>> src/hotspot/os/windows/os_perf_windows.cpp
>>>>   100   s8     lastUpdate; // Last time query was updated (current 
>>>> millis).
>>>> ...
>>>>   290   const s8 now = os::javaTimeNanos();
>>>>   291   if (NANOS_TO_MILLIS(now - update_query->lastUpdate) > 
>>>> min_update_interval_millis) {
>>>> ...
>>>>   295     update_query->lastUpdate = now;
>>>>
>>>> now and update_query->lastUpdate are now in nanos, but comment for
>>>> lastUpdate still says it's in millis.  Looks like the comment needs
>>>> updating.
>>>
>>> Yes - good catch.
>>>
>>>> ------------------------------------------------------------------------------ 
>>>>
>>>> src/hotspot/share/utilities/globalDefinitions.hpp
>>>>   262 // time unit conversion macros
>>>>   263
>>>>   264 #define NANOS_TO_MILLIS(ns) ((ns) / NANOSECS_PER_MILLISEC)
>>>>   265 #define MILLIS_TO_NANOS(ms) ((ms) * NANOSECS_PER_MILLISEC)
>>>>
>>>> Why are these macros, rather than (template) functions?
>>>
>>> Just because I just wanted a simple textual replacement to make it 
>>> clearer that I'm converting from millis to nanos or vice versa. I 
>>> reach for macros for such simple cases.
>>>
>>>> Also, depending on the type and value of ms, MILLIS_TO_NANOS could
>>>> easily overflow, e.g. if ms type is a 32 bit type with a value of more
>>>> than ~4 seconds.  (I checked the two uses, and they happen to be okay.)
>>>
>>> These are not trying to be mathematically sound. The conversion from 
>>> millis to nanos is used in two cases:
>>>
>>> 1. Converting a current timestamp in ms to ns. Unless the current 
>>> time is set far in the future I don't think we have any issue with 
>>> overflow of  such a value.
>>>
>>> 2. converting an elapsed time in ms to ns. These will be small values 
>>> so no overflow is possible.
>>>
>>>> inline int64_t nanos_to_millis(int64_t ns) {
>>>>    return ns / NANOSECS_PER_MILLISECOND;
>>>> }
>>>>
>>>> inline int64_t millis_to_nanos(int64_t ms) {
>>>>    return ms * NANOSECONDS_PER_MILLISEC;
>>>> }
>>>>
>>>> Also, the names don't suggest time conversions, but potentially
>>>> arbitrary unit conversions, e.g. between something in NANOUNITS and
>>>> something in MILLIUNITS.
>>>
>>> They don't have to be time conversions - the calculation is unit-less 
>>> in practice. The fact we have NANOSEC_PER_MILLISECOND et al is just 
>>> an artifact of introducing those values for timeout 
>>> calculations/conversions - it could just be NANOS_PER_MILLI etc
>>>
>>>> ------------------------------------------------------------------------------ 
>>>>
>>>> Regarding this from the audit:
>>>>
>>>> --- begin ---
>>>> ./share/gc/parallel/psParallelCompact.cpp: // os::javaTimeMillis() 
>>>> does not guarantee monotonicity.
>>>> ...
>>>> ./share/gc/shared/referenceProcessor.cpp: // os::javaTimeMillis() 
>>>> does not guarantee monotonicity.
>>>>
>>>> These are all describing why the subsequent code uses javaTimeNanos 
>>>> not javaTimeMillis.
>>>> --- end ---
>>>>
>>>> Do we really still support platforms that don't have a monotonic
>>>> clock?  I guess we appear to at least try.  But it's really wrong that
>>>> callers of os::javaTimeNanos should even think they need to cope with
>>>> that function being non-monotonic.
>>>>
>>>> Hm, I always thought System.nanoTime() was a monotonic clock, but I
>>>> don't see any such guarantee. So I guess Java just doesn't have such a
>>>> thing. Wow!
>>>>
>>>> So I guess none of this is really relevant to the change at hand 
>>>> after all.
>>>
>>> I think you read the comments the wrong way round. The code uses 
>>> javaTimeNanos not javaTimeMillis because javaTimeMillis is not 
>>> monotonic and the code wants a monotonic clock. These comments were 
>>> mostly inserted when the incorrect use of javaTimeMillis was replaced 
>>> with javaTimeNanos.
>>>
>>> Thanks,
>>> David
>>> -----
>>>
>>>> ------------------------------------------------------------------------------ 
>>>>
>>>>
>>>>