[jira] [Commented] (LOG4J2-928) Lock-free synchronous sub-microsecond appender

["ASF GitHub Bot (JIRA)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/LOG4J2-928?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16071300#comment-16071300 ] 

ASF GitHub Bot commented on LOG4J2-928:
---------------------------------------

Github user remkop commented on the issue:

    https://github.com/apache/logging-log4j2/pull/87
  
    Roman, I started to review your patch. Initial feedback below (still reading):
    
    * MemoryMappedFileManager::switchRegion should not throw Error: generally a logging problem should not bring down the application. See also the {{ignoreExceptions}} [configuration|https://logging.apache.org/log4j/2.x/manual/appenders.html#MemoryMappedFileAppender] attribute that allows applications to choose to receive logging exceptions.
    
    * What do you think of the idea of moving some of the newly added classes to the core.async package? ThreadHints, ThreadHintsMH, UninterruptibleCountDownLatch and UnlockedAwaitableReentrantLock. Perhaps also some of MemoryMappedfileManager's inner classes (need to look more at these)? 
    
    * in MemoryMappedfileManager::getFileManager, please call AbstractManager::narrow on the result of super.getManager(). This will show users a better error message when log4j2 is misconfigured (LOG4J2-1908). This is a recent change I made, may have introduced a (small) merge conflict, sorry about that.
    
    * Question: The javadoc for MemoryMappedFileManager::SPIN_WAIT_MINIMIZING_LOCKED_WRITE_THRESHOLD mentions a 32 KB threshold for stack traces. What happens if a user logs a stack trace exceeding this length?
    
    ... still reading, also looking forward to tests & perf results. 
    
    On the topic of perf testing:  I'd be interested to see a throughput comparison of the new MemoryMappedFileAppender vs. RandomAccessFileAppender and FileAppender with a varying number of logging threads (1, 2, 4, 8, 16, 32, 64 if possible).
    
    A throughput comparison with Async Loggers would also be interesting but be aware that JMH quickly fills up the disruptor ringbuffer. To solve this, configure with a non-existing appender (so the background thread essentially logs to /dev/null). See /log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/AsyncLoggersBenchmark.java
    
    Some indication of latency behaviour would also be interesting.


> Lock-free synchronous sub-microsecond appender
> ----------------------------------------------
>
>                 Key: LOG4J2-928
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-928
>             Project: Log4j 2
>          Issue Type: New Feature
>          Components: Appenders
>            Reporter: Remko Popma
>
> _(This is a work in progress.)_
> *Goal*
> It should be possible to create synchronous file appenders with (nearly) the same performance as async loggers.
> *Background*
> The key to the async loggers performance is the lock-free queue provided by the LMAX Disruptor. Multiple threads can add events to this queue without contending on a lock. This means throughput scales linearly with the number of threads: more threads = more throughput.
> With a lock-based design, on the other hand, performance maxes out with a single thread logging. Adding more threads does not help. In fact, total logging throughput goes down slightly when multiple threads are logging (see the Async Appenders in the [async performance comparison|http://logging.apache.org/log4j/2.x/manual/async.html#Asynchronous_Throughput_Comparison_with_Other_Logging_Packages]). Lock contention means that multiple threads together end up logging slower than a single thread.
> *Currently only async loggers are lock-free*
> Log4j2 provides good performance with async loggers, but this approach has several drawbacks:
> * dependency on external LMAX disruptor library
> * possibility of data loss: log events that have been put on the queue but not flushed to disk yet may be lost in the event of an application crash
> This ticket proposes a new feature to address these issues.
> *Proposal: a lock-free synchronous appender*
> For a single-threaded application the current MemoryMappedFileAppender has performance comparable to Async Loggers (TODO: perf test).
> However, the current implementation uses locks to control concurrency, and suffers from lock contention in multi-threaded scenarios.
> For inspiration for a lock-free solution, we can look at [Aeron|https://github.com/real-logic/Aeron], specifically Aeron's design for Log Buffers. Martin Thompson's September 2014 Strangeloop [presentation|https://www.youtube.com/watch?v=tM4YskS94b0] gives details on the design (especially the section 16:45-23:30 is relevant).
> The way this works, is that instead of using locks, concurrency is handled with a protocol where threads "reserve" blocks of memory atomically. Each thread (having serialized the log event) knows how many bytes it wants to write. It then atomically moves the buffer tail pointer by that many bytes using a CAS operation. After the tail has been moved, the thread is free to write the message payload bytes to the area of the buffer that it just reserved, without needing to worry about other threads. Between threads, the only point of contention is the tail pointer, which is similar to the disruptor. We can reasonably expect performance to scale linearly with the number threads, like async loggers.
> *Still needs work*
> This looks promising, but there are a few snags. 
> # Needs the Unsafe. {{java.nio.ByteBuffer}} only provides relative, not absolute bulk put operations. That is, it only allows appending byte arrays at the current cursor location, not at some user-specified absolute location. The above design requires random access to be thread-safe. Aeron works around this by using {{sun.misc.Unsafe}}. Users should be aware of this so they can decide on whether the performance gain is worth the risk. Also, this may make the OSGi folks unhappy (see LOG4J2-238 discussion)... Not sure how serious we are about making Log4j2 work on OSGi, but perhaps it is possible to mark the package for this feature as optional in the OSGi manifest. An alternative may be to put this appender in a separate module.
> # TBD: How many files/buffers to use? In his presentation Martin mentions that using a single large memory mapped file will cause a lot of page faults, page cache churn, and unspecified VM issues. He recommends cycling between three smaller buffers, one active (currently written to), one dirty (full, now being processed by a background thread) and one clean (to swap in when the active buffer becomes full). I am not sure if the page fault problem will occur for our use case: a Log4j appender is append-only, and there is no separate thread or process reading this data at the same time. If it does, and we decide on a similar design with three smaller buffers, we still need to work out if these can be three different mapped regions in the same log file, or if it is better to use a separate temporary file and copy from the temporary file to the target log file in a background thread. I would prefer to have a single file. Note that even with a single file we may want a background thread for mapping a new region at every swap and occasionally extending the file when the EOF is reached.
> Feedback welcome. I intend to update this ticket as I learn more.



--
This message was sent by Atlassian JIRA
(v6.4.14#64029)