Hi! I'm trying to benchmark a possible extension f...

# announcements

[kschlesselmann]

Hi! I'm trying to benchmark a possible extension for https://github.com/MicroUtils/kotlin-logging. This lib provides ideomatic logging like <http://logger.info|logger.info> { "Some expensive $string" }. Now there's structured logging as well with https://github.com/logstash/logstash-logback-encoder. It would be great if I could use the lazy evaluated logging approach with multiple arguments as well.

I came up with something like

private fun KLogger.infoWithVarargSupplier(
        vararg arguments: () -> Any,
        message: () -> String,
    ) {
        if (isInfoEnabled) {
            info(
                message.invoke(),
                *arguments
                    .map { it.invoke() }
                    .toTypedArray(),
            )
        }
    }

and now I'd like if there would be any huge performance impact in using a function like this. I tried creating a JMH benchmark but the results look suspicious … any suggestions?

[Big Chungus]

What's wrong with capturing args in closure?

[Oliver.O]

Can you show us your benchmark code? What exactly do you mean by 'looking suspicious'?

In addition, could you provide some use cases for the above function? Does it make more sense to have a lambda per argument than a lambda returning a list of arguments, for example?

[kschlesselmann]

@Big Chungus What do you mean?

[kschlesselmann]

@Oliver.O Yes of course

[kschlesselmann]

package extensions

import net.logstash.logback.argument.StructuredArguments.kv
import org.openjdk.jmh.annotations.*
import org.openjdk.jmh.infra.Blackhole
import org.openjdk.jmh.runner.Runner
import org.openjdk.jmh.runner.options.Options
import org.openjdk.jmh.runner.options.OptionsBuilder
import java.util.concurrent.TimeUnit


fun testThing(
    message: String,
    vararg args: Any,
) = message.hashCode() + args.hashCode()

val enabled = true

fun testThingExtension(
    vararg arguments: () -> Any,
    message: () -> String,
) = if (enabled) {
    testThing(
        message.invoke(),
        *arguments
            .map { it.invoke() }
        .toTypedArray()
    )
} else {
    0
}

fun testThingExtensionSingle(
    arguments: () -> Array<Any>,
    message: () -> String,
) = if (enabled) {
    testThing(
        message.invoke(),
        *arguments.invoke(),
    )
} else {
    0
}

inline fun inlineTestThingExtension(
    vararg arguments: () -> Any,
    message: () -> String,
) = if (enabled) {
    testThing(
        message.invoke(),
        *arguments
            .map { it.invoke() }
            .toTypedArray()
    )
} else {
    0
}

inline fun inlineTestThingExtensionSingle(
    arguments: () -> Array<Any>,
    message: () -> String,
) = if (enabled) {
    testThing(
        message.invoke(),
        *arguments.invoke()
    )
} else {
    0
}

@BenchmarkMode(Mode.AverageTime) // Benchmark mode
@Warmup(iterations = 5) // Preheating times
@Measurement(iterations = 100, time = 5, timeUnit = TimeUnit.NANOSECONDS)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@Threads(8) // number of test threads per process
@Fork(3)
open class SomeOtherBenchmark {

    @Benchmark
    fun standard(blackhole: Blackhole) {
        val result = if (enabled) {
            testThing("foo", kv("a", "b"), kv("c", "d"))
        } else {
            0
        }

        blackhole.consume(result)
    }

    @Benchmark
    fun extension(blackhole: Blackhole) {
        val result = testThingExtension(
            {kv("a", "b")}, {kv("c", "d")}
        ) {
            "foo"
        }

        blackhole.consume(result)
    }

    @Benchmark
    fun inlineExtension(blackhole: Blackhole) {
        val result = inlineTestThingExtension(
            {kv("a", "b")}, {kv("c", "d")}
        ) {
            "foo"
        }

        blackhole.consume(result)
    }

