Well, after digging deeper it seems 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:33 PM, Ralph Goers <ralph.go...@dslextreme.com> wrote: > > Interesting. I ran the test with > > openjdk version "16" 2021-03-16 > OpenJDK Runtime Environment (build 16+36-2231) > OpenJDK 64-Bit Server VM (build 16+36-2231, mixed mode, sharing) > > and it passed. I then ran it with > > openjdk version "11.0.2" 2019-01-15 > OpenJDK Runtime Environment 18.9 (build 11.0.2+9) > OpenJDK 64-Bit Server VM 18.9 (build 11.0.2+9, mixed mode) > > and > > java version "11.0.9" 2020-10-20 LTS > Java(TM) SE Runtime Environment 18.9 (build 11.0.9+7-LTS) > Java HotSpot(TM) 64-Bit Server VM 18.9 (build 11.0.9+7-LTS, mixed mode) > > and > > java version "11.0.10" 2021-01-19 LTS > Java(TM) SE Runtime Environment 18.9 (build 11.0.10+8-LTS-162) > Java HotSpot(TM) 64-Bit Server VM 18.9 (build 11.0.10+8-LTS-162, mixed mode) > > and it failed with all of them. > > Ralph > > >> On Apr 6, 2021, at 3:22 PM, Ralph Goers <ralph.go...@dslextreme.com >> <mailto:ralph.go...@dslextreme.com>> wrote: >> >> I am using >> >> openjdk version "11.0.10" 2021-01-19 LTS >> OpenJDK Runtime Environment Corretto-11.0.10.9.1 (build 11.0.10+9-LTS) >> OpenJDK 64-Bit Server VM Corretto-11.0.10.9.1 (build 11.0.10+9-LTS, mixed >> mode) >> >> Our test uses >> <dependency> >> <groupId>com.google.code.java-allocation-instrumenter</groupId> >> <artifactId>java-allocation-instrumenter</artifactId> >> <version>3.3.0</version> >> </dependency> >> to validate that it is not allocating any objects. >> >> If you want to test it yourself you can do >> >> git clone https://github.com/apache/logging-log4j2.git >> <https://github.com/apache/logging-log4j2.git> >> <https://github.com/apache/logging-log4j2.git >> <https://github.com/apache/logging-log4j2.git>> >> cd logging-log4j2 >> mvn -DskipTests=true clean install >> cd log4j-core >> mvn surefire:test -Dtest=GcFreeSynchronousLoggingTest >> -Dmaven.surefire.debug="-Dlog4j2.usePreciseClock=true” >> >> When it fails you will see a strange message with >> >> I just allocated the object 2021-04-06T21:55:20.878377Z of type >> java/time/Instant whose size is 24 ==> expected: <true> but was: <false> >> >> Ralph >> >>> On Apr 6, 2021, at 9:53 AM, Peter Levart <peter.lev...@gmail.com> wrote: >>> >>> Hi Ralph, >>> >>> >>> Which version of JDK did you try running the code. I tried the following >>> benchmark: >>> >>> >>> @BenchmarkMode(Mode.AverageTime) >>> @Fork(value = 1) >>> @Warmup(iterations = 5, time = 1) >>> @Measurement(iterations = 10, time = 1) >>> @OutputTimeUnit(TimeUnit.NANOSECONDS) >>> @State(Scope.Benchmark) >>> public class InstantBench { >>> >>> @Benchmark >>> public long epochMilli() { >>> Instant instant = Clock.systemUTC().instant(); >>> return instant.toEpochMilli(); >>> } >>> } >>> >>> >>> And didn't get any heap allocation on either JDK 11: >>> >>> >>> Benchmark Mode Cnt Score Error Units >>> InstantBench.epochMilli avgt 10 34.722 ± 0.328 >>> ns/op >>> InstantBench.epochMilli:·gc.alloc.rate avgt 10 ≈ 10⁻⁴ >>> MB/sec >>> InstantBench.epochMilli:·gc.alloc.rate.norm avgt 10 ≈ 10⁻⁵ >>> B/op >>> InstantBench.epochMilli:·gc.count avgt 10 ≈ 0 >>> counts >>> >>> >>> ..nor on JDK 16: >>> >>> >>> Benchmark Mode Cnt Score Error Units >>> InstantBench.epochMilli avgt 10 33.612 ± 0.258 >>> ns/op >>> InstantBench.epochMilli:·gc.alloc.rate avgt 10 ≈ 10⁻⁴ >>> MB/sec >>> InstantBench.epochMilli:·gc.alloc.rate.norm avgt 10 ≈ 10⁻⁵ >>> B/op >>> InstantBench.epochMilli:·gc.count avgt 10 ≈ 0 >>> counts >>> >>> >>> Regards, Peter >>> >>> On 4/6/21 8:17 AM, Ralph Goers wrote: >>>> Yes, I am aware that the Instant is constructed from the two values. That >>>> is exactly why I was hoping I could pass in an object where the values of >>>> those two fields could be injected. This would still allow Instant to be >>>> immutable but allow Log4j to update one of the pre-existing Clock >>>> instances it is managing. That would require that a new Interface be >>>> defined with the two set methods and a new static method in the Clock >>>> class. >>>> >>>> Getting the value in microseconds would probably be a middle ground that >>>> could also work considering that is the best resolution available on most >>>> hardware today. >>>> >>>> Whichever is implemented I suspect getting it back ported to Java 11 is >>>> unlikely? According to the surveys I’ve seen the majority of users are >>>> still on Java 8. Given that, I’d be surprised if there is a mad rush to >>>> adopt Java 17 very soon. Given where things are I’m not even sure how >>>> likely it is this could make it in for Java 17. The irony here is that >>>> the folks who need to run garbage free are also the ones most likely to >>>> need a Clock with higher resolution. Right now they can’t have both. >>>> >>>> Ralph >>>> >>>>> On Apr 5, 2021, at 1:26 PM, Roger Riggs <roger.ri...@oracle.com> wrote: >>>>> >>>>> Hi, >>>>> >>>>> Java does not have a data type with enough resolution to hold a full >>>>> nanosecond value. >>>>> Hence the implementation of Instant holding seconds and nanos. >>>>> >>>>> There is an long dormant enhancement request to return micro-seconds as a >>>>> long. >>>>> 8196003 <https://bugs.openjdk.java.net/browse/JDK-8196003> java.time >>>>> Instant and Duration methods for microseconds >>>>> >>>>> That might be useful if the application gets enough resolution from >>>>> microseconds. >>>>> There might be some clever interpolation between >>>>> System.currentTimeMillis() >>>>> and adjusting with System.nanoTime(). >>>>> Though it would likely not be exactly synchronized with the values from >>>>> Instant. >>>>> >>>>> Regards, Roger >>>>> >>>>> >>>>> On 4/5/21 3:56 PM, Brian Goetz wrote: >>>>>> Project Valhalla will allow Instant to be migrated to a primitive class, >>>>>> which would address your problem. >>>>>> >>>>>> On 4/2/2021 7:47 PM, Ralph Goers wrote: >>>>>>> Log4j 2 supports the notion of a PreciseClock - one that can be >>>>>>> initialized to something more precise than a millisecond. At the same >>>>>>> time it also supports running with no heap allocations in certain >>>>>>> circumstances. I am in the process of moving our master branch to >>>>>>> require Java 11 as the minimum. In doing so I am encountering unit test >>>>>>> errors while verifying that logging is garbage free. They all occur >>>>>>> allocating an Instant. >>>>>>> >>>>>>> The code we have simply does >>>>>>> >>>>>>> public void init(MutableInstant mutableInstant) { >>>>>>> Instant instant = java.time.Clock.systemUTC().instant(); >>>>>>> mutableInstant.initFromEpochSecond(instant.getEpochSecond(), >>>>>>> instant.getNano()); >>>>>>> } >>>>>>> In our previous tests we had thought the allocation was being >>>>>>> eliminated due to escape analysis since the data is being extracted >>>>>>> from the Instant and not passed along. However, after upgrading the >>>>>>> Google test library and the JDK version it appears that is not the case. >>>>>>> Ideally we would really like something like >>>>>>> >>>>>>> public void init(MutableInstant mutableInstant) { >>>>>>> java.time.Clock.systemUTC().initInstant(mutableInstant); >>>>>>> } >>>>>>> >>>>>>> where Mutable instant would implement an interface that has the two set >>>>>>> methods.The method would execute the same logic that is in the >>>>>>> instant() method but instead of creating a new Instant it would call >>>>>>> the set methods for the provided object. >>>>>>> >>>>>>> This would allow us to either have the MutableInstants in ThreadLocals >>>>>>> or some other mechanism to ensure they are thread safe and have no heap >>>>>>> allocations. As it stands now I see no way to gain access to the higher >>>>>>> precision clock without memory allocation. >>>>>>> >>>>>>> Do you know of another way to do this? Am I missing something? >>>>>>> >>>>>>> Ralph
