Inline all logging functions

[kosiakk]

It seems that the whole fuzz around logging is to not create "expensive" String object, if logging level is not enabled. That totally makes sense.

And that's why we library offers a nice function:

    fun unknownElementType(elementType: Int) {

        // Lazy evaluation of the log message
        log.warn  { "Unknown element: $elementType" }

    }

So, what gets generated for this line?

this.log.warn((Function0)(new Function0() {
         // $FF: synthetic method
         // $FF: bridge method
         public Object invoke() {
            return this.invoke();
         }

         @NotNull
         public final String invoke() {
            return "Unknown element: " + elementType;
         }
      }));

Hm... instead of a String, we create:

1. An anonymous inner class
2. Instance of this class, which gets the closure reference to all required outer variables like elementType

That doesn't look very cheap to me.

On the other hand, in Kotlin StdLib pretty much all map or forEach functions are inline. So, we might write it like this:

inline fun KLogger.warnInline(message: () -> String) {
    if (underlyingLogger.isWarnEnabled) 
        underlyingLogger.warn(message())
}

And this gets compiled to the simplest possible, desired lazy evaluation of String:

   void unknownElementType(int elementType) {

      KLogger $receiver$iv = this.log;
      Logger logger$iv = $receiver$iv.getUnderlyingLogger();
      if (logger$iv.isWarnEnabled()) {
         // Lazy evaluation of the log message
         String var7 = "Unknown element: " + elementType;
         logger$iv.warn(var7);
      }

   }

Just like we wanted in the first place.

[kosiakk]

• Inline functions with Lambda arguments
• Kotlin Bytecode viewer with built-in decompiler

[oshai]

The main issue with inline methods is that they don't play nice with logging of line numbers.
I am also not sure about if using it with interfaces and inheritance is possible.

[dnut]

The main issue with not inlining methods is that it defeats the purpose this library. Or is there an advantage other than lazy string evaluation?

Could you please elaborate on your concerns about line numbers and inheritance?

[oshai]

From my experience kotlin-logging methods on the stack has neglectable effect. So I don't think it defeats the purpose of this library. If you think otherwise please give more details.
Initially, I implemented all methods as inline but when added support to line numbers in the log it just did not work as inline methods do not have line number and appear in a different class. for more details see LocationAwareKLogger. You can also try modifying it yourself and running the tests.
For inheritence (like we have here) inline cannot work as the moethod is virtual and it's impossible to know in compilation which method to actually put in place.
In addition there are restrictions on public api as you can see here: https://kotlinlang.org/docs/reference/inline-functions.html#public-inline-restrictions

[dnut]

From my experience kotlin-logging methods on the stack has neglectable effect.

I'm skeptical that it's negligible. How are you measuring negligible? Maybe string evaluations would also be negligible...

The main reason inline functions exist is to improve performance by avoiding the overhead of creating unnecessary lambdas. That's what it says in the first paragraph of the official documentation you linked to.

For inheritence (like we have here) inline cannot work as the moethod is virtual and it's impossible to know in compilation which method to actually put in place.

I agree this is a concern. But this only happens when the logger type is declared to be the interface. And in that case it works like a normal method. The same way your library works now. There is no downside.

However there is a potential upside. When the logger is declared as the class, its methods will be inlined.

I understand the choice you made to go with the factory pattern. It's a solid design. But don't be too idealistic. Performance is advertised as a central focus of this library. I would consider some other options.

Initially, I implemented all methods as inline but when added support to line numbers in the log it just did not work as inline methods do not have line number and appear in a different class. You can also try modifying it yourself and running the tests.

My intuition tells me that the only line number context that should be lost might be the line numbers of the code in the inline method. But I may have reproduced what you ran into. Log4j throws an error at StackLocator.calcLocation, so nothing is logged. Looks like a compatibility issue. I wonder how hard it would be to make this work. I feel like it should in theory be possible, but it may require changes to kotlin.

This problem only appears if the logger field is declared as LocationAwareKLogger. If I declare it as KLogger, it works fine, because the inline methods don't actually get inlined.

