Master is merged

[Ralph Goers]

I’ve merged the Java 11 changes to the master branch. To summarize:
Toolchains are no longer required.
Java11 (or later?) is required to build and run. However, I have only tried 
with Java 11. 
Log4j-api and log4j-plugins are JPMS modules. Log4j-core will be attacked next. 
We will want to review the classes being exported and determine which should be 
moved to non-exported packages.
Log4j-osgi tests are passing
SystemClock requires -Dlog4j2.usePreciseClock=true to enable the finer grained 
clock resolution. The price for that is that it is not garbage free. At the 
recommendation of Stephen Colebourne I have sent a message to the JDK 
core-libs-dev mailing list to see if there is anything that can be done. I 
suspect if there is it won’t be in Java 11 and I would be lucky to get it in 
Java 17.

I have also been messing with the GitHub Actions configuration. Two of the 
three jobs have been timing out because they simply take too long.

After log4j-core is converted to a JPMS module I am imagining migrating the 
rest that we want to do will be straightforward.

Ralph

Re: Please do not commit to log4j2 master - but review this PR.

[Ralph Goers]

I was able to fix the OSGi tests simply by upgrading the Maven Bundle Plugin.

The Warning message coming from the compiler plugin was because the 
module-info.java file had a requires transitive org.osgi.core and OSGi core is 
not a JPMS module. But that really isn’t correct since JPMS and OSGi don’t 
happen at the same time. So I omitted that from the module-info.java. 

Ralph

> On Apr 2, 2021, at 3:07 PM, Matt Sicker  wrote:
> 
> The maven verify error is something that affects the master branch too.
> Something to do with snapshots and depending on them inter-module. I don’t
> know enough about maven to explain why, but some modules require other
> modules to have been installed and not just packaged.
> 
> On Fri, Apr 2, 2021 at 17:04 Ralph Goers  wrote:
> 
>> Well, log4j-api, log4j-plugins and log4j-core each have unit tests and
>> test classes that are used by other log4j-modules. Because log4j-api and
>> log4j-plugins are JPMS modules the unit tests need to a) either be in a
>> different package or b) have a module-info.java that essentially extends
>> the real module. Because several of the unit tests access package private
>> methods I had to go with option b. But that would mean the test classes
>> that have to be passed downstream needed to be in a different package. So I
>> moved all those classes to their own java-test directory and appended .test
>> to the base package. Then it became a bit tricky to get those compiled and
>> packaged into a test jar without including the unit tests.  So you end up
>> with this weird structure with two test source directories.
>> 
>> The test jars need to be installed in order for them to be used by the
>> other log4j modules that follow. I see no reason they cannot be published.
>> They contain some useful stuff that others could use for unit testing if
>> they wanted.
>> 
>> I will look into the mvn verify error. It might be related to what Tim
>> reported. mvn install worked for me. I’m not sure why Ubuntu would be
>> different than MacOS.
>> 
>> Ralph
>> 
>>> On Apr 2, 2021, at 12:50 PM, Volkan Yazıcı 
>> wrote:
>>> 
>>> Great work Ralph!
>>> Your change set marks an important milestone in Log4j development.
>>> Thanks so much!
>>> 
>>> `./mvnw verify` fails for me while compiling the 2nd module, log4j-api:
>>> `error: module not found: org.osgi.core`. Any ideas?
>>> This said `./mvnw package` succeeds for me, hence all(?) tests pass.
>>> 
>>> $ java -version
>>> openjdk version "11.0.10" 2021-01-19
>>> OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.10+9)
>>> OpenJDK 64-Bit Server VM AdoptOpenJDK (build 11.0.10+9, mixed mode)
>>> 
>>> $ lsb_release -a
>>> No LSB modules are available.
>>> Distributor ID: Ubuntu
>>> Description: Ubuntu 20.10
>>> Release: 20.10
>>> Codename: groovy
>>> 
>>> I have a remark/question regarding removed test-jars. If I am not
>> mistaken
>>> test-jars were only used for testing purposes, so these *-test modules
>> you
>>> have introduced. For one, I am happy to see that test-jars were replaced
>>> with normal module artifacts, at least just for these. Test-jars were
>>> difficult to get right, producing cryptic dependency failures, and not an
>>> often-practiced part of the Maven rituals. This said, shall we prevent
>> them
>>> from getting published? That is, do we need to publish them to the Maven
>>> Central, given they are only needed for internal testing?
>>> 
>>> On Mon, Mar 29, 2021 at 1:24 AM Ralph Goers 
>>> wrote:
>>> 
 I have created https://github.com/apache/logging-log4j2/pull/480 for
