feat: static loggers initialisation

[qoomon]

This new logger {} method

private vql LOGGER = logger {}
class X {
    // LOGGER.info("hello world")
}

compiles to a real static java field

private static final KotlinLogger LOG = logger((Function0)null.INSTANCE);

where as

class X {
    // LOGGER.info("hello world")
    companion object {
         private val LOGGER = logger()
    }
}

compiles to something like this, which leads to multiple method invocations everytime the logger is used

public static final class Companion implements Logging {
      public KotlinLogger getLogger() {
           return DefaultImpls.getLogger(this);
      }
}

[jvz]

Could you add any tests or docs about this?

[qoomon]

What do you mean by documentation, I already added some. Regarding tests, I will add some.

[qoomon]

test is there now

[jvz]

Documentation is in src/site/asciidoc/ and src/site/markdown/ depending on file format.

[qoomon]

Before I update documentation can you give some feedback about the solution in general. And what about the problem with non const fields in companion objects.

[jvz]

@rocketraman can you have a look?

The idea sounds legit, but I haven't kept up with Kotlin for the past couple years, so let's see what Raman has to say.

[rocketraman]

@qoomon Help me understand the issue here. Aren't you comparing apples and oranges? You are comparing a top-level logger instantiation with a companion object instantiation. The current mechanism for a top-level instantiation is using a named logger something like this:

val LOGGER = logger("Bar")

which generates exactly the same bytecode as your new method... e.g. with this code:

val LOGGER1 = logger("Bar")
val LOGGER2 = logger {}

class Foo {
  fun bar() {
    LOGGER1.debug { "Something" }
    LOGGER2.debug { "Something" }
  }
}

I don't see any difference in the bytecode between LOGGER1 and LOGGER2: both are real static fields, and both are invoked in the same way.

If I'm not missing something with my analysis, then what we have left with this pull is a feature: that of being able to generate a top-level logger without specifying a name (using the { } instead). Its debatable to me whether or not this feature is worth the extra complexity, and it is certainly not very discoverable. I'd lean towards just creating methods like this as functions in your own code. @jvz thoughts?

[jvz]

I suppose that depends on how common it is to use Kotlin in a top level context like that. Outside standalone scripts or gradle builds, is that common? And are those use cases common?

[rocketraman]

I suppose that depends on how common it is to use Kotlin in a top level context like that. Outside standalone scripts or gradle builds, is that common? And are those use cases common?

It's not super-common in my code bases -- my top-level functions tend to be things that don't and shouldn't need logging, as they are very general.

However, the OP could be using the top-level function as a performance optimization rather than as a functional necessity. Probably needs some micro-benchmarking to determine if there really is any perf savings compared to the usual companion object mechanism.

[rocketraman]

Assuming using a top-level logger like this is really an attempt to optimize performance by @qoomon, I ran a quick JMH benchmark (will submit a separate pull for this later). These are preliminary numbers but so far I'm seeing basically zero difference between the top-level logger defined in this pull request vs a plain old companion logger defined in the usual way:

Benchmark                                                   Mode  Cnt    Score   Error  Units
LoggingBenchmark.companionObjectKotlinLoggerDirect          avgt   10  155.530 ± 3.002  ns/op
LoggingBenchmark.companionObjectKotlinLoggerFunctional      avgt   10  156.973 ± 3.427  ns/op
LoggingBenchmark.companionObjectLog4jLoggerDirect           avgt   10  134.993 ± 3.664  ns/op
LoggingBenchmark.companionObjectLog4jLoggerFunctional       avgt   10  146.832 ± 3.677  ns/op
LoggingBenchmark.topLevelLoggerWithContextLookupDirect      avgt   10  138.477 ± 2.346  ns/op
LoggingBenchmark.topLevelLoggerWithContextLookupFunctional  avgt   10  159.156 ± 3.584  ns/op
LoggingBenchmark.topLevelNamedLoggerDirect                  avgt   10  141.906 ± 4.317  ns/op
LoggingBenchmark.topLevelNamedLoggerFunctional              avgt   10  157.794 ± 3.417  ns/op

The topLevelLoggerWithContextLookupX methods are using the new logger { } from this PR. The companionObjectKotlinLoggerX methods are the current Kotlin logger in the companion. The time for companionObjectKotlinLoggerDirect is a mistake -- I made the call in a functional way.