I assume that we wouldn't run into any issues like this with LocationIgnorantKLogger. That's the only place where performance really matters anyway; no one is logging line numbers if they care about performance. So you could just make the methods inline for LocationIgnorantKLogger and keep regular methods in LocationAwareKLogger.

[oshai]

Few notes about performance:

• When compiling Kotlin to Java 8 lambda are using invoke dynamic which is cheaper than what was before that.
• The performance saving for the log invocation comes from string concatenation and transforming objects to strings that might be costly in some cases.

Assuming we'll have inline methods for LocationIgnorantKLogger, how do you imagine such api? returning such type from getLogger?
As I see it you might want to have the same logging with different configurations, for example in different environments where some have location aware and some don't. Using it this way you're loosing that ability. Or did you had something else in mind?

[imanushin]

I did performance testing with different inlining ways here. Please feel free to recheck this on your machines.

For current moment:

Benchmark	(parameter)	Mode	Cnt	Score	Error	Units
Current Version	some input	thrpt	25	886985830.852	902317.027	ops/s
Inline Only Methods	some input	thrpt	25	1030269283.210	1055018.686	ops/s
Inline Methods and Class	some input	thrpt	25	1215706262.293	1377949.753	ops/s

So class+method inlining works at least 50% faster (at 1.5 times!!). In this I think we can consider adding special inlined version for at least JVM version.

@oshai, I create create PR with this option. What do you think about this improvement (please note - old option will be still available)?

[oshai]

@imanushin thanks for the details analysis!
Going forward - I think if we are going to change it, it's better not to have more than one version, and since it will be a breaking change, we probably want to bump the version to 2.0.
In addition since it looks like it will be beneficial to have both inline method and class and inline class is still experimental it's better to do this change once inline class is GA.
However, I guess we can start discuss it so a PR is welcome, as I am mainly not sure how/if there is any api change?

[imanushin]

However, I guess we can start discuss it so a PR is welcome, as I am mainly not sure how/if there is any api change?

For current moment KLogging facades slf4 for JVM and Marker for JS. Inline class insists on the one implementation only. In this case we have the following options:

1. Keep the common module. Then we have extract interface LogFacade or something like this. It should be resolved to slf4 for java, Marker for JS and something new for future Native. Because of this facade, the performance can slow down a little (not sure, the tests are required).
2. Remove KLogger from the common module (e.g. it will be impossible for our users to write common kotlin library, which works with different loggers on JVM/JS). Then we can just implement two versions of KLogger: for JVM and for JS. We can have common files, which will be used by JVM/JS module (e.g. two projects (for JVM and for JS) will just have common source folder, this is needed to keep the most of files as internal).
3. Implement 2 first. Then we can create new common module, which won't be inlined and which will reference kotlin-logging to select the actual implementation. It means, that currently actual loggers references the common one. "3" solution inverses it: common module just references actual one, to have slower, but common logging option. So this solution 3 is combination of 2 and 1.

Just to summarize the fact: solution "inline classes and inline methods" improves the performance, however it couldn't work for Kotlin Common modules. Unfortunately...

[qoomon]

I really like the idea of #112

[oshai]

@imanushin do you know if the limitation of common modules and inline method "relaxed" now with Kotlin 1.4?

[sghpjuikit]

I'd also like full inline API for this, but I can see how this is problematic.

I believe it should be inline, after all, even if it should break binary compatibility.

[imanushin]

@oshai, this is looks like interesting. However I thing I found the way to keep the backward compatibility.

We can remain the same signature, however add new - with no inline function call. This increases memory traffic in comparison with the most optimal solution, however in addition it allows us to decrease bytecode amount.

Example:

interface KLogger {
       inline fun warn(getLine: () -> String) {
             if(this.warn.isEnabled) {
                   this.warnNoInline(getLine) // unnesesary memory allocation is here
             }    
       }

      // this method should be hidden ideally, to avoid garbage in the intelli sence.
      // another option - we can use public extension method for type under "this.warn". This can help us a little to hide unnesesary implementation.
      fun warnNoInline(getLine: () -> String)
     
}

[oshai]

