Garbage Free Check

classic Classic list List threaded Threaded
9 messages Options
Reply | Threaded
Open this post in threaded view
|

Garbage Free Check

Ralph Goers
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
Reply | Threaded
Open this post in threaded view
|

Re: Garbage Free Clock

Ralph Goers
Does anyone have any thoughts or suggestions on this please?

Ralph

> On Apr 2, 2021, at 4:47 PM, Ralph Goers <[hidden email]> 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


Reply | Threaded
Open this post in threaded view
|

Re: Garbage Free Check

Brian Goetz-2
In reply to this post by Ralph Goers
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

Reply | Threaded
Open this post in threaded view
|

Re: Garbage Free Check

roger riggs
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
>

Reply | Threaded
Open this post in threaded view
|

Re: Garbage Free Check

Ralph Goers
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 <[hidden email]> 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
>>
>
>


Reply | Threaded
Open this post in threaded view
|

Re: Garbage Free Check

Peter Levart
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 <[hidden email]> 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
>>
>
Reply | Threaded
Open this post in threaded view
|

Re: Garbage Free Check

Ralph Goers
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 <[hidden email]> 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 <[hidden email]> 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
>>>
>>
>

Reply | Threaded
Open this post in threaded view
|

Re: Garbage Free Check

Ralph Goers
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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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
>>>>
>>>
>>
>
>


Reply | Threaded
Open this post in threaded view
|

Re: Garbage Free Check

Ralph Goers
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 <[hidden email]> 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 <[hidden email] <mailto:[hidden email]>> 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 <[hidden email]> 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 <[hidden email]> 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