>> you
 to review. It has many changes and merge conflicts will be painful to
>> fix
 so please do not commit to master until this PR is merged.
 
 Although I could merge this now I would prefer if you could checkout the
 branch on your local machines, build, and test it. I haven’t tested it
>> with
 anything real yet but all the unit tests - except for the osgi module -
 pass.
 
 If you open this in your IDE you might have some issues with some test
 classes being flagged as having compile issues. This is because of the
 weird extra directory I had to include in log4j-api and log4j-plugins to
 create test jars.
 
 Please provide feedback so I can make any changes and get this merged.
 
 Ralph
 
>> 
>> 
>> 

Re: Please do not commit to log4j2 master - but review this PR.

[Matt Sicker]

The maven verify error is something that affects the master branch too.
Something to do with snapshots and depending on them inter-module. I don’t
know enough about maven to explain why, but some modules require other
modules to have been installed and not just packaged.

On Fri, Apr 2, 2021 at 17:04 Ralph Goers  wrote:

> Well, log4j-api, log4j-plugins and log4j-core each have unit tests and
> test classes that are used by other log4j-modules. Because log4j-api and
> log4j-plugins are JPMS modules the unit tests need to a) either be in a
> different package or b) have a module-info.java that essentially extends
> the real module. Because several of the unit tests access package private
> methods I had to go with option b. But that would mean the test classes
> that have to be passed downstream needed to be in a different package. So I
> moved all those classes to their own java-test directory and appended .test
> to the base package. Then it became a bit tricky to get those compiled and
> packaged into a test jar without including the unit tests.  So you end up
> with this weird structure with two test source directories.
>
> The test jars need to be installed in order for them to be used by the
> other log4j modules that follow. I see no reason they cannot be published.
> They contain some useful stuff that others could use for unit testing if
> they wanted.
>
> I will look into the mvn verify error. It might be related to what Tim
> reported. mvn install worked for me. I’m not sure why Ubuntu would be
> different than MacOS.
>
> Ralph
>
> > On Apr 2, 2021, at 12:50 PM, Volkan Yazıcı 
> wrote:
> >
> > Great work Ralph!
> > Your change set marks an important milestone in Log4j development.
> > Thanks so much!
> >
> > `./mvnw verify` fails for me while compiling the 2nd module, log4j-api:
> > `error: module not found: org.osgi.core`. Any ideas?
> > This said `./mvnw package` succeeds for me, hence all(?) tests pass.
> >
> > $ java -version
> > openjdk version "11.0.10" 2021-01-19
> > OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.10+9)
> > OpenJDK 64-Bit Server VM AdoptOpenJDK (build 11.0.10+9, mixed mode)
> >
> > $ lsb_release -a
> > No LSB modules are available.
> > Distributor ID: Ubuntu
> > Description: Ubuntu 20.10
> > Release: 20.10
> > Codename: groovy
> >
> > I have a remark/question regarding removed test-jars. If I am not
> mistaken
> > test-jars were only used for testing purposes, so these *-test modules
> you
> > have introduced. For one, I am happy to see that test-jars were replaced
> > with normal module artifacts, at least just for these. Test-jars were
> > difficult to get right, producing cryptic dependency failures, and not an
> > often-practiced part of the Maven rituals. This said, shall we prevent
> them
> > from getting published? That is, do we need to publish them to the Maven
> > Central, given they are only needed for internal testing?
> >
> > On Mon, Mar 29, 2021 at 1:24 AM Ralph Goers 
> > wrote:
> >
> >> I have created https://github.com/apache/logging-log4j2/pull/480 for
> you
> >> to review. It has many changes and merge conflicts will be painful to
> fix
> >> so please do not commit to master until this PR is merged.
> >>
> >> Although I could merge this now I would prefer if you could checkout the
> >> branch on your local machines, build, and test it. I haven’t tested it
> with
> >> anything real yet but all the unit tests - except for the osgi module -
> >> pass.
> >>
> >> If you open this in your IDE you might have some issues with some test
> >> classes being flagged as having compile issues. This is because of the
> >> weird extra directory I had to include in log4j-api and log4j-plugins to
> >> create test jars.
> >>
> >> Please provide feedback so I can make any changes and get this merged.
> >>
> >> Ralph
> >>
>
>
>