@imanushin it's an interesting solution. Maybe warnNoInline can have reduced visibility somehow?
My main concern is that it will not work well with line numbers logging.
Inspired by #112 and flogger I am thinking maybe we should add another logging flavour like: logger.debug?.log()

[sghpjuikit]

As I said in #112, I think logger.debug?.log("") is not idiomatic, because it simulates by-name evaluation, which Kotlin does not have and which is imo very counter-intuitive in Java-land.

@oshai And there are 2 problems with adding new flavour here.

1 By chasing the 'unopinionated' tag, the library becomes schizophrenic. It splits the user base. This doubles the API surface, maintenance (this cost trickles down to users as well), documentation, complicates explanation of the library by having to explain not only each flavour, but right in the get-go overload user with low-lvl concepts in order to explain pros and cons of each flavor so he can choose one. The user just wants to log the damned thing, preferably learning the library in 1 min by skimming the README file.

Look at the mess with testing frameworks. Kotest and scalatest are both great projects, but I refuse to read/study pages like https://github.com/kotest/kotest/blob/master/doc/styles.md or https://www.scalatest.org/user_guide/selecting_a_style. I'm not sure all the flavors are really necessary and 1 I still struggle with using even the one I always use (because the libs have me forever confused about it) and 2 this may lead to the need for even greater modularity of the library (like scalatest, which broke itself last year to split itself by flavor - that was fun for everyone).

In the end, users only lose. No idiomatic use. Suddenly swiss army knife. More documentation, more API, more classes, more artifacts, more code, bigger sizes, etc.

Also, adding more API is not a way to avoid binary incompatibility. If it should broken, it should break.

2 Provided that another flavor is a good idea, the flavor changes should be purely syntactical - but they are not! Trade-off flavors are evil.

Are you going to tell users to choose readability vs performance? Promise performance boosts with certain flavors? Are you going to back those promises up with facts? Uphold those promises across language versions, platforms, etc? Will you be documenting this and keep updating the documentation? Will someone do comprehensive testing comparing the flavors? Or will the documentation simply state "Flavor X should be slower than Y, but nobody knows due to too many factors and no benchmarks - just use it how you like." I feel like adding another flavor suddenly ups the requirements even on the existing code.

This is not criticism, its an appeal to carefully let the ideas mature before potentially committing to something with consequences. Personally, I dont know the innards of the library to dare to point to the 'best' solution, so I at least want to help by brainstorming about ideas. But thinking about it: when I think about this library I think of simple and does the job - and I like that about it.

[oshai]

@sghpjuikit I totally agree with the concerns raised in 1+2 and I don't plan to rush into implementing it.
Regarding the syntax itself I think that it's pretty clearly indicates that it logs at the correct level only (but that is only my opinion). Maybe a better syntax will be logger.atDebug?.log(). Please also take a look at flogger which have a bit similar style for java.

So I think we can decide on few directions right now:

1. Do nothing and wait for a good inline solution to come up in the future.
2. Replace the syntax with a long deprecation cycle, keeping two flavours for a long period.

I generally tend to 1, but would love to get some more feedback or suggestions how to inline without breaking other things (mainly the line numbers logging).

[MartinHaeusler]

I'd like to add my voice to the "let's use inline functions" faction as well. I think this is the perfect use case for inline functions. I'm not sure what happens to line numbers in stack traces, but that's something the Kotlin compiler team has to figure out, isn't it? As far as I know, this already works out-of-the-box with Kotlin 1.3 or above, inline or no.

That being said, I personally would prefer this:

log.error { "Whoops, ${username} does not exist!"}

... over this:

logger.error?.("Whoops, %s username does not exist", username)

... simply due to the fact that I really want to use the built-in string templates in Kotlin and having to use something else (e.g. %s) to get the best possible performance would really bug me (editor support, code completion, syntax checking etc.). I've always disliked the fragility of C printf(...), and this feels a lot like it.

[oshai]

As far as I know, this already works out-of-the-box with Kotlin 1.3 or above, inline or no

Can you please clarify this?

[MartinHaeusler]

