Logging Performance Comparison

https://blog.sebastian-daschner.com/entries/logging-performance-comparison

by firstSpeaker • 4 years ago

70 19 4 years ago

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.

catsarebetter• 4 years ago

Really liked the data driven approach of this article

invalidname2• 4 years ago

Yes, but the methodology is completely broken. He uses microbenchmarks on a JVM which can eliminate these instantly. It's inconsistent with findings from other logging benchmarks (especially the last bit).

abeyer• 4 years ago

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.

christophilus• 4 years ago

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.

jpgvm• 4 years ago

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.

hyperpape• 4 years ago

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.

ahpeeyem• 4 years ago

    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.

invalidname2• 4 years ago

Exactly my thoughts when reading the article. A bad micro-benchmark that puts everything in bad context as a result. I have numbers on the impact of logging from other articles that show a significant impact, but nothing at this scale.

j16sdiz• 4 years ago

In many C/C++ optimizing compiler, this is replaced with `counter = 1000;`.

I have no idea how java handle this.. Does the AOT compiler do any optimization? Would this defer to the JIT?

thfuran• 4 years ago

There is aot native compilation in javaland these days, but I assume you mean javac, the compiler that transforms source into jvm bytecode. It defers pretty much all optimization to the JITs and won't remove empty loops.

EdwardDiego2• 4 years ago

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.

frant-hartm• 4 years ago

Both Log4j2 and Logback support automatic reloading of the configuration file at a regular interval - just update the file and the log library picks it up after X seconds.

Should work well with K8s config map mounted as volume.

twic2• 4 years ago

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 :)

Or even for successful requests per second averaged over spans of time including normal outages, degradations, and other indignities of life. It doesn't take many minutes at zero throughput to drag those averages down, so every minute shaved off by more illuminating logging is a performance benefit.

gianone• 4 years ago

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

wormik• 4 years ago

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

twic2• 4 years ago

Yes, as he says:

The downside of this approach is that if the system crashes without a chance to flush the buffer, the last lines might not have been written and may be lost.

willsmith72• 4 years ago

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?

Logging Performance Comparison

Related Stories