I think I have a solution for this. My solution involves copying most of the the logic in java.time.Clock.SystemClock.instance(). This means accessing the VM class (in misc), so requires some changes to the modules config.
Is there a JIRA ticket for this issue? On Thu, Apr 8, 2021 at 16:10 Ralph Goers <[email protected]> wrote: > 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 > >>>>>>>>> > >>>>>>> > >>>>>>> > >>>>>>> > >>>>> > >>>>> > >>>>> > >>>> > >>>> > >>>> > >>> > >> > >> > >> > > > > > > > > >
