JLBH - Introducing Java Latency Benchmarking Harness

In this Post:

• What is JLBH
• Why did we write JLBH
• Differences between JMH and JLBH
• Quick start guide

What is JLBH?

JLBH is a tool that can be used to measure latency in Java programs. It has these features:

• Aimed at running code that would be larger than a micro benchmark.
• Suitable for programs that use asynchronous activity like the producer consumer pattern. 
• Ability to benchmark individual points within the program
• Ability to adjust the throughput into the benchmark
• Adjusts for coordinated omission i.e. end to end latencies of iterations impact each other if they back up
• Reports and runs its own jitter thread

Why did we write JLBH?

JLBH was written because we needed a way of benchmarking Chronicle-FIX. We created it to benchmark and diagnose issues in our software. It has proved extremely useful and it is now available in the Chronicle open source libraries.

Chronicle-FIX is an ultra low latency Java fix engine. It guarantees latencies, for example, that parsing a NewOrderSingle message into the object model will not exceed 6us all the way to the 99.9th percentile. In fact we needed measure all the way along the percentile range. This is latency / percentile typical profile. 

50     -> 1.5us
90     -> 2us
99     -> 2us
99.9   -> 6us
99.99  -> 12us
99.999 -> 35us
Worst  -> 500us

Chronicle Fix guarantees these latencies with various throughputs ranging from 10k messages / second to 100k messages / second. So we needed a test harness where we could easily vary the throughput.

We also needed to account for co-ordinated omission. In other words we couldn't just ignore the effect of a slow run on the following run. If run A was slow and that caused run B to be delayed, even if run B had no latency in its own run, that fact that it was delayed still had to be recorded.

We needed to try to differentiate between OS jitter, JVM jitter, and jitter caused by our own code.  For that reason we added the option to have a jitter thread that did nothing but sample jitter in the JVM. This would show up a combination of OS jitter e.g. thread scheduling and general OS interrupts and global JVM events such as GC pauses.  

We needed to attribute the latencies as best possible to individual routines or even lines of code, for this reason we also created the possibility of adding custom sampling into the program.  The addition of NanoSamplers adds very little overhead to the benchmark and allows you to observe where your program introduces latency.

This is a schematic view of the benchmark we constructed to measure Chronicle-FIX.

We ended up with results like these:

This was typical run:

Run time: 100.001s
Correcting for co-ordinated:true
Target throughput:50000/s = 1 message every 20us
End to End: (5,000,000)                         50/90 99/99.9 99.99/99.999 - worst was 11 / 15  17 / 20  121 / 385 - 541
Acceptor:1 init2AcceptNetwork (4,998,804)       50/90 99/99.9 99.99/99.999 - worst was 9.0 / 13  15 / 17  21 / 96 - 541
Acceptor:1.1 init2AcceptorNetwork(M) (1,196)    50/90 99/99.9 99.99 - worst was 22 / 113  385 / 401  401 - 401
Acceptor:2 socket->parse (4,998,875)            50/90 99/99.9 99.99/99.999 - worst was 0.078 / 0.090  0.11 / 0.17  1.8 / 2.1 - 13
Acceptor:2.0 remaining after read (20,649,126)  50/90 99/99.9 99.99/99.999 99.9999/worst was 0.001 / 0.001  0.001 / 0.001  0.001 / 1,800  3,600 / 4,590
Acceptor:2.1 parse initial (5,000,100)          50/90 99/99.9 99.99/99.999 - worst was 0.057 / 0.061  0.074 / 0.094  1.0 / 1.9 - 4.7
Acceptor:2.5 write To Queue (5,000,100)         50/90 99/99.9 99.99/99.999 - worst was 0.39 / 0.49  0.69 / 2.1  2.5 / 3.4 - 418
Acceptor:2.9 end of inital parse (5,000,000)    50/90 99/99.9 99.99/99.999 - worst was 0.17 / 0.20  0.22 / 0.91  2.0 / 2.2 - 7.6
Acceptor:2.95 on mid (5,000,000)                50/90 99/99.9 99.99/99.999 - worst was 0.086 / 0.10  0.11 / 0.13  1.4 / 2.0 - 84
Acceptor:3 parse NOS (5,000,000)                50/90 99/99.9 99.99/99.999 - worst was 0.33 / 0.38  0.41 / 2.0  2.2 / 2.6 - 5.5
Acceptor:3.5 total parse (5,000,000)            50/90 99/99.9 99.99/99.999 - worst was 1.1 / 1.2  1.8 / 3.0  3.5 / 5.8 - 418
Acceptor:3.6 time on server (4,998,804)         50/90 99/99.9 99.99/99.999 - worst was 1.1 / 1.2  1.8 / 3.1  3.8 / 6.0 - 418
Acceptor:4 NOS processed (5,000,000)            50/90 99/99.9 99.99/99.999 - worst was 0.21 / 0.23  0.34 / 1.9  2.1 / 2.8 - 121
Jitter (5,000,000)                              50/90 99/99.9 99.99/99.999 - worst was 0.035 / 0.035  0.035 / 0.037  0.75 / 1.1 - 3.3
OS Jitter (108,141)                             50/90 99/99.9 99.99 - worst was 1.2 / 1.4  2.5 / 4.5  209 - 217

