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

[David Holmes]

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

> ------------------------------------------------------------------------------
> 
>