Man he's keeping me from getting a job On Tue, Apr 20, 2021, 8:03 AM Remko Popma <[email protected]> wrote:
> 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 > > >>>>>>>>> > > >>>>>>> > > >>>>>>> > > >>>>>>> > > >>>>> > > >>>>> > > >>>>> > > >>>> > > >>>> > > >>>> > > >>> > > >> > > >> > > >> > > > > > > > > > > > > > > > >