As far as I know, this already works out-of-the-box with Kotlin 1.3 or above, inline or no

Can you please clarify this?

I use Kotlin extensively at work and there are also inline functions involved. I've yet to encounter a stacktrace where the line numbers didn't match the source code, so I'm not really sure line number mismatches are an issue when using inline functions. There might be a case I haven't encountered yet though.

[imanushin]

@MartinHaeusler , may I ask you to advice some kind of design here?

I created draft PR, please check #226. Precisely please check this line - https://github.com/MicroUtils/kotlin-logging/pull/226/files#diff-0b429ddafa82b8ceaaa5c94a88dfd47b370051bf951c90cb5d89889a94a3a392R50

So what we have in general:

1. val info: LoggingCallback?, which returns the interface. It can be functional interface, or it can be like I created, that doesn't matter.
2. Then you will be able to use notation logger.info?.let { it("some string $someVariable") }. So everything will be logged lazily and (what is important) you will able to use coroutines or anything which you want to generate the final line.
   2.1. Another option is logger.info?.invoke("some string $someVariable"). The generated code will be the same.
3. No any code allocations for logging, nevertheless of logger enabledness. No any premature allocations, everything is lazy, etc.
4. Ugly design, and that is my main concern. Why - because I can't call function with this notation - logger.info?.("123"), I see the following compilation error - The expression cannot be a selector (occur after a dot).

So, do you know how to correct function signature to have pretty syntax here?

[MartinHaeusler]

I think what you're aiming for is:

• if the logger is disabled, .info returns NULL
• otherwise the logger is returned
• use ?. as a shorthand for if(logger.isEnabled)

Is that correct? I see what you tried to do, but there is a better way. Consider this:

inline fun org.slf4j.Logger.info(msg: () -> Any?){
    if(this.isInfoEnabled){
        this.info(msg())
     }
}

If you call this extension method like this:

val log = LoggerFactory.getLogger("mylogger")
log.info { "Hello World" }  // note the curly braces

... then the kotlin compiler will automatically inline the info method - AND the lambda. So what you get in the compiled binary after inlining is exactly what we want:

val log = LoggerFactory.getLogger("mylogger")
if(log.isInfoEnabled){
    log.info("Hello World")
}

The lambda doesn't exist at runtime anymore, so there is no overhead. Also, the inline function itself is gone, so it's just as good as using ?., except that it reads much better. If you're doing more complex logic to construct the string in the original lambda code, that code will end up in the if statement and will therefore only be executed if the logger is actually enabled.

I hope that helps.

[imanushin]

@MartinHaeusler , inline logging functions aren't work well, as @oshai stated here - #34 (comment) . And yes, you had got my concept fully.

So for now we have two contradicting opinions:

• inline methods aren't friendly with LocationAwareLogger
• Normal methods allocate lambdas in heap (plus they de-optimize code, because JIT can't optimize code, because more variables are now visible not only from stack).

If we use extension methods for that case then user will be able to choose what they want. (e.g. if you want to optimize code - use extension methods, if you want to have precise logging location - use methods from interface). However functionality will be duplicated.

@oshai , what is your opinion, should we add extension methods for inline lambdas purpose (so Logger interface remains unchanged)?

[oshai]

I think that what logging frameworks did nicely is that they separated the api from the decision if you want to log line numbers, and it's only in configuration.
With the two methods suggestion you'll have to choose that in advance, or change your code later and compile it again. Also library authors don't know what their users want and will have hard time choosing the implementation.
So I don't think that suggestion is good enough at the moment.

I saw other approaches that are adding line numbers on compile-time (flogger), but I don't know if that is possible with the kotlin compiler.

[sschuberth]

I saw other approaches that are adding line numbers on compile-time (flogger), but I don't know if that is possible with the kotlin compiler.

KFlogger was started as part of GSoC 2023.

Also cite might be interesting here as it provides placeholders like $__FILE__ and $__LINE__.

[MartinHaeusler]

Instead of fiddling with line numbers manually, wouldn't it be smarter to report the issue to the Kotlin team at JetBrains and do some lobbying work there to ensure that the line numbers get fixed?