All samples are summarised across runs at the end of the benchmark here are couple:

-------------------------------- SUMMARY (Acceptor:2.95 on mid)----------------------
Percentile     run1      run2      run3   run4         run5     % Variation var(log)
50:           0.09      0.09      0.09    0.09         0.09         0.00        3.32
90:           0.10      0.10      0.10    0.10         0.10         0.00        3.58
99:           0.11      0.11      0.11    0.11         0.11         2.45        3.69
99.9:         0.13      0.13      0.62    0.78         0.13        76.71        6.01
99.99:        1.50      1.38      1.82    1.89         1.70        19.88        9.30
worst:        1.95      2.02      2.11    2.24         2.24         6.90        9.90
-------------------------------------------------------------------------------------
-------------------------------- SUMMARY (Acceptor:3 parse NOS)----------------------
Percentile   run1   run2    run3    run4         run5      % Variation   var(log)
50:          0.33   0.33    0.34    0.36         0.36         6.11        5.75
90:          0.38   0.38    0.46    0.46         0.46        12.42        6.24
99:          0.41   0.41    0.50    0.53         0.50        16.39        6.47
99.9:        2.11   2.02    2.11    2.11         2.11         3.08        9.76
99.99:       2.37   2.24    2.37    2.37         2.37         3.67       10.05
worst:       2.88   2.62    3.14    3.14         2.88        11.51       10.67

-------------------------------------------------------------------------------------

Using JLBH we were able to both benchmark our application against the criteria in the specification as well as diagnosing some of the latency spikes.

By varying the throughput and the run time of the benchmark and especially by adding sampling to various points in the code patterns started to emerge which lead us to the source of the latency. A particular example of this was an issue with DateTimeFormatter casing a TLB cache miss but that will be the subject of another post.

Differences between JMH and JLBH

I would expect most of those reading this article to be familiar with JMH (Java MicroBenchmarking Harness), this is an excellent tool for micro benchmarks and if you haven't already used it it's a worthwhile tool every Java developer should have in their locker. Especially those concerned with measuring latencies.

As you will see from JLBH design much of it was inspired by JMH.

So if JMH is so great why did we have to create another benchmark harness? 

I guess at a high level the answer is in the name.  JMH is squarely aimed at micro benchmarks whilst JLBH is there to find latencies in larger programs.

But it's not just that. After reading the last section you will see that there are a number of reasons you might want to choose JLBH over JMH for a certain class of problem.

Btw although you can always use JLBH instead of JMH, if you have a genuine micro benchmark that you want measured as cleanly and as exactly as possible I would always recommend you use JMH over JLBH. JMH is an extremely sophisticated tool and does what it does really well for example JMH forks JVMs for each run which at the present moment JLBH does not.   

