Benchmarks
This page gives a baseline for how much overhead Blindsight adds on top of using raw SLF4J. This is purely CPU bound, so your results will vary depending on how powerful your CPU is.
If you want to run the benchmarks yourself, you can find them here. Please note that virtualized cloud hardware on EC2 or GCP can be very different from your laptop, so please be aware of your instance’s CPU profile and budget. It’s best if you look at these numbers as a rough order of magnitude and as a comparison rather than an absolute statement of performance.
Note that the cost of logging is always vastly greater than adding conditional logic that controls logging, and is only partly incurred by the application itself: logs must be collected, indexed, and analyzed by the organization as a whole. Logging is free, logs are expensive.
Also be aware that JMH benchmarks can be tricky. See What’s Wrong With My Benchmark Results? Studying Bad Practices in JMH Benchmarks for details, and don’t trust any benchmarks that don’t show you the code.
Hardware
Tests are run on a desktop CPU running Windows 10, using an Ubuntu image inside VirtualBox:
Processor Intel(R) Core(TM) i9-9900K CPU @ 3.60GHz, 3600 Mhz, 8 Core(s), 16 Logical Processor(s)
Tests were run on OpenJDK 11:
OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.7+10)
OpenJDK 64-Bit Server VM AdoptOpenJDK (build 11.0.7+10, mixed mode
Benchmark History
You can see the benchmarks in detail at JMH Visualizer:
Raw SLF4J Logger
Running SLF4J as a baseline gives an idea of the underlying SLF4J calls and how much overhead is added by Blindsight.
class SLF4JLoggerBenchmark {
private val slf4jLogger = org.slf4j.LoggerFactory.getLogger(classOf[CoreLoggerBenchmark])
@Benchmark
def trace(): Unit = {
slf4jLogger.trace("Hello world")
}
@Benchmark
def isTraceEnabled(blackhole: Blackhole): Unit = {
blackhole.consume(slf4jLogger.isTraceEnabled())
}
@Benchmark
def info(): Unit = {
slf4jLogger.info("Hello world")
}
@Benchmark
def isInfoEnabled(blackhole: Blackhole): Unit = {
blackhole.consume(slf4jLogger.isInfoEnabled())
}
}
With Logback 1.2.3 and a no-op appender:
[info] SLF4JLoggerBenchmark.info avgt 5 42.113 ± 1.356 ns/op
[info] SLF4JLoggerBenchmark.isInfoEnabled avgt 5 4.745 ± 0.104 ns/op
[info] SLF4JLoggerBenchmark.isTraceEnabled avgt 5 4.775 ± 0.157 ns/op
[info] SLF4JLoggerBenchmark.trace avgt 5 1.305 ± 0.024 ns/op
Blindsight Logger
class LoggingBenchmark {
val logger: Logger = LoggerFactory.getLogger
val condition: Condition = Condition((level, _) => level.compareTo(SLF4JLevel.INFO) >= 0)
val infoConditionLogger: Logger = logger.withCondition(condition)
val neverConditionLogger: Logger = logger.withCondition(Condition.never)
@Benchmark
def trace(): Unit = {
logger.trace("Hello world")
}
@Benchmark
def traceWhen(): Unit = {
logger.trace.when(condition) { log => log("Hello world") }
}
@Benchmark
def traceCondition(): Unit = {
infoConditionLogger.trace("Hello world")
}
@Benchmark
def neverTrace(): Unit = {
neverConditionLogger.trace("Hello world")
}
@Benchmark
def traceExplicitPredicate(): Unit = {
if (logger.isTraceEnabled()) logger.trace("Hello world")
}
@Benchmark
def info(): Unit = {
logger.info("Hello world")
}
@Benchmark
def infoWhen(): Unit = {
logger.info.when(condition) { log => log("Hello world") }
}
@Benchmark
def infoCondition(): Unit = {
infoConditionLogger.info("Hello world")
}
@Benchmark
def neverInfo(): Unit = {
neverConditionLogger.info("Hello world")
}
@Benchmark
def infoExplicitPredicate(): Unit = {
if (logger.isInfoEnabled()) logger.info("Hello world")
}
}
With Logback 1.2.3 and a no-op appender:
[info] LoggingBenchmark.info avgt 5 57.882 ± 1.290 ns/op
[info] LoggingBenchmark.infoCondition avgt 5 93.005 ± 0.567 ns/op
[info] LoggingBenchmark.infoExplicitPredicate avgt 5 54.650 ± 1.502 ns/op
[info] LoggingBenchmark.infoWhen avgt 5 63.091 ± 2.924 ns/op
[info] LoggingBenchmark.neverInfo avgt 5 2.808 ± 0.197 ns/op
[info] LoggingBenchmark.neverTrace avgt 5 2.806 ± 0.138 ns/op
[info] LoggingBenchmark.trace avgt 5 4.297 ± 0.014 ns/op
[info] LoggingBenchmark.traceCondition avgt 5 18.676 ± 0.946 ns/op
[info] LoggingBenchmark.traceExplicitPredicate avgt 5 4.199 ± 0.188 ns/op
[info] LoggingBenchmark.traceWhen avgt 5 9.244 ± 0.140 ns/op
Flow Logger
class FlowBenchmark {
val flow = LoggerFactory.getLogger.flow
val condition: Condition = Condition((level, _) => level.compareTo(SLF4JLevel.INFO) >= 0)
val neverLogger = flow.withCondition(Condition.never)
implicit def flowBehavior[B]: FlowBehavior[B] = FlowBehavior.noop
@Benchmark
def info(): Unit = {
val result = flow.info {
"Hello world"
}
}
@Benchmark
def infoWhen(): Unit = {
val result = flow.info.when(condition) {
"Hello world"
}
}
@Benchmark
def neverInfo(): Unit = {
val result = neverLogger.info {
"Hello world"
}
}
@Benchmark
def trace(): Unit = {
val result = flow.trace {
"Hello world"
}
}
@Benchmark
def traceWhen(): Unit = {
val result = flow.trace.when(condition) {
"Hello world"
}
}
@Benchmark
def neverTrace(): Unit = {
val result = neverLogger.trace {
"Hello world"
}
}
}
With Logback 1.2.3 and a no-op appender:
[info] FlowBenchmark.info avgt 5 47.409 ± 1.310 ns/op
[info] FlowBenchmark.infoWhen avgt 5 116.816 ± 3.505 ns/op
[info] FlowBenchmark.neverInfo avgt 5 39.095 ± 0.324 ns/op
[info] FlowBenchmark.neverTrace avgt 5 38.780 ± 0.610 ns/op
[info] FlowBenchmark.trace avgt 5 42.328 ± 1.771 ns/op
[info] FlowBenchmark.traceWhen avgt 5 114.078 ± 4.367 ns/op
The flow logger is slightly slower even when disabled because of sourcecode.Args creating a Seq of arguments.
Fluent Logger
class FluentBenchmark {
val fluent: FluentLogger = LoggerFactory.getLogger.fluent
val condition: Condition = Condition((level, _) => level.compareTo(SLF4JLevel.INFO) >= 0)
val neverConditionLogger = fluent.withCondition(Condition.never)
@Benchmark
def info(): Unit = {
fluent.info.message("Hello world").log()
}
@Benchmark
def infoWhen(): Unit = {
fluent.info.when(condition) { info =>
info.message("Hello world").log()
}
}
@Benchmark
def neverWhen(): Unit = {
neverConditionLogger.info.message("Hello world").log()
}
@Benchmark
def trace(): Unit = {
fluent.trace.message("Hello world").log()
}
@Benchmark
def neverTrace(): Unit = {
neverConditionLogger.trace.message("Hello world").log()
}
@Benchmark
def traceWhen(): Unit = {
fluent.trace.when(condition) { trace =>
trace.message("Hello world").log()
}
}
}
With Logback 1.2.3 and a no-op appender:
[info] FluentBenchmark.info avgt 5 90.699 ± 0.817 ns/op
[info] FluentBenchmark.infoWhen avgt 5 98.016 ± 3.917 ns/op
[info] FluentBenchmark.neverTrace avgt 5 4.383 ± 0.235 ns/op
[info] FluentBenchmark.neverWhen avgt 5 4.350 ± 0.042 ns/op
[info] FluentBenchmark.trace avgt 5 4.810 ± 0.038 ns/op
[info] FluentBenchmark.traceWhen avgt 5 8.010 ± 0.181 ns/op
Semantic Logger
class SemanticBenchmark {
val semantic = LoggerFactory.getLogger.semantic[SampleMessage]
val sampleMessage = SampleMessage("hello world")
val condition: Condition = Condition((level, _) => level.compareTo(SLF4JLevel.INFO) >= 0)
@Benchmark
def info(): Unit = {
semantic.info(sampleMessage)
}
@Benchmark
def infoWhen(): Unit = {
semantic.info.when(condition) { info =>
info(sampleMessage)
}
}
@Benchmark
def trace(): Unit = {
semantic.trace(sampleMessage)
}
@Benchmark
def traceWhen(): Unit = {
semantic.trace.when(condition) { trace =>
trace(sampleMessage)
}
}
}
final case class SampleMessage(messageType: String)
object SampleMessage {
implicit val toStatement: ToStatement[SampleMessage] = ToStatement { sample =>
Message(sample.messageType).toStatement
}
}
With Logback 1.2.3 and a no-op appender:
[info] SemanticBenchmark.info avgt 5 76.736 ± 1.964 ns/op
[info] SemanticBenchmark.infoWhen avgt 5 78.773 ± 0.845 ns/op
[info] SemanticBenchmark.trace avgt 5 19.461 ± 1.099 ns/op
[info] SemanticBenchmark.traceWhen avgt 5 8.012 ± 0.249 ns/op
Unchecked Logger
class UncheckedBenchmark {
val logger = LoggerFactory.getLogger.unchecked
val condition: Condition = Condition((level, _) => level.compareTo(SLF4JLevel.INFO) >= 0)
val infoConditionLogger = logger.withCondition(condition)
val neverConditionLogger = logger.withCondition(Condition.never)
val args = Arguments("one", "two", "three")
@Benchmark
def trace(): Unit = {
logger.trace("Hello world")
}
@Benchmark
def traceWithArg1(): Unit = {
logger.trace("Hello world {}, {}", "one")
}
@Benchmark
def traceWithArg1Arg2(): Unit = {
logger.trace("Hello world {}, {}", "one", "two")
}
@Benchmark
def traceWithArgs(): Unit = {
logger.trace("Hello world {}, {}, {}", args)
}
@Benchmark
def traceWhen(): Unit = {
logger.trace.when(condition) { log => log("Hello world") }
}
@Benchmark
def traceCondition(): Unit = {
infoConditionLogger.trace("Hello world")
}
@Benchmark
def neverTrace(): Unit = {
neverConditionLogger.trace("Hello world")
}
@Benchmark
def traceExplicitPredicate(): Unit = {
if (logger.isTraceEnabled()) logger.trace("Hello world")
}
@Benchmark
def info(): Unit = {
logger.info("Hello world")
}
@Benchmark
def infoWithArg1(): Unit = {
logger.info("Hello world {}, {}", "one")
}
@Benchmark
def infoWithArg1Arg2(): Unit = {
logger.info("Hello world {}, {}", "one", "two")
}
@Benchmark
def infoWithArgs(): Unit = {
logger.info("Hello world {}, {}, {}", args)
}
@Benchmark
def infoWhen(): Unit = {
logger.info.when(condition) { log => log("Hello world") }
}
@Benchmark
def infoCondition(): Unit = {
infoConditionLogger.info("Hello world")
}
@Benchmark
def neverInfo(): Unit = {
neverConditionLogger.info("Hello world")
}
@Benchmark
def infoExplicitPredicate(): Unit = {
if (logger.isInfoEnabled()) logger.info("Hello world")
}
}
With Logback 1.2.3 and a no-op appender:
[info] UncheckedBenchmark.info avgt 5 57.720 ± 5.151 ns/op
[info] UncheckedBenchmark.infoCondition avgt 5 93.347 ± 2.561 ns/op
[info] UncheckedBenchmark.infoExplicitPredicate avgt 5 60.161 ± 0.945 ns/op
[info] UncheckedBenchmark.infoWhen avgt 5 62.670 ± 1.166 ns/op
[info] UncheckedBenchmark.infoWithArg1 avgt 5 79.083 ± 1.462 ns/op
[info] UncheckedBenchmark.infoWithArg1Arg2 avgt 5 68.226 ± 3.502 ns/op
[info] UncheckedBenchmark.infoWithArgs avgt 5 100.909 ± 10.412 ns/op
[info] UncheckedBenchmark.neverInfo avgt 5 2.301 ± 0.132 ns/op
[info] UncheckedBenchmark.neverTrace avgt 5 2.277 ± 0.070 ns/op
[info] UncheckedBenchmark.trace avgt 5 3.574 ± 0.227 ns/op
[info] UncheckedBenchmark.traceCondition avgt 5 18.149 ± 0.591 ns/op
[info] UncheckedBenchmark.traceExplicitPredicate avgt 5 3.523 ± 0.089 ns/op
[info] UncheckedBenchmark.traceWhen avgt 5 8.010 ± 0.137 ns/op
[info] UncheckedBenchmark.traceWithArg1 avgt 5 3.517 ± 0.042 ns/op
[info] UncheckedBenchmark.traceWithArg1Arg2 avgt 5 3.534 ± 0.061 ns/op
[info] UncheckedBenchmark.traceWithArgs avgt 5 6.773 ± 0.568 ns/op
The source code for this page can be found here.