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