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