A blog mainly about Java

Micro Benchmarking with JMH: Measure, don’t guess!

I’m sure you’ve all heard that assigning a variable to null helps the Garbage Collector, or not declaring a method final improves in lining…. But what you also know is that JVMs have evolved drastically and what was true yesterday may not be true today. So, how do we know that our code performs? Well, we don’t, because we are not supposed to guess what the JVM does… we just measure!

Measure, don’t guess!

As my friend Kirk Pepperdine once said, “Measure, don’t guess“. We’ve all faced performance problems in our projects and were asked to tune random bits in our source code… hoping that performance will get improved. Instead, we should setup a stable performance environment (operating system, JVM, application server, database…), measure continuously, set some performance goals… then, take action when our goals are not achieved. Continuous delivery, continuous testing… is one thing, but continuous measuring is another step.

Anyway, performance is a dark art and it’s not the goal of this blog post. No, I just want to focus on microbenchmarking and show you how to use JMH on a real use case : logging.

Microbenchmarking Logging

I’m sure that, like me, you’ve spent the last decades going from one logging framework to another one and you’ve seen different ways to write debug logs:

These are all debug messages and we usually don’t care because in production we run with an INFO or WARNING level. But debug logs can have an impact on our performances… even if we are in WARNING level. To prove it, we can use Java Microbenchmarking Harness (JMH) to make a quick microbenchmark and measure the performance of the three logging mechanism: Concatenating strings, Using variable arguments and Using the if debug enabled.

Setting up JMH

JMH is a Java harness for building, running, and analysing nano/micro/milli/macro benchmarks written in Java and other languages targeting the JVM. It’s really easy to setup and, thanks to the Maven archetype, we can quickly get a JMH project skeleton and get going. For that, execute the following Maven command:

A pom.xml file with the JMH dependencies and a customized maven-shade-plugin to get a uber-jar

An empty MyBenchmark class with a @Benchmark annotation

At this point we haven’t done anything yet, but the microbenchmark project is already up and running. Packaging the code with Maven will create a uber-jar called benchmarks.jar.

$ mvn clean install
$ java -jar target/benchmarks.jar

When we execute the uber-jar, we see a funny output in the console: JMH goes into a loop, warms up the JVM, executes the code inside the method annotated @Benhmark (empty method for now) and gives us the number of operations per seconds

The good thing with the maven-shade-plugin is that when I package the application, all the dependencies, configuration files and so on, will all get flatten into the uber-jar target/benchmarks.jar.

Using String Concatenation in the Logs

Let’s do the first micro benchmark: using logs with string concatenation. The idea here is to take the MyBenchmark class and add the needed code into the method annotated with @Benchmark, and let JMH do the rest. So, we add a Logger, create a few string (x, y, z), do a loop, and log a debug message with string concatenation. This will look like this:

Result of the Microbenchmarks

After running the three micro-benhmarks we get what we had expected (remember, don’t guess, measure). The more operation per second, the better. So if we look at the last line of the following table, we notice that the best performance is with the isDebugEnabled and the worse is String concatenation. Then, as we can see, variable argument without isDebugEnabled is not bad either… plus we gain in visibility (less boiler plate code). So I’ll go with variable arguments !

String concatenation

Variable arguments

if isDebugEnabled

Iteration 1

57108,635 ops/s

97921,939 ops/s

104993,368 ops/s

Iteration 2

58441,293 ops/s

98036,051 ops/s

104839,216 ops/s

Iteration 3

58231,243 ops/s

97457,222 ops/s

106601,803 ops/s

Iteration 4

58538,842 ops/s

100861,562 ops/s

104643,717 ops/s

Iteration 5

57297,787 ops/s

100405,656 ops/s

104706,503 ops/s

Iteration 6

57838,298 ops/s

98912,545 ops/s

105439,939 ops/s

Iteration 7

56645,371 ops/s

100543,188 ops/s

102893,089 ops/s

Iteration 8

56569,236 ops/s

102239,005 ops/s

104730,682 ops/s

Iteration 9

57349,754 ops/s

94482,508 ops/s

103492,227 ops/s

Iteration 10

56894,075 ops/s

101405,938 ops/s

106790,525 ops/s

Average

57491,4534 ops/s

99226,5614 ops/s

104913,1069 ops/s

Conclusion

In the last decades JVMs have evolved drastically. Design pattern that would optimize our code ten years ago are not accurate anymore. The only way to be sure that one piece of code is better that another piece of code, is to measure it. JMH is the perfect tool to easily and quickly micro benchmark pieces of code, or like in this post, an external framework (logging, utility classes, date manipulation, apache commons….). Of course, reasoning about a small section of code is only one step because we usually need to analyze the overall application performance. Thanks to JMH this first step is easy to make.

And remember to check the JMH examples, it’s full of interesting ideas.

The problem with varargs is that it can lead to quite a lot of litter. First of course the array creation, but if there are any primitives, these will be autoboxed. So I would really think twice about using anything else then the ‘isDebugEnabled’ approach.

Thank you for this writeup. Do you have any ideas how to apply JMH benchmarking in Android apps? I mean, if I am using Android Studio, I am not really dealing with running jars and Maven. But still, I’d like to benchmark my Java code…