Re: Please do not commit to log4j2 master - but review this PR.

[Ralph Goers]

Well, log4j-api, log4j-plugins and log4j-core each have unit tests and test 
classes that are used by other log4j-modules. Because log4j-api and 
log4j-plugins are JPMS modules the unit tests need to a) either be in a 
different package or b) have a module-info.java that essentially extends the 
real module. Because several of the unit tests access package private methods I 
had to go with option b. But that would mean the test classes that have to be 
passed downstream needed to be in a different package. So I moved all those 
classes to their own java-test directory and appended .test to the base 
package. Then it became a bit tricky to get those compiled and packaged into a 
test jar without including the unit tests.  So you end up with this weird 
structure with two test source directories.

The test jars need to be installed in order for them to be used by the other 
log4j modules that follow. I see no reason they cannot be published. They 
contain some useful stuff that others could use for unit testing if they wanted.

I will look into the mvn verify error. It might be related to what Tim 
reported. mvn install worked for me. I’m not sure why Ubuntu would be different 
than MacOS.

Ralph

> On Apr 2, 2021, at 12:50 PM, Volkan Yazıcı  wrote:
> 
> Great work Ralph!
> Your change set marks an important milestone in Log4j development.
> Thanks so much!
> 
> `./mvnw verify` fails for me while compiling the 2nd module, log4j-api:
> `error: module not found: org.osgi.core`. Any ideas?
> This said `./mvnw package` succeeds for me, hence all(?) tests pass.
> 
> $ java -version
> openjdk version "11.0.10" 2021-01-19
> OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.10+9)
> OpenJDK 64-Bit Server VM AdoptOpenJDK (build 11.0.10+9, mixed mode)
> 
> $ lsb_release -a
> No LSB modules are available.
> Distributor ID: Ubuntu
> Description: Ubuntu 20.10
> Release: 20.10
> Codename: groovy
> 
> I have a remark/question regarding removed test-jars. If I am not mistaken
> test-jars were only used for testing purposes, so these *-test modules you
> have introduced. For one, I am happy to see that test-jars were replaced
> with normal module artifacts, at least just for these. Test-jars were
> difficult to get right, producing cryptic dependency failures, and not an
> often-practiced part of the Maven rituals. This said, shall we prevent them
> from getting published? That is, do we need to publish them to the Maven
> Central, given they are only needed for internal testing?
> 
> On Mon, Mar 29, 2021 at 1:24 AM Ralph Goers 
> wrote:
> 
>> I have created https://github.com/apache/logging-log4j2/pull/480 for you
>> to review. It has many changes and merge conflicts will be painful to fix
>> so please do not commit to master until this PR is merged.
>> 
>> Although I could merge this now I would prefer if you could checkout the
>> branch on your local machines, build, and test it. I haven’t tested it with
>> anything real yet but all the unit tests - except for the osgi module -
>> pass.
>> 
>> If you open this in your IDE you might have some issues with some test
>> classes being flagged as having compile issues. This is because of the
>> weird extra directory I had to include in log4j-api and log4j-plugins to
>> create test jars.
>> 
>> Please provide feedback so I can make any changes and get this merged.
>> 
>> Ralph
>> 

Re: Garbage Free Precise Time

[Ralph Goers]

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  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 >> > 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 >>> > wrote:
 
 On Fri, Apr 2, 2021 at 4:26 PM Ralph Goers >>> >
 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 > > 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 > >
>> wrote:
>> 
>>> 
>>> 
 On Apr 1, 2021, at 10:38 PM, Ralph Goers >>> >
>>> 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.getNanoTimeAd

Re: Please do not commit to log4j2 master - but review this PR.

[Volkan Yazıcı]

Great work Ralph!
Your change set marks an important milestone in Log4j development.
Thanks so much!

`./mvnw verify` fails for me while compiling the 2nd module, log4j-api:
`error: module not found: org.osgi.core`. Any ideas?
This said `./mvnw package` succeeds for me, hence all(?) tests pass.

$ java -version
openjdk version "11.0.10" 2021-01-19
OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.10+9)
OpenJDK 64-Bit Server VM AdoptOpenJDK (build 11.0.10+9, mixed mode)

$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 20.10
Release: 20.10
Codename: groovy

