Logging Performance Comparison

Agreeing with others—these benchmarks are not quite telling us what we want to know. The problem is that the endpoints aren’t doing any work, so logging dominates.

You might think “that’s ok, it still shows me the overhead of logging.” This is subtly wrong, though, because you can’t necessarily talk about the overhead of logging without saying how much logging, from how many threads, with how much other work.

Take the simplest case, stdout. Writing to stdout requires a lock. If logging is sufficiently rare, most of the time, there’s no wait. As logging increases in frequency, there is more contention. Doubling the number of writes more than doubles the time spent logging, because of that contention.

To benchmark this properly, you’d[0] want to have a test where the total number of requests/second without logging and the number of logs/request as independent variables. That would show you the regions where logging becomes a bottleneck, and regions where it’s not.

[0] At a minimum. I’m not saying this would be an ideal benchmark—if you’re not doing marketing, benchmarks aren’t about “let’s find the biggest number”, but accurately modeling a phenomenon so that you can make predictions. That means you might need to do a lot of experimentation.

    for (; counter < 1_000; counter++) {
        // ... I know this doesn't make much sense :)
    }

I think the JVM would optimise away this loop because it doesn't do anything. e.g. if the loop optimisation method is to unroll the loop into 1000 inline statements, there's nothing there.

This makes "No Logging" result not quite a fair comparison; maybe something like the sum of 1000 random numbers do some actual work in the loop.

I wonder if the no logging case actually tested what the author intended, or if the compiler simply optimized away the empty loop that was supposed to stand in for doing useful work in a transaction.

Now compare the efficiency of minimal logging compared to lotsa logging (even if most of it is only conditionally enabled), when optimising for dev time spent on troubleshooting :)

The one thing from modern Java logging I love and miss in other languages is being able to set log levels on specific loggers while the app is running.

Yeah it involves JMX, which has an annoying protocol that insists on domain names that you can resolve, making it a PITA with K8s from your local terminal, but it's such a QoL feature.

Huh, the GH repo contains a logback-async test case, but the article omits it. I've found it to be pretty fast in the past.

I really hope no one takes this analysis to heart. If I was moved onto a project without logging for this reason I would be pretty pissed. If you already have the quarkus project, why not get some metrics in real use-cases, instead of a weird do-nothing loop?

This only makes sense when logging is a substantial portion of the wall-clock time of a transaction. The moment you do any other I/O, even if that is just to hit a database this difference becomes completely irrelevant.

The tests he created effectively made logging dominate the request active time so it's rather deceptive in that manner.

His non-logging case was probably entirely optimized away by Hotspot unless he is running these benchmarks under JMH and properly disabled optimizations for that loop.

Remember: System.out is a PrintStream which is a synchronized class. So multiple threads writing large amounts to System.out will block each other for sure

Interesting. I noticed massive performance improvements when I went to a decent buffered logger in Clojure and Go projects. IIRC, there was no distinguishable difference from the “no logging” scenario for real world workloads (where the buffered channel never fills completely). This makes me want to revisit those tests and see if I’m misremembering, though.

Really liked the data driven approach of this article

Isn't buffered log writer prone to error (read not flushing to output) in case of ie. Premature container termination?