Asynchronous Loggers for Low-Latency Logging
- http://logging.apache.org/log4j/2.x/manual/async.html
- http://logging.apache.org/log4j/2.x/manual/async.html#Performance
Log4j 2 contains next-generation Asynchronous Loggers based on the LMAX Disruptor library. In multi-threaded scenarios Asynchronous Loggers have 10 times higher throughput and orders of magnitude lower latency than Log4j 1.x and Logback. See Asynchronous Logging Performance for details. Otherwise, Log4j 2 performs faster than Log4j 1.x in critical areas and similarly to Logback under most circumstances. See Performance for more information. http://logging.apache.org/log4j/2.x/
Asynchronous Loggers are implemented using the LMAX Disruptor inter-thread messaging library. From the LMAX web site: ... using queues to pass data between stages of the system was introducing latency, so we focused on optimising this area. The Disruptor is the result of our research and testing. We found that cache misses at the CPU-level, and locks requiring kernel arbitration are both extremely costly, so we created a framework which has "mechanical sympathy" for the hardware it's running on, and that's lock-free. LMAX Disruptor internal performance comparisons with java.util.concurrent.ArrayBlockingQueue can be found here. http://logging.apache.org/log4j/2.x/manual/async.html#UnderTheHood
Explanation by Remko Popma, one of the Log4j2 contributors...
remkop: The threading model is part of the "Mechanical Sympathy". Multiple threads can write into a ring buffer, without locks. On the other end, coming out of the ring buffer you can have one thread (which means that the biz logic never needs to lock anything and can be blazingly fast), or multiple threads doing something with the event independently (at LMAX they journal to disk and replicate to backup machine). These threads can process the event in parallel. And you can "pipeline" or stage threads, so after both journaling and replication are complete (and not earlier than that) the event is passed to the business logic.
Then if the business logic needs to do something slow, like network I/O, disk I/O, database access etc, you would set up one or more other Disruptors for that. Instead of doing the slow task in the biz logic thread, you'd post a task for that on the helper Disruptor. That way the business logic can stay single-threaded, uncontended and blazingly fast.
When the slow task (disk I/O or whatever) is done, it will post a new event onto the first Disruptor, so the business logic can pick up the result and process that. So it's all asynchronous, all event-driven, but pretty flexible.
In Log4j 2.0 there is just one Disruptor that takes the log message, puts it in the ring buffer, and passes control back to the application. Coming out of the ring buffer the event is passed to the normal log4j loggers, parent loggers and appenders.
It is not completely zero-garbage, but all ring buffer slots are created up front and re-used during the life of the process. Coming into the ring buffer, log event parameters are copied into the ring buffer slot without creating new LogEvent objects. Slots in the ring buffer implement the LogEvent interface, so coming out of the ring buffer, the slot itself is passed downstream, again avoiding object creation. Other parts of log4j are not that garbage-conscious so there is still room for improvement in this area.