[
https://issues.apache.org/jira/browse/LOG4J2-1270?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15152099#comment-15152099
]
Remko Popma commented on LOG4J2-1270:
-------------------------------------
I found why the "NoGC" test was not completely GC-free: it uses
Unboxer.box(double) to wrap the primitive parameters in a StringBuilder, but
when building the formatted message text, the {{StringBuilder.append(Object)}}
method was called instead of {[StringBuilder.append(StringBuilder)}}. As Ralph
pointed out in LOG4J2-1271, this means the {{toString}} method got called on
the StringBuilder parameter. Ouch!
Checking the param type with {{instanceof}} and casting to StringBuilder before
appending to the formatted text StringBuilder solved the problem.
Results:
{code}
NoGC[0] (2016-02-18 19:15:34.130) took 803,649,416 ns. CHECK=1113dda30
NoGC[1] (2016-02-18 19:15:35.033) took 795,524,068 ns. CHECK=1113dda30
NoGC[2] (2016-02-18 19:15:35.935) took 764,242,400 ns. CHECK=1113dda30
NoGC[3] (2016-02-18 19:15:36.791) took 759,120,882 ns. CHECK=1113dda30
NoGC[4] (2016-02-18 19:15:37.648) took 760,439,465 ns. CHECK=1113dda30
NoGC[5] (2016-02-18 19:15:38.508) took 764,538,570 ns. CHECK=1113dda30
NoGC[6] (2016-02-18 19:15:39.372) took 769,256,005 ns. CHECK=1113dda30
NoGC[7] (2016-02-18 19:15:40.241) took 785,887,154 ns. CHECK=1113dda30
NoGC[8] (2016-02-18 19:15:41.131) took 758,333,986 ns. CHECK=1113dda30
NoGC[9] (2016-02-18 19:15:41.981) took 767,727,505 ns. CHECK=1113dda30
0 (zero) minor GC occurrences (yay!)
{code}
> 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]
