logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Remko Popma (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (LOG4J2-1297) Document "gc-free" configuration and performance
Date Tue, 26 Apr 2016 05:29:12 GMT

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

Remko Popma edited comment on LOG4J2-1297 at 4/26/16 5:28 AM:
--------------------------------------------------------------

I suspect the big drop in throughput has to do with locking: how much of the critical path
is in a synchronized section. Generally there are four stages to synchronous logging with
pattern layout:
# populating the log event (params, MDC snapshot)
# converting the log event into text (Once you start measuring you'll find this stage to be
surprisingly expensive. Many optimizations possible. Dates are one example but it is crucial
to profile/measure and focus on the biggest bottleneck first.)
# encoding the text to bytes
# File I/O in the appender (Surprisingly fast on modern hardware & OS-es. Buffering and
[smart batching|https://dzone.com/articles/smart-batching] will help.)

Ideally _only the last stage_ should be in a synchronized section.


was (Author: remkop@yahoo.com):
I suspect the big drop in throughput has to do with locking: how much of the critical path
is in a synchronized section. Generally there are four stages to synchronous logging with
pattern layout:
# populating the log event (params, MDC snapshot)
# converting the log event into text (Once you start measuring you'll find this stage to be
surprisingly expensive. Many optimizations possible. Dates are one example but it is crucial
to profile/measure and focus on the biggest bottleneck first.)
# encoding the text to bytes
# File I/O in the appender (Surprisingly fast on modern hardware & OS-es. Buffering and
smart batching .)

Ideally _only the last stage_ should be in a synchronized section.

> Document "gc-free" configuration and performance
> ------------------------------------------------
>
>                 Key: LOG4J2-1297
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-1297
>             Project: Log4j 2
>          Issue Type: New Feature
>          Components: Documentation
>    Affects Versions: 2.5
>            Reporter: Remko Popma
>            Assignee: Remko Popma
>             Fix For: 2.6
>
>         Attachments: LatencyHistogram.png, garbage-free2.6-SyncThroughputLinux.png, log4j-2.5-FlightRecording.png,
log4j-2.6-FlightRecording.png
>
>
> Update the site with a description of which configurations are GC-free (i.e., that don't
create temporary objects in steady running state).
> Currently that means
> * Loggers are all asynchronous (Log4jContextSelector is set to org.apache.logging.log4j.core.async.AsyncLoggerContextSelector).
> * The configuration does not contain a <Properties> section.
> * The "steady-state" appenders are either RandomAccessFile or RollingRandomAccessFile
Appenders (logging to any other appender will cause temporary objects to be created - including
ConsoleAppender).
> * The Layout is a PatternLayout that uses one of the pre-defined date formats, does not
have any regular expression replacements, and does not have lookups (TODO: may need to restrict
this further).
> * The thread name is cached (this is the [default|https://issues.apache.org/jira/browse/LOG4J2-467]).
Running with -DAsyncLogger.ThreadNameStrategy=UNCACHED will create garbage.
> * In user code, when logging a parameterized message, the number of parameters is no
more than ... (TBD pending discussion in LOG4J2-1278).
> * In user code, when logging a parameterized message, parameters of primitive type are
boxed in a reused StringBuilder (Log4j provides a utility to make this relatively painless).
> Even with the above restrictions, Log4j may occasionally create garbage:
> * Initially StringBuilders are presized to 128 characters. They may grow for larger messages
(contributing to garbage in Old Gen). If  the StringBuilder grows beyond 512 characters it
is trimmed back to 512 characters to prevent memory leaks from excessively long messages.
(TODO: the resizing algorithm is {{size = value.length * 2 + 2}}, so a better cutoff value
is 518.)
> * Messages containing {{"$\{"}} will be converted to a String and StrSubstitutor will
be used to replace occurences of variables with their matching values. Multiple temporary
objects are created during this process.
> Furthermore, we need to explain that some of this functionality depends on ThreadLocals
and so is disabled by default in web applications to prevent memory leaks. The page should
also explain how to manually switch off the use of ThreadLocals.
> Finally, the page should show a performance test comparison similar to the [performance
section|http://logging.apache.org/log4j/2.x/manual/async.html#Performance] on the Async Loggers
page. I'm thinking a comparison between Logback, Log4j-1, Log4j-2.0, Log4j-2.6 "classic" and
Log4j-2.6 "gc-free" would be ideal.



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org


Mime
View raw message