Background Logging with the Disruptor

Adrian Sutton

September 26, 2011

Peter Lawrey posted an example of using the Exchanger class from core Java to implement a background logging implementation. He briefly compared it to the LMAX disruptor and since someone requested it, I thought it might be interesting to show a similar implementation using the disruptor.

Firstly, let’s revisit the very high level differences between the exchanger and the disruptor. Peter notes:

This approach has similar principles to the Disruptor. No GC using recycled, pre-allocated buffers and lock free operations (The Exchanger not completely lock free and doesn’t busy wait, but it could)

Two keys difference are:

there is only one producer/consumer in this case, the disruptor supports multiple consumers.

this approach re-uses a much smaller buffer efficiently. If you are using ByteBuffer (as I have in the past) an optimal size might be 32 KB. The disruptor library was designed to exploit large amounts of memory on the assumption it is relative cheap and can use medium sized (MBs) to very large buffers (GBs). e.g. it was design for servers with 144 GB. I am sure it works well on much smaller servers. ;)

Actually, there’s nothing about the Disruptor that requires large amounts of memory. If you know that your producers and consumers are going to keep pace with each other well and you don’t have a requirement to replay old events, you can use quite a small ring buffer with the Disruptor. There are a lot of advantages to having a large ring buffer, but it’s by no means a requirement.

It’s also worth noting that the Disruptor does not require consumers to busy-spin, you can choose to use a blocking wait strategy, or strategies that combine busy-spin and blocking to handle both spikes and lulls in event rates efficiently.

There is also an important advantage to the Disruptor that wasn’t mentioned: it will process events immediately if the consumer is keeping up. If the consumer falls behind however, it can process events in a batch to catch up. This significantly reduces latency while still handling spikes in load efficiently.

The Code

First let’s start with the LogEntry class. This is a simple value object that is used as our entries on the ring buffer and passed from the producer thread over to the consumer thread.

Peter’s Exchanger based implementation – the use of StringBuilder in the LogEntry class is actually a race condition and not thread safe. Both the publishing side and the consumer side are attempting to modify it and depending on how long it takes the publishing side to write the log message to the StringBuilder, it will potentially be processed and then reset by the consumer side before the publisher is complete. In this implementation I’m instead using a simple String to avoid that problem.

import com.lmax.disruptor.EventFactory; class LogEntry { public static final EventFactory<LogEntry> FACTORY = new EventFactory<LogEntry>() { public LogEntry newInstance() { return new LogEntry(); } }; long time; int level; String text;

}

The one Disruptor-specific addition is that we create an EventFactory instance which the Disruptor uses to pre-populate the ring buffer entries.

Next, let’s look at the BackgroundLogger class that sets up the process and acts as the producer.

import com.lmax.disruptor.RingBuffer; import com.lmax.disruptor.dsl.Disruptor; import java.util.concurrent.ExecutorService; import java.util.concurrent.Executors; public class BackgroundLogger { private static final int ENTRIES = 64; private final ExecutorService executorService; private final Disruptor<LogEntry> disruptor; private final RingBuffer<LogEntry> ringBuffer; BackgroundLogger() { executorService = Executors.newCachedThreadPool(); disruptor = new Disruptor<LogEntry>(LogEntry.FACTORY, ENTRIES, executorService); disruptor.handleEventsWith(new LogEntryHandler()); disruptor.start(); ringBuffer = disruptor.getRingBuffer(); } public void log(String text) { final long sequence = ringBuffer.next(); final LogEntry logEntry = ringBuffer.get(sequence); logEntry.time = System.currentTimeMillis(); logEntry.level = level; logEntry.text = text; ringBuffer.publish(sequence); } public void stop() { disruptor.shutdown(); executorService.shutdownNow(); } }

In the constructor we create an ExecutorService which the Disruptor will use to execute the consumer threads (a single thread in this case), then the disruptor itself. We pass in the LogEntry.FACTORY instance for it to use to create the entries and a size for the ring buffer.

The log method is our producer method. Note the use of two-phase commit. First claim a slot with the ringBuffer.next() method, then copy our values into that slot’s entry and finally publish the slot, ready for the consumer to process. We could have also used the Disruptor.publish method which can make this simpler for many use cases by rolling the two phase commit into call.

The producer doesn’t need to do any batching as the Disruptor will do that automatically if the consumer is falling behind, though there are also APIs that allow batching the producer which can improve the performance if it fits into your design (here it’s probably better to publish each log entry as it comes in).

The stop method uses the new shutdown method on the Disruptor which takes care of waiting until all consumers have processed all available entries for you, though the code for doing it yourself is quite straight-forward. Finally we shut down the executor.

Note that we don’t need a flush method since the Disruptor is always consuming log events as quickly as the consumer can.

Last of all, the consumer which is almost entirely implementation logic:

import com.lmax.disruptor.EventHandler; public class LogEntryHandler implements EventHandler<LogEntry> { public LogEntryHandler() { } public void onEvent(final LogEntry logEntry, final long sequence, final boolean endOfBatch) throws Exception { // Write }

}

The consumer’s onEvent method is called for each LogEntry put into the Disruptor. The endOfBatch flag can be used as a signal to flush written content to disk, allowing very large buffer sizes to be used causing writes to disk to be batched when the consumer is running behind, yet also ensure that our valuable log messages get to disk as quickly as possible.

The full code is available as a Gist.