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 <ralph.go...@dslextreme.com > > <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 <remko.po...@gmail.com > >> <mailto:remko.popma%40gmail.com>> wrote: > >> > >> On Fri, Apr 2, 2021 at 4:26 PM Ralph Goers <ralph.go...@dslextreme.com > >> <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 <remko.po...@gmail.com > >>>> <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 <ralph.go...@dslextreme.com > >>>> <mailto:ralph.goers%40dslextreme.com>> > >>>> wrote: > >>>> > >>>>> > >>>>> > >>>>>> On Apr 1, 2021, at 10:38 PM, Ralph Goers <ralph.go...@dslextreme.com > >>>>>> <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 > >>>>> > >>> > >>> > >>> > > > > > > > > >