I have a remark/question regarding removed test-jars. If I am not mistaken
test-jars were only used for testing purposes, so these *-test modules you
have introduced. For one, I am happy to see that test-jars were replaced
with normal module artifacts, at least just for these. Test-jars were
difficult to get right, producing cryptic dependency failures, and not an
often-practiced part of the Maven rituals. This said, shall we prevent them
from getting published? That is, do we need to publish them to the Maven
Central, given they are only needed for internal testing?

On Mon, Mar 29, 2021 at 1:24 AM Ralph Goers 
wrote:

> I have created https://github.com/apache/logging-log4j2/pull/480 for you
> to review. It has many changes and merge conflicts will be painful to fix
> so please do not commit to master until this PR is merged.
>
> Although I could merge this now I would prefer if you could checkout the
> branch on your local machines, build, and test it. I haven’t tested it with
> anything real yet but all the unit tests - except for the osgi module -
> pass.
>
> If you open this in your IDE you might have some issues with some test
> classes being flagged as having compile issues. This is because of the
> weird extra directory I had to include in log4j-api and log4j-plugins to
> create test jars.
>
> Please provide feedback so I can make any changes and get this merged.
>
> Ralph
>

Re: Garbage Free Precise Time

[Carter Kozak]

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  > > 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  >> > wrote:
> >> 
> >> On Fri, Apr 2, 2021 at 4:26 PM Ralph Goers  >> >
> >> 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   > 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   >
>  wrote:
>  
> > 
> > 
> >> On Apr 1, 2021, at 10:38 PM, Ralph Goers  >> >
> > 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 --a

Re: Garbage Free Precise Time

[Ralph Goers]

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  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  wrote:
>> 
>> On Fri, Apr 2, 2021 at 4:26 PM Ralph Goers 
>> 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  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 
 wrote:
 
> 
> 
>> On Apr 1, 2021, at 10:38 PM, Ralph Goers 
> 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
> 
>>> 
>>> 
>>> 
> 
> 
> 

Re: Garbage Free Precise Time

[Ralph Goers]

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  wrote:
> 
> On Fri, Apr 2, 2021 at 4:26 PM Ralph Goers 
> 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  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 
>>> wrote:
>>> 
 
 
> On Apr 1, 2021, at 10:38 PM, Ralph Goers 
 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
 
>> 
>> 
>> 

Re: Garbage Free Precise Time

[Remko Popma]

On Fri, Apr 2, 2021 at 4:26 PM Ralph Goers 
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  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 
> > wrote:
> >
> >>
> >>
> >>> On Apr 1, 2021, at 10:38 PM, Ralph Goers 
> >> 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
> >>
>
>
>

OpenJDK 17 Early Access build 16 is now available