When you would use JLBH over JMH:

• If you want to see your code running in context.  (See JLBH Examples 1 - Why Code Should be Benchmarked in Context for a full treatment of this concept with examples.) The nature of JMH is to take a very small sample of your code, let's say in the case of a FIX engine just the parsing, and time it in isolation.  In our tests the exact same fix parsing took over twice as long when run in context i.e. as part of the fix engine, as they did when run out of context i.e. in a micro benchmark. I have a good example of that in my Latency examples project DateSerialise where  I demonstrate that serialising a Date object can take twice as long when run inside a TCP call. The reason for this is all to do with CPU caches and something we will return to in a later blog.
• If you want to take into account coordinated omission.  In JMH, by design, all iterations are independent of each other, so if one iteration of the code is slow it will have no effect on the next one.  We can see a good example of this in the my Latency examples SimpleSpike where we see the huge effect that accounting for coordinated omission can have. Real world examples should almost always be measured when accounting for coordinated omission.
  For example let's imagine you are waiting for a train and get delayed in the station for an hour because the train in front of you was late.  Let's then imagine you get on the train an hour late and the train takes it's usual half an hour to reach it's destination. If you don't account for coordinated omission you will not consider yourself to have suffered any delay as your journey took exactly the correct amount of time even though you waited for an hour at the station before departing!
• If you want to vary throughput into your test. JLBH allows you to set the throughput as a parameter to your benchmark. The truth is that latency makes little sense without a defined throughput so it's extremely important that you are able to see the results of varying the throughput on your latency profile. JMH does not allow you to set throughput. (In fact this goes hand in hand with the fact that JMH does not account for coordinated omission.)
• You want to be able to sample various points within your code.  An end to end latency is great as a start but then what? You need to be able to record a latency profile for many points within the code. With JLBH you can add probes into your codes wherever you choose at very little overhead to the program. JMH is designed so that you only measure from the start of your method (@Benchmark) to the end.
• You want to measure OS and JVM global latencies. JLBH runs a separate jitter thread.  This runs in parallel to your program and does nothing but sample latency by repeatedly calling System.nanoTime(). Whilst this doesn't in of itself tell you all that much it can be indicative as to what is going on side your JVM during the time of the benchmark. Additionally you can add a probe which does nothing (this will be explained later on) where you can sample latency inside the thread that runs the code you are benchmarking. JMH does not have this sort of functionality.

As I mentioned earlier, if you don't want to use one or more of these functionalities than favour JMH over JLBH.

Quick Start Guide

The code for JLBH can be found in Chronicle-Core library which can be found on GitHub over here.

To download from Maven-Central include this in your pom.xml (check the latest version):

<dependency>

    <groupId>net.openhft</groupId>

    <artifactId>chronicle-core</artifactId>

    <version>1.4.7</version>

</dependency>




To write a benchmark you have implement the JLBHTask interface:

It has just two methods you need to implement:

• init(JLBH jlbh) you are passed a reference to JLBH which you will need to call back on (jlbh.sampleNanos()) when your benchmark is complete. 
• run(long startTime) the code to run on each iteration. You will need to retain the start time when you work out how long your benchmark has taken and call back on jlbh.sampleNanos(). JLBH counts the number of times sampleNanos() is called and it must exactly match the number of times run() is called. This is not the case for other probes you can create.
• There is third optional method complete()that might be useful for cleanup for certain benchmarks.

All this is best seen in a simple example:

In this case we measure how long it takes to put an item on an ArrayBlockingQueue and to take it off again.

We add probes to see how long the call to put() and poll() take.

I would encourage you to run this varying the throughput and the size of the ArrayBlockingQueue and see what difference it makes. 

You can also see the difference it makes if you set accountForCoordinatedOmission to true or false.

Take a look look at all the options with which you can set up your JLBH benchmark which are contained in JLBHOptions.

In the next posts we will look at some more examples of JLBH benchmarks.

