MattHicks.com

Programming on the Edge

Scribe 2.0: Fastest JVM Logger in the World!

Published by Matt Hicks under , , , , , , , , , , on Tuesday, February 06, 2018
An intentionally provocative heading, but one I stand behind until someone can prove otherwise (and I welcome just that).  Scribe 1.x was pretty fast (http://www.matthicks.com/2017/01/logging-performance.html), but was not written with performance in mind.  When I came back around and realized just how fast log4j2 is, I could see no reason why a Scala logging solution shouldn't be able to run circles around it.

Note: the benchmarks below are tested using simple file logging to represent the most common production logging scenario.

Log4J Comparison

Now, for people like me that often want to skip all the blustering, explanations, and bravado, I'll cut straight to the result graph of the performance comparison between log4j 2.10.0 and Scribe 2.0.0:

Like I said, log4j2 is fast, but Scribe 2 is just shy of a 50% performance boost on that.  If we look at the over-time graph it provides additional insights:

You can see that log4j does well, but operations increase in cost partway through, while Scribe is smooth and steady for the entire run.

Method and Line Numbers

This is all compelling but practically speaking, 99% of applications won't even notice the difference between 1,500 nanoseconds and 800 nanoseconds per record logging.  Thus far I've been comparing Apples to Oranges though.  In Scribe, the method and line numbers are integrated into the log records by default.  If we add that to the logging (which any reasonable logging framework should have) we see a different story:

Shocking, right?  If you know Java, you'll probably realize why this is.  In Java, the only way to get access to method and line numbers in your logging is by walking the stack trace.  This is a very expensive operation to be doing and slows the logging to a crawl.  This is why it's not on by default, and why you don't see this talked about much in Java logging frameworks.  However, Scala Macros come to the rescue!  In Scribe, we get all of that for free.  The method and line number information are extracted at compile-time so you can see that Scribe is just as fast whether method and line number logging is enabled or not.

Typesafe Scala Logging

In 1.x my focus was the comparison with Scala Logging.  As you can see below, we're not even in the same ballpark:


It's a pretty pathetic comparison.  In Scribe, 1.x Scribe was noticeably faster, but this shows just how inefficient Scala Logging is.

All Loggers

If you'd like to see the side-by-side comparisons of all the competitors:


Though the log4jTrace and scalaLogging results dwarf the performance distinction between log4j and Scribe, if you've seen all the results here, Scribe is the clear performance winner here.  I'll make another post to show why it's also more powerful, but I'll save that for another day.

Sources

I'm not a master with log4j or Scala Logging, so it's possible I'm not giving ideal running circumstances for these loggers to "show their stuff".  The original source code is posted in the repository: https://github.com/outr/scribe/blob/master/benchmarks/src/main/scala/scribe/benchmark/LoggingSpeedBenchmark.scala

The JMH benchmark results were also saved to a JSON file if you want the raw results to make sure I'm not trying to pull a fast one: https://github.com/outr/scribe/blob/master/work/benchmark/2018.01.31.benchmarks.json

Getting Started

To learn more about Scribe and start using it, check it out here: https://github.com/outr/scribe

Please feel free to email me if you find any mistakes in anything I've said to set me straight, or you can publicly shame me by writing a comment on this post.  I welcome criticism and praise, but criticism gives me something to learn from, so it is more appreciated.

0 comments:

Post a Comment