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

[David Holmes]

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