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
Does anyone have any thoughts or suggestions on this please? Ralph
On Apr 2, 2021, at 4:47 PM, Ralph Goers <ralph.goers@dslextreme.com> 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
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
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
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.Riggs@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
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.Riggs@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
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> 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.levart@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.Riggs@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
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.goers@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> 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.levart@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.Riggs@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
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.goers@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.goers@dslextreme.com <mailto:ralph.goers@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.levart@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.Riggs@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
I don’t have an account in the bug tracking system. Could someone possibly update the issue noted below to indicate that Apache Log4j 2 would also like that enhancement? Thanks, Ralph
On Apr 5, 2021, at 1:26 PM, Roger Riggs <Roger.Riggs@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
Hi Ralph, I've added an apache-log4j-interest label to the issue. cheers, dalibor topic On 14.04.2021 19:00, Ralph Goers wrote:
I don’t have an account in the bug tracking system. Could someone possibly update the issue noted below to indicate that Apache Log4j 2 would also like that enhancement?
Thanks,
Ralph
On Apr 5, 2021, at 1:26 PM, Roger Riggs <Roger.Riggs@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
-- <http://www.oracle.com> Dalibor Topic Consulting Product Manager Phone: +494089091214 <tel:+494089091214>, Mobile: +491737185961 <tel:+491737185961>, Video: dalibor.topic@oracle.com <sip:dalibor.topic@oracle.com> Oracle Global Services Germany GmbH Hauptverwaltung: Riesstr. 25, D-80992 München Registergericht: Amtsgericht München, HRB 246209 Geschäftsführer: Ralf Herrmann
participants (5)
-
Brian Goetz
-
Dalibor Topic
-
Peter Levart
-
Ralph Goers
-
Roger Riggs