I filed a bug report with OpenJDK but have not gotten a response yet. It isn’t viewable in their Jira system until it goes through triage.
I considered what you are proposing but decided against it because I don’t believe that will be allowed without runtime flags, so it cannot be enabled by default. Ralph > On Apr 20, 2021, at 5: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 >>>>>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>> >>>>>>> >>>>>>> >>>>>> >>>>>> >>>>>> >>>>> >>>> >>>> >>>> >>> >>> >>> >> >> >>
