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

[Erik Gahlin]

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.

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