Add `PreciseClock` implementation for JRE 8 systems

[ppkarwasz]

Currently Java 8 users do not have access to timestamps with sub-millisecond precision.
The only PreciseClock implementation is only available in the SystemClock implementation for JRE 9+.

Since that implementation does not use any JDK 9-specific feature, I propose to:

• Move the SystemClock implementation from log4j-core-java9 to log4j-core, overriding the current one.
• Document its effects on garbage-free logging. The implementation of init(MutableInstant):
  

  logging-log4j2/log4j-core-java9/src/main/java/org/apache/logging/log4j/core/util/SystemClock.java

  Lines 42 to 44 in 89c9b9f

  	public void init(final MutableInstant mutableInstant) {
  	final Instant instant = java.time.Clock.systemUTC().instant();
  	mutableInstant.initFromEpochSecond(instant.getEpochSecond(), instant.getNano());

  
  might create a new java.time.Instant instance for each log event, although I am pretty much convinced that the JRE will inline that instance, when the method becomes hot enough.

[jaykataria1111]

Hi @ppkarwasz , if no one is assigned to this issue, can I pick this up? (After writing the openRewrite rule in 2769, did not want to tag the issues' since they are separate.)

[ppkarwasz]

Sure, go ahead!

The task itself is rather easy, but it would be nice if you can add a test that shows that modern JREs perform scalar replacement to the init method above. When the method is hot, I suspect that it should work as if it was implemented using:

 public void init(final MutableInstant mutableInstant) { 
     long epochSecond = ...;
     long nano = ...;
     mutableInstant.initFromEpochSecond(epochSecond, nano);
}

We do use Google's allocation-instrumenter in some tests, but I have no idea how to apply it in this case. @carterkozak, @vy, any ideas? Should we test the allocation impact of SystemClock or should we assume on faith that it could be garbage-free?

[jaykataria1111]

@ppkarwasz for testing here, we just do something of this sorts along with allocation-instrumenter and see the effects? Just add the evidence to the PR, if we have good outcome, or should we do something else?

public void testMethodHotness() {
    MutableInstant mutableInstant = new MutableInstant();
    SystemClock clock = new SystemClock();

    // Call the method 10000 times to ensure it's hot
    for (int i = 0; i < 10000; i++) {
        clock.init(mutableInstant);
    }
}

[vy]

might create a new java.time.Instant instance for each log event, although I am pretty much convinced that the JRE will inline that instance, when the method becomes hot enough.

@ppkarwasz, I don't know of a way to measure/detect this effect.

[ppkarwasz]

might create a new java.time.Instant instance for each log event, although I am pretty much convinced that the JRE will inline that instance, when the method becomes hot enough.

@ppkarwasz, I don't know of a way to measure/detect this effect.

@jaykataria1111, I think we can drop the "hotness" test.

[jaykataria1111]

Hi @ppkarwasz,

It seems like overriding the current implementation of SystemClock break compatibility:

/*
 * Licensed to the Apache Software Foundation (ASF) under one or more
 * contributor license agreements.  See the NOTICE file distributed with
 * this work for additional information regarding copyright ownership.
 * The ASF licenses this file to you under the Apache License, Version 2.0
 * (the "License"); you may not use this file except in compliance with
 * the License.  You may obtain a copy of the License at
 *
 *      http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 */
package org.apache.logging.log4j.core.util;

import java.time.Instant;
import org.apache.logging.log4j.core.time.MutableInstant;
import org.apache.logging.log4j.core.time.PreciseClock;

/**
 * Implementation of the {@code Clock} interface that returns the system time.
 * @since 2.11
 */
public final class SystemClock implements Clock, PreciseClock {

    /**
     * Returns the system time.
     * @return the result of calling {@code System.currentTimeMillis()}
     */
    @Override
    public long currentTimeMillis() {
        return System.currentTimeMillis();
    }

    /**
     * {@inheritDoc}
     */
    @Override
    public void init(final MutableInstant mutableInstant) {
        final Instant instant = java.time.Clock.systemUTC().instant();
        mutableInstant.initFromEpochSecond(instant.getEpochSecond(), instant.getNano());
    }
}

[ERROR] Failed to execute goal biz.aQute.bnd:bnd-baseline-maven-plugin:7.0.0:baseline (check-api-compat) on project log4j-core: An error occurred while calculating the baseline: Baseline problems detected. See the report in /Users/jay/workplace/log4j2/logging-log4j2/log4j-core/target/baseline/log4j-core-2.25.0-SNAPSHOT.txt.
[ERROR] ===============================================================
[ERROR]   Name                                               Type       Delta      New        Old        Suggest    
[ERROR]   org.apache.logging.log4j.core                      BUNDLE     MAJOR      2.25.0.SNAPSHOT 2.24.1     -          
[ERROR] ===============================================================

...
...

[ERROR]     MINOR              CLASS      org.apache.logging.log4j.core.util.SystemClock
[ERROR]       ADDED            IMPLEMENTS org.apache.logging.log4j.core.time.PreciseClock
[ERROR]       ADDED            METHOD     init(org.apache.logging.log4j.core.time.MutableInstant)
[ERROR]         ADDED          RETURN     void

I wonder why, The interesting part is in the context it shows that it is a MINOR , but at the bundle level, it shows MAJOR, I did some research, and realized that adding an interface, does not break the binary or the source compatibility. I did some looking around and saw maybe code relying on runtime reflection to inspect the class's interfaces may behave differently. But would you know if people are consuming the Clock interface or PreciseClock interface in such a way? Also what are the other scenarios it could break MAJOR compatibility? would you know, it would be a great learning opportunity for me!

[ppkarwasz]

[ERROR] ===============================================================
[ERROR]   Name                                               Type       Delta      New        Old        Suggest    
[ERROR]   org.apache.logging.log4j.core                      BUNDLE     MAJOR      2.25.0.SNAPSHOT 2.24.1     -          
[ERROR] ===============================================================
...

I wonder why, The interesting part is in the context it shows that it is a MINOR , but at the bundle level, it shows MAJOR,

I am not sure, what the delta at the bundle level means, but it is certainly not related to the Java public API.

The build failure is probably due to the MINOR change in the package, which must be reflected in a change to the package version. Package versions are hardcoded in a @Version annotation in the apposite package-info.java file. See Fixing API compatibility check failures for more information.

In this case you should bump the version number to 2.25.0:

@Export
@Version("2.25.0")
package org.apache.logging.log4j.core.util;

[jaykataria1111]

Hi @ppkarwasz , opened a PR, for the purpose :), Thanks got to know that you have to manually update the version appreciate it!

[jaykataria1111]

@ppkarwasz can this be closed?