In this article we present the CoralLog performance numbers when logging messages to a file.

The machine used for the benchmarks below was an Intel i7 quad-core (4 x 3.50GHz) Ubuntu box overclocked to 4.50Ghz with a 120 GB solid-state drive.

CoralLog is very fast! It performs asynchronous logging through a lock-free queue (i.e. CoralQueue) to be able to log a 256-byte message in 145 nanoseconds on average with a throughput around 2.7 million messages per second. And without producing any garbage.

Latency Numbers

Because CoralLog is asynchronous, the latency in the producer side (i.e. in the thread doing the logging) is very small. For a latency benchmark, we measure the time it takes to log each message in isolation, in other words, without any contention in the asynchronous queue. This is accomplished by periodically calling the method drainAndWait() so we can be sure the queue is never full when we log a message. Below we compute the average time per message when we log two million messages, with an initial warmup of one million messages.

The command line to run the test is:

$ java -server -verbose:gc -cp target/corallog-all.jar -DlogSysErrOnQueueContention=true -DdeleteFile=true -DincludeTimestamp=true -DprocToBindProducer=2 -DlogProcToBindConsumer=3 -Xms2g -Xmx8g -XX:NewSize=512m -XX:MaxNewSize=1024m com.coralblocks.corallog.bench.Latency 256 1000000 3000000

Note: You can check the source code of the latency test here.

The results are:

Messages: 3,000,000 (256 bytes in length)
Avg Time: 145.36 nanos
Min Time: 94.0 nanos
Max Time: 13.995 micros
75% = [avg: 134.0 nanos, max: 157.0 nanos]
90% = [avg: 139.0 nanos, max: 171.0 nanos]
99% = [avg: 143.0 nanos, max: 214.0 nanos]
99.9% = [avg: 144.0 nanos, max: 652.0 nanos]
99.99% = [avg: 145.0 nanos, max: 1.117 micros]
99.999% = [avg: 145.0 nanos, max: 6.538 micros]

Note: For latency is makes almost no difference if you include a timestamp before each log line. For throughput, as you will see below, it does.

Throughput Numbers

For the throughput test, we log one million messages as fast as possible and compute the total time it takes to log them. Queue contention will occur so we should expect the average time per message (i.e. average latency) to be bigger than the numbers we found above. The message size is again 256 bytes and we perform 10 passes to have a better idea of the average numbers.

Note: You can check the source code of the throughput test here.

Without timestamps:

The command line to run the test is:

$ java -server -verbose:gc -cp target/corallog-all.jar -DincludeTimestamp=false -DdeleteFile=true -DprocToBindProducer=2 -DlogProcToBindConsumer=3 -Xms2g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m com.coralblocks.corallog.bench.Throughput 1000000 10 256

The results are:

Batch 1 took 387.419 millis: Latency = 387 nanos per message | Throughput = 2,581,188 messages/sec
Batch 2 took 312.559 millis: Latency = 312 nanos per message | Throughput = 3,199,396 messages/sec
Batch 3 took 311.092 millis: Latency = 311 nanos per message | Throughput = 3,214,479 messages/sec
Batch 4 took 462.953 millis: Latency = 462 nanos per message | Throughput = 2,160,048 messages/sec
Batch 5 took 358.261 millis: Latency = 358 nanos per message | Throughput = 2,791,258 messages/sec
Batch 6 took 395.448 millis: Latency = 395 nanos per message | Throughput = 2,528,780 messages/sec
Batch 7 took 354.197 millis: Latency = 354 nanos per message | Throughput = 2,823,287 messages/sec
Batch 8 took 340.067 millis: Latency = 340 nanos per message | Throughput = 2,940,593 messages/sec
Batch 9 took 389.391 millis: Latency = 389 nanos per message | Throughput = 2,568,114 messages/sec
Batch 10 took 351.775 millis: Latency = 351 nanos per message | Throughput = 2,842,724 messages/sec

With timestamps:

$ java -server -verbose:gc -cp target/corallog-all.jar -DincludeTimestamp=true -DdeleteFile=true -DprocToBindProducer=2 -DlogProcToBindConsumer=3 -Xms2g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m com.coralblocks.corallog.bench.Throughput 1000000 10 256

The results are:

Batch 1 took 490.413 millis: Latency = 490 nanos per message | Throughput = 2,039,098 messages/sec
Batch 2 took 394.976 millis: Latency = 394 nanos per message | Throughput = 2,531,798 messages/sec
Batch 3 took 392.274 millis: Latency = 392 nanos per message | Throughput = 2,549,238 messages/sec
Batch 4 took 474.025 millis: Latency = 474 nanos per message | Throughput = 2,109,595 messages/sec
Batch 5 took 470.434 millis: Latency = 470 nanos per message | Throughput = 2,125,695 messages/sec
Batch 6 took 479.055 millis: Latency = 479 nanos per message | Throughput = 2,087,442 messages/sec
Batch 7 took 512.113 millis: Latency = 512 nanos per message | Throughput = 1,952,695 messages/sec
Batch 8 took 474.119 millis: Latency = 474 nanos per message | Throughput = 2,109,174 messages/sec
Batch 9 took 476.338 millis: Latency = 476 nanos per message | Throughput = 2,099,348 messages/sec
Batch 10 took 432.351 millis: Latency = 432 nanos per message | Throughput = 2,312,934 messages/sec