Please let me know if you have any feedback on JLBH - if you want to contribute feel free to fork Chronicle-Core and issue a pull request!

Learn about JDK9 Compact Strings (Video review Charlie Hunt)

JDK 9 introduces a new feature called Compact Strings.  Given the ubiquity of Strings in Java programs I feel that this is a really important change that needs to be understood by all Java developers.

In this video Charlie Hunt explains the history and implementation of this new feature.  The video is not actually about Compact Strings. Compact Strings are only introduced as a case study to explain how with a lot of work, the three legged stool of, latency, throughput and memory footprint can all be improved together.

If you have the time I definitely recommend watching the whole video - although the actual part on Compact Strings start at 26:24.

If you want a 5 minute overview here are the highlights:

• String density (JEP 254 Compact Strings) is a feature of JDK 9.
• Aims were to reduce memory footprint without affecting any performance - latency or throughput as well maintaining full backward compatibility.
• JDK 6 introduced compressed strings but this was never brought forward into later JVMs.  This is a complete rewrite.
• To work out how much memory could be saved 960 disparate java application heap dumps were analysed.
• Live data size of the heap dumps were between 300MB and 2.5GB.
• char[] consumed between 10% and 45% of the live data
• vast majority of chars were only one byte in size (i.e. ASCII) 
• 75% of the char arrays were 35 chars or smaller
• On average reduction in application size would be 5-15% (reduction in char[] size about 35-45% because of header size)
• The way it will be implemented is that if all chars in the String use only 1 byte (the higher byte is 0) then a byte[] will be used rather than char[] (IS0-8859-1/Latin1 encoding).  There will a leading bye to indicate which encoding was used.
• UTF8 not used because it supports variable length chars and is therefore not performant for random access.
• private final byte coder on the String indicates the encoding.  Note the room to support many more encodings in the future.
• For all 64 bit JVMs no extra memory was needed for the extra field because of the 'dead' space needed for 8 byte object alignment.
• Throughput doesn't suffer as tested with 400 JMH benchmarks available online.
• The reason for this is that String is highly optimized in that there 55 specific JVM features for String alone.
• Latency also improved tested with industry benchmark SPECjbb2015 also regression tested on SPECjbb2005
• Feature can be enabled and disabled with -XX:+CompactStrings but will be enabled by default.

How to set up repository authentication with Gradle

• Setting up repository authentication with Gradle

In the previous post I showed you how to move a project from maven to Gradle. One of the issues I had was that authenticated repositories no longer worked (in Maven they were using the setting.xml file in the .m2 directory). I'm sure this is standard knowledge for any Gradle user but it took a little figuring out as a Maven user.

First create a file called gradle.properties and same it into the same directory as your build.gradle. It doesn't have to live there but it's a good place to start. See more here.

Add the following lines to the gradle.properties file:

repoUser=user123

repoPassword=123abc

Then in your build.gradle add the following:

repositories {

    maven {

        credentials {

            username repoUser

            password repoPassword

        }

        url "http://nexus........."

    }

}

Moving from Maven to Gradle in under 5 minutes

• How to move a project from Maven to Gradle

For mainly historic reasons I've been a heavy Maven users for all my projects and not really dipped more than a toe into the 'holy grail' that is Gradle.

So I was pleased to be set the challenge by one of my clients, that as part of the delivery they wanted the code moved from Maven to Gradle.

After a bit of research (as well as some trial and error) I can take you through the steps that should be able to convert a Maven project to Gradle in about 5 minutes. (Note I've used IntelliJ but I would imagine this should be pretty much the same on any other IDE - or even if you're not using an IDE). 

1. Install Gradle on your machine.  You can get the software from here.
2. Check out (or copy) your code into a new directory.  This is not strictly necessary but it makes things cleaner.
3. cd into the directory that contains your pom.xml
4. Run the command: run gradle init.  This will create a new gradle project creating a build.gradle file based on your pom.xml.  (Note this is an incubator feature but it seems to work quite well).
5. Create a new IntelliJ project as follows:  File -> New -> Project From Existing Sources. Select the build.gradle file you created in the previous step and choose the following defaults as in this dialog:

