Optimizing lambda that is used for logging

1

I have a simple logger here that uses lambdas for logging, like this:

logger(LogLevel.DEBUG) { "Test log 123 $somevalue" }

The implementation looks like this:

inline operator fun invoke(logLevel: LogLevel, logLambda: () -> String) {
    if (logLevel.numericLevel <= Logger.threshold.numericLevel)
        Logger.backend.log(logLevel, logLambda.invoke())
}

The idea here is that by setting Logger.threshold, I can control the verbosity and avoid evaluating log lines altogether. So even if there is logger code that constructs some very verbose lines or calls functions, it is completely skipped if the log level is not low enough. This can save a lot of unnecessary CPU work. Example: logger(LogLevel.VERBOSE) { "Current status: ${getCurrentStatus()}" } - if the VERBOSE log level is not enabled, the getCurrentStatus function call is avoided completely.

However, I am curious if I can make performance improvements, perhaps by making them inline. I do get warnings that inline may not be useful if I try that, however. My overall concern is that internally, this creates a Function0 class instance for each and every log line, which sounds like a nontrivial overhead. I am OK with limiting what one can do inside the log lambdas here, since in 99.9999% of all cases, it is a simple expression like { "abc" }. Complex logger lambdas with multiple exit points and such are highly uncommon.

Thoughts?

2

The lambda will have to be created anyway since the compiler can’t know in advance the value of Logger.threshold.numericLevel.

3

Hmm, I think you should not get this warning in the above case. This is a typical use case for inline functions in Kotlin, as explained here:

Using higher-order functions imposes certain runtime penalties: each function is an object, and it captures a closure. A closure is a scope of variables that can be accessed in the body of the function. Memory allocations (both for function objects and classes) and virtual calls introduce runtime overhead. But it appears that in many cases this kind of overhead can be eliminated by inlining the lambda expressions.

Also, did you look at already existing logging libraries that does the same thing, for example: kotlin-logging ?

Hmm, I’m not sure what do you mean. Lambda won’t be needed here, because it is inlined as well. This is the main point of inline functions in Kotlin. This code:

logger(LogLevel.DEBUG) { "Test log 123 $somevalue" }

Becomes:

if (LogLevel.DEBUG.numericLevel <= Logger.threshold.numericLevel) {
    Logger.backend.log(LogLevel.DEBUG, "Test log 123 $somevalue")
}

So both the contents of the invoke() function and of the lambda are inlined at the call-site.

1 Like
4

sorry, you’re right. my bad.

5

Now that I revisited this code (the “inline” in the example was not included in the actual code), you seem to be correct - this works without a warning. I am now confused as to why I saw it before. Perhaps it was a bug in an older Kotlin version? I tried this a long time ago, I think even before Kotlin 1.4.

So, with the invoke operator function inlined, and lambda function arguments being inlined by default, this code should not have any overhead caused by Function0 instances, right?

6

Are you sure logLambda was there from the beginning? Because this warning about unnecessary inline appears when we try to inline a function that is not a higher-order function. It seems Kotlin authors decided that at least for now the only / main reason to inline a function is to inline the lambda passed to it (edit: another is to use a reified param). So exactly your case.

Yes. You can verify this by yourself. Create a simple function like this:

fun test(logger: Logger, level: LogLevel) {
    logger(level) { "foo" }
}

Then in IntelliJ select Tools → Kotlin → Show Kotlin Bytecode → Decompile. You should see the code similar to one I posted in my previous post. There should be no closures / lambdas.

7

By the way, this particular case already has a good (if limited) solution in Java (and hence Kotlin).

Concatenating strings in log messages is so common that most of the standard loggers (java.util.logging, SLF4J, Log4j, &c) have overrides for most methods that do some formatting, taking a varargs list of values to interpolate. So instead of something like:

logger.debug("Test log 123 $somevalue")

you can write:

logger.debug("Test log 123 {}", somevalue)

That will call somevalue.toString() and interpolate it into the string at the first {} — but only if the logger is configured to output that string; otherwise, it does no string processing at all.

Obviously, being able to optimise lambda usage is of much wider importance; but it’s good to know what options are already available.

8

That trick with "{}" unfortunately works only for single parameter. For multiple parameters, they have to be passed as an array, introducing memory overhead, that can be rather tremendous for messages that are produced very often (at very detailed log levels).

9

Some logging frameworks have overloads for multiple parameters. For example, Log4J has overloads for up to 10 params, using an array only for 11+ (which is vanishingly rare IME). So there would be no overhead in nearly all cases.

(Also, even where that doesn’t apply, the overhead of a single array may be a lot less than that of several strings — one from each interpolated value, plus one for the resulting string — when the log isn’t used.)

As I said, this solution is a bit specialised for logging, and it’s a shame there’s no good general solution. But since the question was asking about logging, I think it’s worth mentioning.

10

Right, I should’ve clarified that my comment applies only to java.util.logging. The overhead may be less than for string interpolation, but I’ve hit a case when it was rather high compared to the rest of the code, so I had to put an extra if (debug) check.

11

If we talk about Kotlin and not Java then I think inlined higher-order function is a good general solution. And it’s much more powerful than {} as it allows to compute values used in the log.