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]> 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]> wrote: >> >> On Fri, Apr 2, 2021 at 4:26 PM Ralph Goers <[email protected]> >> 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]> 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]> >>>> wrote: >>>> >>>>> >>>>> >>>>>> On Apr 1, 2021, at 10:38 PM, Ralph Goers <[email protected]> >>>>> 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 >>>>> >>> >>> >>> > > >