[Rory O'Donnell]

Hi Ralph,

*OpenJDK 17 Early Access build 16 is now available at 
**http://jdk.java.net/17* 


 * These early-access , open-source builds are provided under the
 o GNU General Public License, version 2, with the Classpath
   Exception 

 * Schedule (proposed)
 o 2021/06/10         Rampdown Phase One
 o 2021/07/15         Rampdown Phase Two
 o 2021/08/05         Initial Release Candidate
 o 2021/08/19         Final Release Candidate
 o 2021/09/14         General Availability

 * Features:*Heads-up on an important Candidate JEP
   *
 o *Candidate - JEP 403: **Strongly Encapsulate JDK Internals
   *
 o successor to JEP 396: Strongly Encapsulate JDK Internals by
   Default 
 o strongly encapsulate all internal elements of the JDK by default
 o exception for Critical Internal APIs such as /sun.misc.Unsafe/

 * JEPs targeted to JDK 17, so far:
 o JEP 356: Enhanced Pseudo-Random Number Generators
   
 o JEP 382: New macOS Rendering Pipeline
   
 o JEP 391: macOS/AArch64 Port 
 o JEP 398: Deprecate the Applet API for Removal
   

 * Release Notes are available at http://jdk.java.net/17/release-notes
   
 * Changes in recent builds that maybe of interest:
 o Build 16
 + JDK-8263898: (fs) Files.newOutputStream on the "NUL" special
   device throws FileSystemException: "nul: Incorrect function"
   (win)
 # Reported by Apache Ant
 o Build 15
 + JDK-8263575: Conflict between JDK rpms and OL8 Modularity
   prevents dnf install/updates
 o Build 14
 + JDK-8262277: URLClassLoader.getResource throws undocumented
   IllegalArgumentException
 + JDK-8262351: Extra '0' in java.util.Formatter for '%012a'
   conversion with a sign character

*Project Loom Early-Access Build: **Build 17-loom+5-191* 
*(2021/3/19)*


 * These early-access builds are provided under the GNU General Public
   License, version 2, with the Classpath Exception
   .
 * These builds are produced for the purpose of gathering feedback. Use
   for any other purpose is at your own risk.
 * Please send feedback via e-mail to loom-...@openjdk.java.net
   . To send e-mail to this address
   you must first subscribe to the mailing list
   .

*Quality Report for March 2021 was published here [1]*.

 * Thanks to everyone who contributed by creating features or
   enhancements, logging  bugs, or downloading and testing the
   early-access builds.

*Worth reading - **The Arrival of Java 16! 
*


 * JDK 16 Migration guide -
   https://docs.oracle.com/en/java/javase/16/migrate/getting-started.html
 * #AllTestsGreenOnJDK16 - If your tests are green on JDK 16 please
   respond to this *tweet
   *.
 * Oracle Developer Live event - Individual sessions:
1. *Java 16: Consistency and Innovation* (Aurelio Garcia-Ribeyro):
   https://youtu.be/1acKCBbd6f4 
2. *Java Language Futures: Spring 2021* (Gavin Bierman):
   https://youtu.be/K9SVV0XNIP8 
3. *Ask the Java Architects* (Mark Reinhold, Brian Goetz, Mikael
   Vidstedt, Ron Pressler): https://youtu.be/CVE4bWvuD3o
   
4. *Learn Java 16 with IntelliJ IDEA *(Trisha Gee[JetBrains])*:
   *https://youtu.be/1hyWJTjxeGM **
5. *How Records Can Improve Serialization* (Julia Boes, Chris
   Hegarty): https://youtu.be/44D8M6ZxuLU
   
6. *Vector API: SIMD Programming in Java* (Paul Sandoz, Sandhya
   Viswanathan[Intel]): https://youtu.be/VYo3p4R66N8
   
7. *Your Guide to OpenJDK Development* (Jesper Wilhelmsson):
   https://youtu.be/bHcKTYy_Nec 
8. *Project Skara: Migrating OpenJDK to Git and GitHub* (Erik
   Duveblad, Robin Westberg): https://youtu.be/-pBgplk7fVk
   
9. *Monitoring and Troubleshooting Tools in the JDK* (Poonam
   Parhar): https://youtu.be/mcfubUmbZhQ 
   10. *Fast and Efficient Microservices for Java with GraalVM* (Alina
   Yurenko): https://youtu.be/_eRD6qJqtNw
   
   11. *Accelerating Productivity with Micronaut and Java Records*
   (Graeme Rocher): https://youtu.be/RoNeo

Re: Garbage Free Precise Time

[Ralph Goers]

I should also add that I tested with Amazon Correto

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)

This is what my employer has decided to use since AdoptOpenJDK doesn’t have 
access to the Java test kit so can’t be Java certified.  Although I have 
Oracle’s Java 11 installed I rarely use it due to the licensing issues.

Ralph

> On Apr 2, 2021, at 12:25 AM, Ralph Goers  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.
> 
> Ralph
> 
>> On Apr 2, 2021, at 12:00 AM, Remko Popma  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 
>> wrote:
>> 
>>> 
>>> 
 On Apr 1, 2021, at 10:38 PM, Ralph Goers 
>>> 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
>>> 
> 
> 
> 

Re: Garbage Free Precise Time

[Ralph Goers]

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.

Ralph

> On Apr 2, 2021, at 12:00 AM, Remko Popma  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 
> wrote:
> 
>> 
>> 
>>> On Apr 1, 2021, at 10:38 PM, Ralph Goers 
>> 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
>> 

Re: Garbage Free Precise Time

[Ralph Goers]

That isn’t the case when I ran it with Java 11 and the latest version of the 
allocation tool. Virtually everything failed since almost everything creates a 
timestamp.

I would suggest you checkout the master-java11 branch, uncomment the stuff in 
the SystemClock class and try it yourself.

Ralph

> On Apr 2, 2021, at 12:00 AM, Remko Popma  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 
> wrote:
> 
>> 
>> 
>>> On Apr 1, 2021, at 10:38 PM, Ralph Goers 
>> 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
>> 

Re: Garbage Free Precise Time

[Remko Popma]

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 
wrote:

>
>
> > On Apr 1, 2021, at 10:38 PM, Ralph Goers 
> 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
>