The Log4j companionObjectLog4jLoggerX are bypassing the Kotlin wrapper completely so it makes sense those are faster.

[rocketraman]

Benchmarks are hard... turns out most of the time in the previous benchmark was taken up by log4j itself, because the NullAppender was active at TRACE level. Changing the appender to be inactive at the level the benchmark logs at so as to focus on the logger call times, results in these numbers:

LoggingBenchmark.companionObjectKotlinLoggerDirect          avgt   10  1.485 ± 0.041  ns/op
LoggingBenchmark.companionObjectKotlinLoggerFunctional      avgt   10  1.476 ± 0.034  ns/op
LoggingBenchmark.companionObjectLog4jLoggerDirect           avgt   10  1.139 ± 0.030  ns/op
LoggingBenchmark.companionObjectLog4jLoggerFunctional       avgt   10  1.114 ± 0.016  ns/op
LoggingBenchmark.topLevelLoggerWithContextLookupDirect      avgt   10  1.487 ± 0.035  ns/op
LoggingBenchmark.topLevelLoggerWithContextLookupFunctional  avgt   10  1.479 ± 0.016  ns/op
LoggingBenchmark.topLevelNamedLoggerDirect                  avgt   10  1.485 ± 0.037  ns/op
LoggingBenchmark.topLevelNamedLoggerFunctional              avgt   10  1.471 ± 0.014  ns/op

I'm probably still missing something, but at least so far these numbers are still consistent (relatively speaking) with my prior post.

[rocketraman]

If the primary goal here is not performance but instead to support top-level logging as a feature without explicit naming (which would definitely be nice for scripts and the like), we could make it slightly more composable and discoverable, at the cost of a bit more verbosity, like this:

val LOG = logger(context { })

where context is:

fun context(_context: () -> Unit) = with(_context::class.java.name) {
  when {
    contains("Kt$") -> substringBefore("Kt$")
    contains("$") -> substringBefore("$")
    else -> this
  }
}

[qoomon]

@rocketraman thanks for all the analysis. I'm impressed by the numbers, cause I really thought a static field access would be faster than 2 extra function calls. The JVM surprised me again 🤩

I really like you more explicit version.

I would go for val LOG = logger(contextName { }) to make it even easier to understand. WDYT

[qoomon]

would be nice if you can share the benchmark code.

[rocketraman]

@rocketraman thanks for all the analysis. I'm impressed by the numbers, cause I really thought a static field access would be faster than 2 extra function calls. The JVM surprised me again

The JVM can indeed to amazing things, but I'm curious why you think the companion object approach results in 2 function calls? AFAICT from the bytecode, its just two GETSTATIC field accesses to get the logger reference.

I would go for val LOG = logger(contextName { }) to make it even easier to understand. WDYT

Yeah, I like it.

would be nice if you can share the benchmark code.

See https://github.com/apache/logging-log4j-kotlin/pull/12.

[qoomon]

Done.

[qoomon]

when do you plan to merge and release?

[jvz]

@rocketraman can merge this as he's been the main developer in this component. As for a release, we'd likely need a volunteer to help do that. I have a release guide written here: https://cwiki.apache.org/confluence/display/LOGGING/Log4j+Kotlin+API+Release+Process

Main thing I'd need any help with here is getting the repository into a state where I can run the release commands, commit artifacts, and send the email. I don't have time to modify the build if it's not creating a full release candidate.

[rocketraman]

Actually @jvz I don't think I have push rights to this repository. I did modify @qoomon 's branch a little bit so if you do decide to push this yourself, let me know and I'll give you the coordinates to the modified branch. Otherwise if you can update the push permissions, even better.

[jvz]

Alright, I'll merge this for you. Let me look into the permissions thing.

[rocketraman]

Alright, I'll merge this for you. Let me look into the permissions thing.

Ok you merged the branch as-is, with the back-and-forth on the code changes, whereas I was gonna merge a cleaned up version. All good.

[jvz]

You're a committer on the project, so you should be able to merge. Make sure you have two-factor auth set up for you github account.

[rocketraman]

You're a committer on the project, so you should be able to merge. Make sure you have two-factor auth set up for you github account.

I do.

[jvz]

I filed https://issues.apache.org/jira/browse/INFRA-20289 to get that looked at.

[jvz]

@rocketraman check your account settings on https://gitbox.apache.org/setup/ and report back in that INFRA ticket I linked.

[qoomon]

thx guys

[qoomon]

any release schedule?