That's really all there is to it. A brand new Gradle project.

Here are some additional notes I found useful as a Gradle newbie:

1. If you want to include files you already have in your existing Maven .m2 repo add mavenLocal() as a dependency.
2. Your dependencies get downloaded here (the equivalent of .m2): 
   .gradle/caches/modules-2/files-2.1
3. This is the correct way to define jdk compatibility:def javaVersion = JavaVersion.VERSION_1_8;sourceCompatibility = javaVersion;targetCompatibility = javaVersion;
4. To see the results of your tests as they are running add this method to your build.gradletest { testLogging {     events "started", "passed", "skipped", "failed", "standardOut", "standardError" }}
5. If you have repositories that need authentication see here.

Starting out with ChronicleMap: Using Off Heap Memory

Introduction

This post will introduce you to ChronicleMap and explain how by using off heap memory you can do things you might never expect a Java program to be able to do. Using off heap memory is very un-Javaish. If you're following the debate about UNSAFE in Java 9 you will appreciate just how controversial it is. Nevertheless it provides the power to do some some really useful things. ChronicleMap harnesses the power of UNSAFE, taming it and making it 'SAFE' for the rest of us to use. 

Let's demonstrate using a really simple use case for ChronicleMap

Scenario: Your server accepts requests from many clients. You want to keep a count of the requests from each client. You must ensure that every time the request count is incremented the number is persisted to disk to prevent against your process crashing and the data being lost.

Traditional approach: Create a table in database with two columns, clientID and requestCount. Every time you get a request from a client fetch the client's requestCount from the database, increment it and save the result back into the database. The actual database interaction can be abstracted somewhat by having data beans using Hibernate or the equivalent. But then you have deal with configuration and you still have to setup a database...   

Wouldn't it be nice if: We could just save the data to a java.util.Map and that would be all the configuration you would need.

Enter ChronicleMap: ChronicleMap is just like a normal java HashMap except that rather than saving its data to on-heap memory it saves its data to off-heap memory. Since the off heap memory is backed by a memory mapped file all the data gets flushed to disk and persisted by the OS. 

What's the difference between on and off heap memory: On heap memory is memory 'managed' by the JVM.  Most importantly all data that is allocated on heap is subject to garbage collection.  (This has its pros and cons but more of that another time).  This memory is entirely local to the JVM and data in on heap memory will be lost when the JVM dies.  Off heap memory is unmanaged memory. It can be shared between processes and persisted through memory mapped files.

Enough of the theory: Let's see the code for this in practice.

To add Chronicle-Map to you project just add this Maven dependency:

<dependency>
    <groupId>net.openhft</groupId>
    <artifactId>chronicle-map</artifactId>
    <version>2.4.12</version>
</dependency>

It takes exactly 2 lines write the code for our scenario - have a look at the code below:

The first line creates the map and the second updates it as you would any other java.util.concurrent.ConcurrentMap.

Each time you run the program you will notice that the number of user requests for "user1" is incremented.

A note to explain the parameters to the constructor: To achieve the greatest performance with ChronicleMap the Map does not resize.  (Apart from anything else ChronicleMap was written as a performant data store for low latency systems but that's not what we are really concentrating on in this post). Therefore, to enable the Map to reserve the correct amount amount of disk space we must specify the maximum number of entries and also give it a rough idea of the length of the Strings in the key. (You shouldn't worry too much about over estimating the number of entries as disk space is only taken passively and will only be used if required.)

A deeper look into off heap memory: Hopefully that was simple enough we've seen how you can use ChronicleMap as an implementation of java.util.Map and all inserts and updates to that map are saved to disk because ChronicleMap is backed by off heap memory.

But let's say you don't want to write the number of requests back to the map each time you want it saved to disk.  What you might want is to update the userRequests and for that number to be persisted without having to update the Map.  (It is the equivalent of having an AtomicLong stored in a HashMap.)