    @Benchmark
    fun extensionSingle(blackhole: Blackhole) {
        val result = testThingExtensionSingle(
            { arrayOf(kv("a", "b"), kv("c", "d")) }
        ) {
            "foo"
        }

        blackhole.consume(result)
    }

    @Benchmark
    fun inlineExtensionSingle(blackhole: Blackhole) {
        val result = inlineTestThingExtensionSingle(
            { arrayOf(kv("a", "b"), kv("c", "d")) }
        ) {
            "foo"
        }

        blackhole.consume(result)
    }

    companion object {

        @JvmStatic
        fun main(args: Array<String>) {

            val options: Options = OptionsBuilder()
                .include(".*" + SomeOtherBenchmark::class.java.simpleName + ".*")
                .output("benchmark_test.log")
                .build()

            Runner(options).run()
        }
    }

}

[kschlesselmann]

As you can seen I tried 4 flavours. Multiple lambdas and a single lambda providing an Array<Any>. Then both functions as inline function as well.

[kschlesselmann]

I thought for example that the inline version should be faster … but often it's not 🤷🏻‍♂️

[kschlesselmann]

Some results are for example

Benchmark                                 Mode  Cnt      Score       Error  Units
SomeOtherBenchmark.extension              avgt  300  24089,809 ± 34911,345  ns/op
SomeOtherBenchmark.extensionSingle        avgt  300  16363,556 ± 29068,461  ns/op
SomeOtherBenchmark.inlineExtension        avgt  300  18925,285 ± 25892,763  ns/op
SomeOtherBenchmark.inlineExtensionSingle  avgt  300  25488,181 ± 36613,759  ns/op
SomeOtherBenchmark.standard               avgt  300  14638,310 ± 27306,244  ns/op

[kschlesselmann]

I substitued the logger in this case to avoid anything I don't want to measure to some function that just computes the hashCodes of the arguments

[kschlesselmann]

The problem I want to solve is, that I don't want to wrap my log statements with if (logger.isFooEnabled) {} all the time

[Oliver.O]

@kschlesselmann Profiling the code you posted shows that most of the time is spent in java.lang.Object.hashCode(). The invocation overhead introduced by the different test is negligible in comparison. That's probably not what you are intending to measure.

I have changed the benchmark code, keeping the overhead of invoked functions minimal while trying to avoid constant folding. (I have also changed the benchmark configuration, as allocating 5 nanoseconds per iteration is a bit short and seems to be ignored.)

package test

import org.openjdk.jmh.annotations.*
import org.openjdk.jmh.infra.Blackhole
import org.openjdk.jmh.runner.Runner
import org.openjdk.jmh.runner.options.Options
import org.openjdk.jmh.runner.options.OptionsBuilder
import java.util.concurrent.TimeUnit

fun testThing(
    message: Int,
    vararg args: Int,
) = message * args.sum()

fun kv(k: Int, v: Int) = k * v

var enabled = true
var a = 1
var b = 2
var c = 3
var d = 4
var m = 10

fun testThingExtension(
    vararg arguments: () -> Int,
    message: () -> Int,
) = if (enabled) {
    testThing(
        message.invoke(),
        *arguments
            .map { it.invoke() }
            .toIntArray()
    )
} else {
    0
}

fun testThingExtensionSingle(
    arguments: () -> IntArray,
    message: () -> Int,
) = if (enabled) {
    testThing(
        message.invoke(),
        *arguments.invoke(),
    )
} else {
    0
}

inline fun inlineTestThingExtension(
    vararg arguments: () -> Int,
    message: () -> Int,
) = if (enabled) {
    testThing(
        message.invoke(),
        *arguments
            .map { it.invoke() }
            .toIntArray()
    )
} else {
    0
}

inline fun inlineTestThingExtensionSingle(
    arguments: () -> IntArray,
    message: () -> Int,
) = if (enabled) {
    testThing(
        message.invoke(),
        *arguments.invoke()
    )
} else {
    0
}

