[
https://issues.apache.org/jira/browse/LOG4J2-1270?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15149003#comment-15149003
]
Remko Popma commented on LOG4J2-1270:
-------------------------------------
As requested in LOG4J2-1274 and LOG4J2-1278, I created a performance test that
compares "classic" logging with gc-free logging. The classic test uses varargs,
creating temporary ParameterizedMessages and PatternLayout; the noGC test
unrolls the varargs, re-uses a StringBuilder-based Message and uses the
CharEncoder API to convert text to bytes.
Results:
{code}
Classic[0] (2016-02-17 02:59:11.292) took 1,432,449,565 ns. CHECK=1113dda30
Classic[1] (2016-02-17 02:59:12.839) took 1,259,734,411 ns. CHECK=1113dda30
Classic[2] (2016-02-17 02:59:14.202) took 1,218,989,829 ns. CHECK=1113dda30
Classic[3] (2016-02-17 02:59:15.530) took 1,209,093,017 ns. CHECK=1113dda30
Classic[4] (2016-02-17 02:59:16.839) took 1,208,648,678 ns. CHECK=1113dda30
Classic[5] (2016-02-17 02:59:18.145) took 1,222,321,165 ns. CHECK=1113dda30
Classic[6] (2016-02-17 02:59:19.471) took 1,221,951,084 ns. CHECK=1113dda30
Classic[7] (2016-02-17 02:59:20.800) took 1,388,327,159 ns. CHECK=1113dda30
Classic[8] (2016-02-17 02:59:22.297) took 1,311,564,533 ns. CHECK=1113dda30
Classic[9] (2016-02-17 02:59:23.710) took 1,206,745,142 ns. CHECK=1113dda30
{code}
{code}
NoGC[0] (2016-02-17 02:58:44.002) took 972,486,586 ns. CHECK=1113dda30
NoGC[1] (2016-02-17 02:58:45.081) took 923,443,846 ns. CHECK=1113dda30
NoGC[2] (2016-02-17 02:58:46.103) took 833,296,707 ns. CHECK=1113dda30
NoGC[3] (2016-02-17 02:58:47.032) took 809,844,530 ns. CHECK=1113dda30
NoGC[4] (2016-02-17 02:58:47.942) took 828,931,195 ns. CHECK=1113dda30
NoGC[5] (2016-02-17 02:58:48.880) took 818,920,279 ns. CHECK=1113dda30
NoGC[6] (2016-02-17 02:58:49.802) took 816,935,846 ns. CHECK=1113dda30
NoGC[7] (2016-02-17 02:58:50.724) took 818,421,605 ns. CHECK=1113dda30
NoGC[8] (2016-02-17 02:58:51.647) took 812,101,242 ns. CHECK=1113dda30
NoGC[9] (2016-02-17 02:58:52.554) took 848,276,857 ns. CHECK=1113dda30
{code}
To verify the results, the tests can be run like this:
{noformat}
// Run CLASSIC test (varargs, ParameterizedMessage, PatternLayout(%m)):
java -Xms64M -Xmx64M -cp log4j-perf/target/benchmarks.jar -verbose:gc
-XX:+PrintGCDetails -XX:+PrintGCTimeStamps
org.apache.logging.log4j.perf.nogc.Test Classic
// Run NOGC test (unrolled varargs, StringBuilderMessage, NoGcLayout(%m)):
java -Xms64M -Xmx64M -cp log4j-perf/target/benchmarks.jar -verbose:gc
-XX:+PrintGCDetails -XX:+PrintGCTimeStamps
org.apache.logging.log4j.perf.nogc.Test NoGC
{noformat}
> Garbage-free steady-state logging
> ---------------------------------
>
> Key: LOG4J2-1270
> URL: https://issues.apache.org/jira/browse/LOG4J2-1270
> Project: Log4j 2
> Issue Type: Epic
> Components: API, Appenders, Core, Layouts, Pattern Converters
> Affects Versions: 2.5
> Reporter: Remko Popma
> Labels: gc
>
> In certain fields like finance, predictable latency is very important, and
> applications in this space tend to carefully manage their object allocation
> to avoid unpredictable GC pauses. As of 2.5, Log4j is not suitable to be
> included in such applications since it allocates new objects while running in
> its steady state.
> This ticket is to investigate the feasibility of modifying some key
> components in Log4j to provide a configuration that does not allocate new
> objects in its steady state. (Initialization or shutdown don't need to be
> allocation-free.)
> To clarify, I am not proposing to make all of Log4j allocation-free. My goal
> is to create an allocation-free execution path in Log4j with some reasonable
> subset of the Log4j functionality. For example, make logging garbage-free if
> all of these conditions are met:
> * all loggers are AsyncLoggers
> * you only use the RandomAccessFileAppender
> * you only use a PatternLayout without any regular expression replacements,
> without lookups and with one of the pre-defined date formats.
> Further restrictions may be necessary.
> AsyncLogger already has a ring buffer of pre-allocated LogEvents, so some of
> the work here is already done.
> Components that currently allocate objects in the critical path:
> # (API) Logger methods with vararg parameters
> # (API) All MessageFactory implementations
> # LoggerConfig.getProperties (if non-null) - wraps in
> Collections.unmodifiableMap
> # RingBufferLogEvent.mergePropertiesIntoContextMap (if LoggerConfig
> properties is non-null)
> # LoggerConfig.callAppenders (for-each loop over CopyOnWriteArraySet creates
> iterator)
> # Layout.toByteArray(LogEvent) - this API makes it difficult to avoid
> allocating a new byte[] array for each log event
> # AbstractStringLayout.toByteArray() - turns each LogEvent into a new String
> before turning the String into a byte[] array
> # DatePatternConverter - new CachedTime if event.millis differs from previous
> event
> # DatePatternConverter.CachedTime - new String caching the result
> # FixedDateFormat - new char[] array
> # (FastDateFormat - for each event: new GregorianCalendar, new StringBuilder,
> new char[], new String)
> # String.getBytes - creates initial byte array, CharBuffer, ByteBuffer,
> trimmed resulting byte array
> The Layout API and turning Strings into bytes are probably the most tricky
> areas. One advantage of restricting ourselves to async logging is that there
> is only a single background thread that does all the formatting and I/O, so
> we don't have to worry about concurrency issues when re-using buffers etc.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