To do this rather than using a Long to hold the user request you should use LongValue where LongValue is just a wrapper class for a Long. Crucially though LongValue must be backed by off heap memory.  For this reason you can't just create an instance of LongValue using new as you would with normal on heap memory you need to use a factory provided by Chronicle.

It's much easier to understand this by examining as the code below:

The Map is built exactly the same way as in the simple example above other than the value type is LongValue not Long. 

The variable userRequests is create by generating a direct (off heap) instance using the call DataValueClasses.newDirectInstance().  (If you want to understand more about the internals of this code run the program in a debugger and step into line addValue() on line 28.) All the data written into this instance variable is saved off heap and therefore persisted.

Because useRequest is backed by off heap memory we can increment it on line 28 and do not have to store it back into the ChronicleMap for the data to be persisted.

One thing to point out is the the method call on the Map acquireUsing() on line 25 which allows us to fetch the data in the Map using a a pre-existing instance variable.  This means that no allocation takes place and allows for zero GC program. (This is important because GC is the enemy of predictable low latency systems).

Summary

ChronicleMap uses off heap memory to enable:

• persistence (as we have seen in this post)
• IPC (inter process communication) you can share the ChronicleMap between more than one JVM.
• Zero GC (important for real-time systems)

If you need any of the above you might consider using ChronicleMap in your code!

Writing 2 Characters into a Single Java char

Here's another nice trick we used when creating the ultra low latency Chronicle FIX-Engine.

When it comes to reading data off a stream of bytes it's way more efficient, if possible, to store data in a char rather than having to read it into a String.  (At the very least you are avoiding creating a String object, although this can be mitigated by using a cache or working with CharSequence rather than String but that's the subject of another post.)

Using JMH benchmarks I've found these timings: (I haven't included the source code for this as this is going to be the subject of another post where I describe the different methodologies in more detail).

Reading 2 ascii characters off a bytes stream into:

String - 34.48ns
Pooled String - 28.57ns
StringBuilder - 21.27ns
char (using 2 chars method) - 6.75ns

(As a benchmark reading a single char takes 3.27ns.)

The point is that it takes at least 3 times longer to read data into a String than a char, and that doesn't even take into account the garbage created.

So it goes without saying that when you know that you are expecting data that is always a single character, rather than reading that data into a String variable you should read it into a char.

Now what if you know that that data you are expecting on the stream is no more than 2 characters. (You find this situation, for example in FIX 5.0 tag 35 msgType). Do you have to use a String so that you can accommodate the extra character?  At first thoughts it appears so, after all a char can only contain a single character.

Or can it? 

A java char is made up of 2 bytes not one.  Therefore if you know that your data is made up of ascii characters you know that only a single byte (of the 2 bytes in the char) will be used. For example 'A' is 65 though to 'z' which is 122. 

You can print out the values that fit into a single byte with this simple loop:

for (int i = 0; i < 256; i++) {
    char c = (char)i;
    System.out.println(i+ ":" + c);
}

You are now free to use the other bye of the char to hold the second ascii character.

This is the way to do it: 

In this example you have read 2 bytes 'a' and 'b' and want to store them in a single char.

byte a = (byte)'a';
byte b = (byte)'b';
//Now place a and b into a single char
char ab = (char)((a << 8) + b);
//To retrieve the bytes individually see code below 
System.out.println((char)(ab>>8) +""+ (char)(ab & 0xff)); 
To better understand this let's look at the binary:

byte a  = (byte)'a' // 01100001
byte b  = (byte)'b' // 01100010

As you can see below, when viewed as a char, the top 8 bits are not being used

char ca = 'a' // 00000000 01100001
char cb = 'b' // 00000000 01100010

Combine the characters with a taking the top 8 bits and b the bottom 8 bits.
char ab = (char)((a << 8) + b); // 01100001 01100010

Summary

It's more efficient reading data into a char rather than a String.  If you know that you have a maximum of 2 ascii characters they can be combined into a single Java char.  Of course only use this technique if you really are worried about ultra low latency!