@Suppress("SpellCheckingInspection")
@BenchmarkMode(Mode.AverageTime) // Benchmark mode
@Warmup(iterations = 3, time = 1, timeUnit = TimeUnit.SECONDS)
@Measurement(iterations = 3, time = 5, timeUnit = TimeUnit.SECONDS)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
//@Threads(8) // number of test threads per process
@Fork(1)
open class LoggingBenchmark {
    @Benchmark
    fun standard(blackhole: Blackhole) {
        val result = if (enabled) {
            testThing(m, kv(a, b), kv(c, d))
        } else {
            0
        }
        blackhole.consume(result)
    }

    @Benchmark
    fun extension(blackhole: Blackhole) {
        val result = testThingExtension(
            { kv(a, b) }, { kv(c, d) }
        ) {
            m
        }
        blackhole.consume(result)
    }

    @Benchmark
    fun inlineExtension(blackhole: Blackhole) {
        val result = inlineTestThingExtension(
            { kv(a, b) }, { kv(c, d) }
        ) {
            m
        }
        blackhole.consume(result)
    }

    @Benchmark
    fun extensionSingle(blackhole: Blackhole) {
        val result = testThingExtensionSingle(
            { intArrayOf(kv(a, b), kv(c, d)) }
        ) {
            m
        }
        blackhole.consume(result)
    }

    @Benchmark
    fun inlineExtensionSingle(blackhole: Blackhole) {
        val result = inlineTestThingExtensionSingle(
            { intArrayOf(kv(a, b), kv(c, d)) }
        ) {
            m
        }
        blackhole.consume(result)
    }

    companion object {
        @JvmStatic
        fun main(args: Array<String>) {
            val options: Options = OptionsBuilder()
                .include(".*" + LoggingBenchmark::class.java.simpleName + ".*")
                .output("benchmark_test.log")
                .build()
            Runner(options).run()
        }
    }
}

[Oliver.O]

The new results seem to be in line with expectations:

enabled = true, 3 x 1 sec warmup, 3 x 5 seconds measurement:

Benchmark                               Mode  Cnt   Score   Error  Units
LoggingBenchmark.extension              avgt    3  43.721 ± 1.742  ns/op
LoggingBenchmark.extensionSingle        avgt    3   7.289 ± 1.792  ns/op
LoggingBenchmark.inlineExtension        avgt    3  42.142 ± 1.353  ns/op
LoggingBenchmark.inlineExtensionSingle  avgt    3   5.498 ± 0.105  ns/op
LoggingBenchmark.standard               avgt    3   4.925 ± 0.021  ns/op

enabled = false, 3 x 1 sec warmup, 3 x 5 seconds measurement:

Benchmark                               Mode  Cnt  Score   Error  Units
LoggingBenchmark.extension              avgt    3  2.347 ± 0.183  ns/op
LoggingBenchmark.extensionSingle        avgt    3  2.346 ± 0.081  ns/op
LoggingBenchmark.inlineExtension        avgt    3  2.361 ± 0.304  ns/op
LoggingBenchmark.inlineExtensionSingle  avgt    3  2.349 ± 0.021  ns/op
LoggingBenchmark.standard               avgt    3  2.368 ± 0.477  ns/op

[Oliver.O]

Does that help?

[kschlesselmann]

Thanks for your input. Let me have a look later 🙂 👍🏻

[kschlesselmann]

@Oliver.O Where are your measurements and code? Did you delete your post?

[Oliver.O]

No, I did not delete anything. Over here my posts do still appear in the thread.

[kschlesselmann]

@Oliver.O Weird … could you link me your post again?

[Oliver.O]

https://kotlinlang.slack.com/archives/C0922A726/p1622545548373000?thread_ts=1622131251.269400&amp;cid=C0922A726

[Oliver.O]

https://kotlinlang.slack.com/archives/C0922A726/p1622545764373200?thread_ts=1622131251.269400&amp;cid=C0922A726

[kschlesselmann]

thanks!