[
https://issues.apache.org/jira/browse/LOG4J2-928?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16071511#comment-16071511
]
ASF GitHub Bot commented on LOG4J2-928:
---------------------------------------
Github user leventov commented on the issue:
https://github.com/apache/logging-log4j2/pull/87
<h3>Throughput comparison</h3>
First number is the number of threads, "150" is the message size.
Before this PR
```
1 - o.a.l.l.p.j.Log4j2AppenderComparisonBenchmark.end2endMMap
150 thrpt 10 988106.677 ± 44561.265 ops/s
2 - o.a.l.l.p.j.Log4j2AppenderComparisonBenchmark.end2endMMap
150 thrpt 10 1378707.634 ± 45234.050 ops/s
3 - o.a.l.l.p.j.Log4j2AppenderComparisonBenchmark.end2endMMap
150 thrpt 10 1507720.952 ± 42527.798 ops/s
4 - o.a.l.l.p.j.Log4j2AppenderComparisonBenchmark.end2endMMap
150 thrpt 10 1615561.064 ± 10197.025 ops/s
1 - o.a.l.l.p.j.Log4j2AppenderComparisonBenchmark.appenderMMap
150 thrpt 10 1406710.542 ± 53654.749 ops/s
2 - o.a.l.l.p.j.Log4j2AppenderComparisonBenchmark.appenderMMap
150 thrpt 10 2032867.062 ± 33273.059 ops/s
3 - o.a.l.l.p.j.Log4j2AppenderComparisonBenchmark.appenderMMap
150 thrpt 10 2182597.197 ± 19446.011 ops/s
4 - o.a.l.l.p.j.Log4j2AppenderComparisonBenchmark.appenderMMap
150 thrpt 10 2128503.272 ± 40132.820 ops/s
```
With this PR
```
1 - o.a.l.l.p.j.Log4j2AppenderComparisonBenchmark.end2endMMap
150 thrpt 10 848596.439 ± 29081.144 ops/s
2 - o.a.l.l.p.j.Log4j2AppenderComparisonBenchmark.end2endMMap
150 thrpt 10 1302047.611 ± 21627.635 ops/s
3 - o.a.l.l.p.j.Log4j2AppenderComparisonBenchmark.end2endMMap
150 thrpt 10 1702653.587 ± 36385.194 ops/s
4 - o.a.l.l.p.j.Log4j2AppenderComparisonBenchmark.end2endMMap
150 thrpt 15 1880038.309 ± 35208.682 ops/s
1 - o.a.l.l.p.j.Log4j2AppenderComparisonBenchmark.appenderMMap
150 thrpt 10 1283001.528 ± 40095.635 ops/s
2 - o.a.l.l.p.j.Log4j2AppenderComparisonBenchmark.appenderMMap
150 thrpt 10 1803333.701 ± 27412.900 ops/s
3 - o.a.l.l.p.j.Log4j2AppenderComparisonBenchmark.appenderMMap
150 thrpt 10 2506996.207 ± 40209.437 ops/s
4 - o.a.l.l.p.j.Log4j2AppenderComparisonBenchmark.appenderMMap
150 thrpt 10 2723771.920 ± 103479.124 ops/s
```
On the same MacBook with 4 cores.
You can see that with 1 or 2 threads older version is faster, but it's the
limit of it's scalability, and with 3 or 4 threads the wait-free version takes
over.
> 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)
