HdrHistogram: A better latency capture method

Some years back I was working on a latency sensitive application, and since latency was sensitive it was a requirement that we somehow capture latency both on a transaction/event level and in summary form. The event level latency was post processed from the audit logs we had to produce in any case, but the summary form was used for live system monitoring. We ended up with a solution I've seen since in many places (mild variations on a theme), which is what I've come to think of as the linear buckets histogram:

	// Illustration of principal, simplified code. DO NOT COPY AND PASTE!
	class LinearBucketHistogram {
	long[] counters;
	long bucketSize;
	LinearBucketHistogram(long maxTrackableValue, long resolution) {
	bucketSize = resolution;
	counters = new long[(int) (maxTrackableValue/bucketSize + 1)];
	}
	void record(long val) {
	counters[(int) (val/bucketSize)]++;
	}
	}

view raw LinearBucketHistogram.java hosted with ❤ by GitHub

The above data structure was an easy solution to a problem we had little time to solve, but it left much to be desired.
These days the histogram problem is gloriously solved by the HdrHistogram (High Dynamic Range), and though it's been around for a couple of years now I still find olden hand rolled histograms in many a code base. Cut that shit out boys and girls! Let me show you a better way :-)

HdrHistogram highlights:

• Mature and battle tested, this data structure has been in production for many companies for a while now. Kinks have been unkinked and knickers untwisted.
• Multi-lingual support: current implementations available in Java, C, C#, Erlang, Go and more are on the way.
• Auto-resizing histograms (if you exceed your initial miximum value estimate)
• Compact memory footprint supporting high precision of values across a wide range.
• Compressed lossless serialization/de-serialization
• Plotting scripts for gnuplot, a webby charting tool and an excel sheet chart
• Lock-free concurrency support for recording and logging from multiple threads
• Zero allocation on recording path (unless resizing which is optional, and then only if value exceeds initially specified max recorded value)
• Constant time measurement which is less than cost of calling System.nanoTime() (on the cost, scalability and trustworthiness of nanoTime read Shipilev's excellent report)

It is truly as if the bees-knees and the dogs-bollocks had a baby, is it not?

Mama, what's a histogram?

"Histogram of arrivals per minute" by DanielPenfield
Own work. Licensed under CC BY-SA 3.0 via Wikimedia Common

Well, you could look it up on wikipedia, but the short answer is that a histogram is a summary of data in terms of the frequency of ranges of values.  So given the following data set [1,2,3,...,100000] captured for a second I could summarize in several ways:

• I could capture the whole range of values each value in a bucket of it's own, assigning each value a frequency of 1 per second.
• I could have a single bucket for values between 0 and 100,000, this bucket will have the frequency of 100,000 times per second.

These are both a bit silly, the first is as bad as dealing with the full set of data, the second is telling us nothing about the way the 100,000 values break down within the range. Still these are the 2 extremes of histograms, the alternatives lie within that range in terms of the data they offer but there are many ways to skin a cat (apparently, :( poor cats):

• Capture the values in 1000 buckets, each bucket representing a range of 100 values: [1..100][101..200]...[99,901..100,000] that will result in 1,000 buckets each with a frequency of 100. This is the sort of histogram described above where all buckets capture the same fixed range.
• Capture the values in 17 buckets, each bucket K representing a range [2^K..(2^(K+1)-1)] e.g. [1..1][2..3][4..7]...[65,536..131,071]. This would be a good solution if we thought most values are likely to be small and so wanted higher precision on the lower range, with lower and lower precision for larger values. Note that we don't have to use 2 as the base for exponential histogram, other values work as well.

Both of the above solutions trade precision across a large range with storage space. In both solutions I am required to choose up-front the histogram precision and we expect to pay for a large range with either space or precision. Now that we realize what the variables are we can describe these solutions:

• Linear buckets: For a range 0..R we will have to pay R/B space for buckets of range B. The higher R is the more space we require, we can compensate by picking a large B.
• Exponential buckets: For a range 0..R we require space of log2 of R. The bucket size grows exponentially as we track higher values.

The problem we face with latency data points is that the range of values we want to capture is rather large. It is not unreasonable to expect the latency outliers to be several orders of magnitude larger than the typical observed measurement. For example, it may well be that we are timing a method whose cost is in the 100s of nanoseconds, or a high speed connection round trip on the order of 1-100µs but on occasion our latency is dominated by some stop the world GC pause, or network congestion, which is in the order of 10ms to a few seconds. How can we correctly size the range of our histogram? Given the possibility of multi-second GC delays we need to cover a typical range of 1000ns to 100,000,000,000ns. If we used a linear histogram with a 100µs bucket we'd need 1,000,000 buckets (assuming an int counter this will add up to a ~4MB data structure).

The HdrHistogram follows a different path to the above solutions and manages to accommodate a large range with a high precision across the range in a limited space.

How does it work?

Here's what the documentation has to say:

"Internally, data in HdrHistogram variants is maintained using a concept somewhat similar to that of floating point number representation: Using an exponent a (non-normalized) mantissa to support a wide dynamic range at a high but varying (by exponent value) resolution. AbstractHistogram uses exponentially increasing bucket value ranges (the parallel of the exponent portion of a floating point number) with each bucket containing a fixed number (per bucket) set of linear sub-buckets (the parallel of a non-normalized mantissa portion of a floating point number). Both dynamic range and resolution are configurable, with highestTrackableValue controlling dynamic range, and numberOfSignificantValueDigits controlling resolution."

Hmmm... I'll admit to having difficulty immediately understanding what's happening from the above text, precise though it may be. I had to step through the code to get my head around what works why, read the above again and let it simmer. I'm not going to dig into the implementation because, while interesting, it is not the point of this post. I leave it to the reader to pester Gil Tene(the author of HdrHistogram) with implementation related questions.

The principal idea is a mix of the exponential and linear histograms to support a dynamic range precision that is appropriate to the time unit scale. At the scale of seconds we have a precision of milliseconds, at the scale of milliseconds we have a precision of microseconds etc. This translates roughly into exponential scale buckets which have linear sub-buckets.

Example: From raw recording to histogram

I have posted a while back a Java ping utility which measures the round trip between minimal client and server processes. Each round trip was recorded into a large array and every set number of round trips the measurements were summarized in percentiles:

	// ... Blah, blah, class name and stuff
	private static final int ITERATIONS = 1000000;
	private static final long[] MEASUREMENTS = new long[ITERATIONS];
	// yeah, it's all static... just worked out that way, can't remember why
	// ... Blah, blah, make a socket, send request, wait for response, measure how many nanos it took
	private static void observe(int i, long time) {
	MEASUREMENTS[i]=time;
	}
	private static void report() {
	Arrays.sort(MEASUREMENTS);
	System.out.printf("@%d,%d,%d,%d,%d,%d,%d\n",
	MEASUREMENTS[0],//minimum
	MEASUREMENTS[ITERATIONS/2],//Median
	MEASUREMENTS[(int)(ITERATIONS/100*90)],//90%ile
	MEASUREMENTS[(int)(ITERATIONS/100*99)],//99%ile
	MEASUREMENTS[(int)(ITERATIONS/1000*999)],//99.9%ile
	MEASUREMENTS[(int)(ITERATIONS/10000*9999)],//99.99%ile
	MEASUREMENTS[ITERATIONS-1]);//maximum
	}

view raw gistfile1.java hosted with ❤ by GitHub

Recording raw data is the simplest way of capturing latency, but it comes at a price. The long[] used to capture the latencies is ~8MB in size, this is for a million samples and in a real application can grow without bounds until some cutoff point where we decide to summarize or discard the data. When we want to report percentiles we have to sort it and pick the relevant data points. This is not usually an acceptable solution (because of the memory footprint), but it offers absolute accuracy and is trivial to implement (until you have to consider serialization, concurrency and visualization, but otherwise trivial).

Replacing this measurement method with a histogram is straight forward:

	private static final Histogram HDR_HISTOGRAM =
	new Histogram(TimeUnit.MINUTES.toNanos(1), 2);
	// (max recorded value , decimal places precision)
	// Same shit, different latency capture method
	private static void observe(int i, long time) {
	HDR_HISTOGRAM.recordValue(time);
	}
	private static void report() {
	System.out.printf("#%d,%d,%d,%d,%d,%d,%d\n",
	HDR_HISTOGRAM.getMinValue(),
	HDR_HISTOGRAM.getValueAtPercentile(50),
	HDR_HISTOGRAM.getValueAtPercentile(90),
	HDR_HISTOGRAM.getValueAtPercentile(99),
	HDR_HISTOGRAM.getValueAtPercentile(99.9),
	HDR_HISTOGRAM.getValueAtPercentile(99.99),
	HDR_HISTOGRAM.getMaxValue());
	HDR_HISTOGRAM.reset();
	}

view raw gistfile1.java hosted with ❤ by GitHub

This histogram is 31KB when using 2 decimal places precision which is good enough in most case (according to JOL, add it to your utility belt if it ain't there already. Increasing the precision to 3 increases the size to 220KB), which is a large improvement over 8MB. We could reduce the memory consumption further if we were willing to limit the maximum data point count per bucket and use an integer/short histogram(ints seem like a reasonable choice).

If we print both measurements methods for the same run we can see the difference between the raw data and the HDR representation which is naturally slightly less accurate (# lines are HdrHistogram,@ is for raw data, each line represents 1M data points):

	Min , 50% , 90% , 99% , 99.9% , 99.99% , Max
	#20992, 30079, 42239, 64255, 239615, 1400831, 28180479
	@21000, 30000, 42000, 64000, 239000, 1410000, 28151000
	#20992, 30079, 41215, 56063, 172031, 1294335, 28966911
	@21000, 30000, 41000, 56000, 173000, 1296000, 28880000
	#20992, 30079, 42239, 64255, 231423, 1294335, 11075583
	@21000, 30000, 42000, 64000, 231000, 1326000, 11043000
	#20992, 30079, 42239, 73215, 317439, 1441791, 46399487
	@21000, 30000, 42000, 73000, 317000, 1458000, 46214000
	#20992, 30079, 41215, 56063, 156671, 892927, 9764863
	@21000, 30000, 41000, 56000, 157000, 909000, 9718000
	#20992, 30079, 41215, 54015, 164863, 1146879, 27918335
	@21000, 30000, 41000, 54000, 164000, 1165000, 27867000

view raw gistfile1.txt hosted with ❤ by GitHub

We can see that reported percentiles are pretty close to the raw data:

• Note that the nanoTime on Mac reports in µs granularity, which is why the real values(@ lines) all end with 3 zeros.
• Note that the max/min reported are adjusted to the correct histogram resolution (not a big deal, but slightly surprising).

What would have happened with our hand rolled solution? To keep a range of 0 to 60,000,000,000ns in a linear histogram of the same memory footprint we would need to limit ourselves to roughly 220k/8=64k buckets. Each bucket would have a granularity of roughly 1ms which would have translated to a very limited visibility on the lower end of the spectrum as most data sets are actually all under 1ms. This would have also completely skewed our percentiles (i.e 99.99% results in 1ms bucket, no breakdown of behaviour in percentiles). We could try and tackle the issue by picking a lower range to cover (which if applied to HdrHistogram will minimize memory usage further) or by blowing the memory budget on finer grained buckets.

Example: Aeron samples, much percentiles! Such graphs! Wow!

Percentiles are commonly used to describe latency SLA of a given system and a typical application will report a range of percentiles to reflect the probability of a given response time. In this context we can say that a 99%ile latency of 1ms means that 99% of all requests were handled in =< 1ms.
Aeron is a low latency, reliable UDP messaging library. Since latency is an obvious concern, all the samples utilize the HdrHistogram lib to demonstrate measurement and report results, here are the relevant excerpts from the Ping sample:

	public class Ping {
	//Blah, blah, initialization stuff
	private static final Histogram HISTOGRAM = new Histogram(TimeUnit.SECONDS.toNanos(10), 3);
	public static void main(String[] args) {
	//Blah, blah, open channels, warmup etc.
	final ContinueBarrier barrier = new ContinueBarrier("Execute again?");
	do {
	HISTOGRAM.reset();
	System.out.println("Pinging " + NUMBER_OF_MESSAGES + " messages");
	sendPingAndReceivePong(pingPublication, pongSubscription, NUMBER_OF_MESSAGES);
	System.out.println("Histogram of RTT latencies in microseconds.");
	HISTOGRAM.outputPercentileDistribution(System.out, 1000.0);
	} while (barrier.await());
	}
	// each 'ping' message contains the originating timestamp, and this method is called
	// when a 'pong' message returns.
	private static void pongHandler(final DirectBuffer buffer, final int offset, final int length, final Header header) {
	final long pingTimestamp = buffer.getLong(offset);
	final long rttNs = System.nanoTime() - pingTimestamp;
	HISTOGRAM.recordValue(rttNs);
	}
	}

view raw gistfile1.java hosted with ❤ by GitHub

This results in a pile of text getting poured into the console, not that friendly:

	Value Percentile TotalCount 1/(1-Percentile)
	6.167 0.000000000000 1 1.00
	7.027 0.100000000000 5125 1.11
	7.083 0.200000000000 10509 1.25
	7.111 0.300000000000 15543 1.43
	7.135 0.400000000000 20873 1.67
	7.155 0.500000000000 25469 2.00
	7.167 0.550000000000 28146 2.22
	7.179 0.600000000000 30791 2.50
	7.191 0.650000000000 33153 2.86
	7.203 0.700000000000 35337 3.33
	7.219 0.750000000000 37914 4.00
	7.227 0.775000000000 39020 4.44
	7.235 0.800000000000 40048 5.00
	7.247 0.825000000000 41359 5.71
	7.263 0.850000000000 42782 6.67
	7.279 0.875000000000 43796 8.00
	7.291 0.887500000000 44450 8.89
	7.307 0.900000000000 45062 10.00
	7.335 0.912500000000 45674 11.43
	7.427 0.925000000000 46253 13.33
	8.127 0.937500000000 46875 16.00
	8.863 0.943750000000 47188 17.78
	9.223 0.950000000000 47501 20.00
	9.359 0.956250000000 47817 22.86
	9.479 0.962500000000 48144 26.67
	9.599 0.968750000000 48445 32.00
	9.679 0.971875000000 48596 35.56
	9.783 0.975000000000 48752 40.00
	9.943 0.978125000000 48911 45.71
	10.335 0.981250000000 49063 53.33
	10.431 0.984375000000 49226 64.00
	10.487 0.985937500000 49301 71.11
	10.607 0.987500000000 49376 80.00
	10.975 0.989062500000 49454 91.43
	11.039 0.990625000000 49536 106.67
	11.087 0.992187500000 49618 128.00
	11.119 0.992968750000 49660 142.22
	11.159 0.993750000000 49689 160.00
	11.263 0.994531250000 49727 182.86
	11.623 0.995312500000 49766 213.33
	11.735 0.996093750000 49808 256.00
	11.791 0.996484375000 49826 284.44
	11.967 0.996875000000 49844 320.00
	12.231 0.997265625000 49864 365.71
	12.359 0.997656250000 49885 426.67
	12.439 0.998046875000 49905 512.00
	12.519 0.998242187500 49914 568.89
	12.743 0.998437500000 49922 640.00
	12.943 0.998632812500 49932 731.43
	13.303 0.998828125000 49943 853.33
	13.743 0.999023437500 49952 1024.00
	13.847 0.999121093750 49958 1137.78
	13.919 0.999218750000 49962 1280.00
	14.103 0.999316406250 49966 1462.86
	14.263 0.999414062500 49971 1706.67
	14.511 0.999511718750 49976 2048.00
	15.015 0.999560546875 49979 2275.56
	15.135 0.999609375000 49981 2560.00
	15.799 0.999658203125 49983 2925.71
	16.447 0.999707031250 49986 3413.33
	17.055 0.999755859375 49988 4096.00
	18.079 0.999780273438 49990 4551.11
	18.223 0.999804687500 49991 5120.00
	18.319 0.999829101563 49992 5851.43
	18.799 0.999853515625 49993 6826.67
	18.911 0.999877929688 49994 8192.00
	19.439 0.999890136719 49995 9102.22
	19.519 0.999902343750 49996 10240.00
	19.519 0.999914550781 49996 11702.86
	20.895 0.999926757813 49997 13653.33
	20.895 0.999938964844 49997 16384.00
	23.919 0.999945068359 49998 18204.44
	23.919 0.999951171875 49998 20480.00
	23.919 0.999957275391 49998 23405.71
	26.719 0.999963378906 49999 27306.67
	26.719 0.999969482422 49999 32768.00
	26.719 0.999972534180 49999 36408.89
	26.719 0.999975585938 49999 40960.00
	26.719 0.999978637695 49999 46811.43
	37.919 0.999981689453 50000 54613.33
	37.919 1.000000000000 50000
	#[Mean = 7.299, StdDeviation = 0.785]
	#[Max = 37.888, Total count = 50000]
	#[Buckets = 24, SubBuckets = 2048]

view raw gistfile1.txt hosted with ❤ by GitHub

Fear not, HdrHistogram comes packed with a handy charty thingy! Here's what the above histogram looks like when plotted:

To get this graph:

• Save output above to a text file
• Open a browser, and go here (the same HTML is in the project here)
• Choose your file, choose percentiles to report and unit to report in
• Export the picture and stick it in your blog!

This histogram was provided to me by Martin Thompson (one of the Aeron developers) and is from a test run in a performance lab. We can see that Aeron is delivering a solid 7µs RTT up to the 90%ile where latency starts to gradually grow. In this particular data set the maximum observed latency was 38µs. This is a great latency profile. It is far more common for the max and 99.99%ile to be orders of magnitude more that the 90%ile.
I could similarly plot this histogram using a gnuplot script to be found here. The gnuplot script is very handy for scripted reporting on large runs. It also allows for plotting several histograms on the same graph to allow visual comparison between benchmark runs for instance.

Example: Compressed histogram logging

Because the SLA is often specified in percentiles, it is common for applications to log only percentiles and not histograms. This leads to a reporting problem as it turns out that percentiles output cannot be combined to produce meaningful average percentiles. The solution would be to log the full histogram data, but who want a log that grows by 31KB every 5 seconds just to capture one histogram? Worry not, HdrHistogram comes with a compressed logging format and log writer and all that good stuff:

	// Somewhere, in another class
	protected final HistogramLogWriter histogramLogWriter;
	// Later, in a constructor
	PrintStream log = new PrintStream(new FileOutputStream("HapoelHaifa.hgrm"), false);
	histogramLogWriter = new HistogramLogWriter(log);
	// Some log header bits
	histogramLogWriter.outputComment("[Logged with " + getVersionString() + "]");
	histogramLogWriter.outputLogFormatVersion();
	histogramLogWriter.outputStartTime(reportingStartTime);
	histogramLogWriter.setBaseTime(reportingStartTime);
	histogramLogWriter.outputLegend();
	// Every once in a while, we just drop some histograms
	histogramLogWriter.outputIntervalHistogram(aHistogram);

view raw gistfile1.java hosted with ❤ by GitHub

How many bytes is that logged histogram costing us? The 31KB histogram compressed down to 1KB in my example, but the result of compression will depend on the histogram captured. It is fair to assume that histograms compress well as the array of buckets is full of zeros (on the byte level) as most buckets are empty or low count.
If 1KB sounds like allot consider that a days worth of 10s interval histograms will result in an 8MB log file, which seems pretty acceptable even if you have a hundred such files. The benefit is that you will now have high precision interval latency data that you can reliably use to create longer interval latency data. You can use the HistogramLogProcessor to produce a full or partial log summary histogram for plotting as above.
I believe there's some truly exciting data visualizations one could build on top of this data, but sadly thats not where my skills lie. If you got skills to show of in this area I'm sure HdrHistogram would value your contribution.

Example: jHiccup and concurrent logging

jHiccup is a pause measurement tool used to capture OS or JVM 'hiccups'. It deserves it's own post but I'll try and summarize it in a few points:

• jHiccup runs a HiccupRecorder thread which sleeps for a period of time (configurable) and measures the delta between the wakeup time and actual time. The failure to be re-scheduled is taken as a potential OS/JVM hiccup. The size of the hiccup is recorded in a histogram.
• jHiccup can be run as an agent in your own process, an external process, or both.
• jHiccup has been ported to C as well.
• People typically use jHiccup to help charecterize and diagnose disruptions to execution in their system. While not every hiccup is the result of a STW pause we can use the jHiccup agent evidence correlated with an external jHiccup process and the JVM gc logs to support root cause analysis. A significant hiccup is a serious sign of trouble meaning a thread was denied from scheduling for the length of the hiccup. We can safely assume in most cases that this is a sign that other threads were similarly disturbed.

Gil Tene originally wrote HdrHistogram as part of jHiccup, but as HdrHistogram turned out to be more generally useful the two were split. The reason I bring jHiccup up in this context is that it serves as a regularly maintained full blown real world example of using an HdrHistogram.
jHiccup has 2 interesting threads, with roles that parallel many real world applications out there:

• The measuring thread(HiccupRecorder): This is the thread that sleeps and wakes up and so on. The rate at which it does that is potentially quite high and we don't want to skew to measurement by performing IO on this thread. Similarly many real world application will have critical threads where it is not desirable to introduce IO. Since this is the case actual persistence will be performed on another thread.
• The monitoring/logging thread(HiccupMeter): This thread will wake up at regular intervals and write the last interval's histogram to the log file. But since it is reading a histogram while another thread is writing to the histogram we now need to manage concurrency.

HdrHistogram offers a synchronization facility to serve exactly this use case in the form of the Recorder:

• Recording a value in the recorder is a wait free operation (on JDK8, can be lock free on older depending on the getAndAdd implementation for AtomicLongArray).
• The Recorder also comes in a single-writer flavour, which minimizes the concurrency related overheads.

Under the covers the recorder is using an active histogram and an inactive one, swapped seamlessly when an interval histogram is requested. Using a Recorder looks much like using a normal histogram(full code here):

	/**
	* NOTE: I'm just grabbing relevant bits from HiccupMeter in jHiccup. I recommend
	* reading through the whole class if you got 5 minutes.
	*/
	public class HiccupMeter extends Thread {
	// The meter thread will write out the log
	final HistogramLogWriter histogramLogWriter;
	final HiccupMeterConfiguration config;
	@Override
	public void run() {
	// jHiccup has a single measuring thread, can use SingleWriter
	SingleWriterRecorder recorder =
	new SingleWriterRecorder(config.lowestTrackableValue,
	config.highestTrackableValue,
	config.numberOfSignificantValueDigits);
	// create the recording thread and start it
	HiccupRecorder hiccupRecorder = createHiccupRecorder(recorder);
	hiccupRecorder.start();
	// we reuse the first interval returned from the recorder to avoid unnecessary allocation
	Histogram intervalHistogram = null;
	// this is a simplification of the meter reporting loop
	while(notDoneReporting()) {
	sleepUntil(nextReportingTime);
	// Get the latest interval histogram and give the recorder a fresh Histogram for the next interval
	intervalHistogram = recorder.getIntervalHistogram(intervalHistogram);
	if (intervalHistogram.getTotalCount() > 0) {
	histogramLogWriter.outputIntervalHistogram(intervalHistogram);
	}
	}
	}
	class HiccupRecorder extends Thread {
	final SingleWriterRecorder recorder;
	final HiccupMeterConfiguration config;
	@Override
	public void run() {
	long resolutionNsec = (long)(config.resolutionMs * 1000L * 1000L);
	while (doRun) {
	long hiccupTimeNsec = hic(resolutionNsec);
	// the recorder will fill in missing measurements as delayed
	recorder.recordValueWithExpectedInterval(hiccupTimeNsec, resolutionNsec);
	}
	}
	}
	}

view raw gistfile1.java hosted with ❤ by GitHub

And that's concurrent logging sorted ;-).

Summary

With HdrHistogram now hitting version 2.1.4 and offering a wealth of tried and tested functionality along with cross platform implementations and a standardized compressed logging format it is definitely time you gave it a go! May your latencies always be low!
If you are looking for a pet project and have a gift for UI thingies a latency explorer for the histogram interval logs would be an awesome contribution!