I spoke too soon. It didn’t really pass on Java 16. The allocation instrumenter was unable to instrument anything so it didn’t generate the errors the test looks for. I tried with Java 12-14 and those all failed. In Java 15 the JVM crashed.
Ralph > On Apr 7, 2021, at 11:36 PM, Ralph Goers <[email protected]> wrote: > > I have modified the test to allow -DusePreciseClock=true to be passed in. > When I set it to true and run it in JDK 16 the test passes! However, I tried > 3 versions of JDK 11 and it failed in all of them. > > Ralph > >> On Apr 2, 2021, at 2:54 PM, Ralph Goers <[email protected]> wrote: >> >> I just tried adding logic to call SystemClock.init() 100,000 times. It made >> no difference. The GC test still fails. >> >> Ralph >> >>> On Apr 2, 2021, at 7:18 AM, Carter Kozak <[email protected]> wrote: >>> >>> Escape analysis can take quite a few iterations to take effect, perhaps we >>> need a few more tens of thousands of warmup cycles? Admittedly I haven't >>> taken a look at the failures yet and there's a great deal of subtlety >>> around this. I can try to take a closer look later, unfortunately I've been >>> overwhelmed lately. >>> >>> On Fri, Apr 2, 2021, at 03:59, Ralph Goers wrote: >>>> Looking at the source repo I don’t see anything that changed after support >>>> for the higher precision was added. >>>> >>>> Ralph >>>> >>>>> On Apr 2, 2021, at 12:44 AM, Ralph Goers <[email protected] >>>>> <mailto:ralph.goers%40dslextreme.com>> wrote: >>>>> >>>>> Yes, I was just thinking that. But if there was a bug fix along the way >>>>> that added a single line of code that could now be causing the code not >>>>> to be inlined. >>>>> >>>>> Ralph >>>>> >>>>>> On Apr 2, 2021, at 12:38 AM, Remko Popma <[email protected] >>>>>> <mailto:remko.popma%40gmail.com>> wrote: >>>>>> >>>>>> On Fri, Apr 2, 2021 at 4:26 PM Ralph Goers <[email protected] >>>>>> <mailto:ralph.goers%40dslextreme.com>> >>>>>> wrote: >>>>>> >>>>>>> I will take a look at the link. What you are saying makes sense to a >>>>>>> degree. However, the new is actually performed in Instant.create() >>>>>>> which is >>>>>>> 2 levels down in the call stack. Without having read the link I would >>>>>>> wonder if that qualifies. >>>>>>> >>>>>> >>>>>> That is at the code level, yes. But these get inlined when called >>>>>> sufficiently often. >>>>>> So it is difficult to reason about what is eligible for escape analysis >>>>>> just from the code... >>>>>> >>>>>> >>>>>> >>>>>>> >>>>>>> Ralph >>>>>>> >>>>>>>> On Apr 2, 2021, at 12:00 AM, Remko Popma <[email protected] >>>>>>>> <mailto:remko.popma%40gmail.com>> wrote: >>>>>>>> >>>>>>>> My understanding is that PreciseClock is garbage-free because the JVM >>>>>>> does >>>>>>>> escape analysis. >>>>>>>> Here is the relevant code: >>>>>>>> >>>>>>>> public void init(MutableInstant mutableInstant) { >>>>>>>> Instant instant = java.time.Clock.systemUTC().instant(); >>>>>>>> mutableInstant.initFromEpochSecond(instant.getEpochSecond(), >>>>>>>> instant.getNano()); >>>>>>>> } >>>>>>>> >>>>>>>> The code calls the instant() method, which returns an Instant object. >>>>>>>> We would think that this is not garbage-free, but it magically is >>>>>>>> thanks >>>>>>> to >>>>>>>> escape analysis! >>>>>>>> >>>>>>>> This Instant object is only used within the init(MutableInstant) >>>>>>>> method. >>>>>>>> It is not allowed to "escape": the method accesses fields in Instant, >>>>>>>> and >>>>>>>> passes these primitive values to the initFromEpochSecond method (and >>>>>>>> does >>>>>>>> not pass the Instant object itself). >>>>>>>> >>>>>>>> In theory, JVM escape analysis is able to detect that the object is not >>>>>>>> referenced outside that method, and stops allocating the object >>>>>>> altogether, >>>>>>>> and instead does something called "scalar replacement", where it just >>>>>>> uses >>>>>>>> the values that are actually being used, without putting them in an >>>>>>> object >>>>>>>> first and then getting them out of the object again to use these >>>>>>>> values. >>>>>>>> More details here: https://www.beyondjava.net/escape-analysis-java and >>>>>>>> https://shipilev.net/jvm/anatomy-quarks/18-scalar-replacement/ >>>>>>>> >>>>>>>> I think I tested this on Java 9, and the >>>>>>>> Google java-allocation-instrumenter library could not detect >>>>>>>> allocations. >>>>>>>> >>>>>>>> Has that changed: do the garbage-free tests fail >>>>>>>> for org.apache.logging.log4j.core.util.SystemClock? >>>>>>>> >>>>>>>> Note that when looking at this in a sampling profiler it may show >>>>>>>> allocations. (We actually ran into this in a work project.) >>>>>>>> Profiles tend to disable the optimizations that allow escape analysis, >>>>>>>> so >>>>>>>> our method may show up as allocating when looked at in a profiler, >>>>>>>> while >>>>>>> in >>>>>>>> real life it will not (after sufficient warmup). >>>>>>>> >>>>>>>> >>>>>>>> >>>>>>>> On Fri, Apr 2, 2021 at 2:46 PM Ralph Goers <[email protected] >>>>>>>> <mailto:ralph.goers%40dslextreme.com>> >>>>>>>> wrote: >>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>>>> On Apr 1, 2021, at 10:38 PM, Ralph Goers <[email protected] >>>>>>>>>> <mailto:ralph.goers%40dslextreme.com>> >>>>>>>>> wrote: >>>>>>>>>> >>>>>>>>>> In thinking about this problem I suspect we never noticed that the >>>>>>>>> PreciseClock version of our SystemClock class is not garbage free is >>>>>>>>> because we previously ran all of our unit tests with Java 8. Now that >>>>>>> they >>>>>>>>> are using Java 11 that code is being exercised. >>>>>>>>>> >>>>>>>>>> I’ve looked at java.time.Clock and java.time.Instant. As far as I >>>>>>>>>> know >>>>>>>>> those are the only two classes in Java that provide sub-millisecond >>>>>>>>> granularity. Unfortunately there is no way to call them to extract the >>>>>>>>> field data we need to initialize MutableInstant. I considered >>>>>>>>> modifying >>>>>>> our >>>>>>>>> version of SystemClock to perform the same actions as java.time’s >>>>>>>>> SystemClock but the relevant method there calls >>>>>>>>> jdk.internal.misc.VM.getNanoTimeAdjustment() to correct the >>>>>>> sub-millisecond >>>>>>>>> portion. That is implemented as a native method and seems to only be >>>>>>>>> available to be called by an application when something like >>>>>>>>> --add-opens >>>>>>>>> java.base/jdk.internal.misc=xxx is on the command line. >>>>>>>>>> >>>>>>>>>> I’ve also considered disabling the PreciseClock when garbage free >>>>>>>>>> mode >>>>>>>>> is enabled but as far as I can tell we don’t have a single switch for >>>>>>> that. >>>>>>>>> So I would have to add yet another system property to control it. >>>>>>>>> >>>>>>>>> One other option is to modify the documentation to indicate timestamps >>>>>>> are >>>>>>>>> not garbage free. But this seems awful since virtually every log event >>>>>>> has >>>>>>>>> one. It would make more sense to use the property to determine which >>>>>>>>> to >>>>>>> use >>>>>>>>> so user’s who wish to be garbage free can continue with millisecond >>>>>>>>> granularity. >>>>>>>>> >>>>>>>>> Ralph >>>>>>>>> >>>>>>> >>>>>>> >>>>>>> >>>>> >>>>> >>>>> >>>> >>>> >>>> >>> >> >> >> > > >
