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] [Commented] (LOG4J2-1297) Document "gc-free" configuration and performance
Date Sun, 03 Apr 2016 07:07:27 GMT

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

Remko Popma commented on LOG4J2-1297:
-------------------------------------

Draft of the work in progress, feedback welcome:

h1. Garbage-free Steady State Logging

Garbage collection pauses are a common cause of latency spikes and for many systems significant
effort is spent on controlling these pauses.

Traditionally, logging libraries allocate many temporary objects like log event objects, Strings,
char arrays, byte arrays and more during steady state logging. This contributes to pressure
on the garbage collector and increases the frequency with which GC pauses occur.

>From version 2.6, Log4j can be used in a "garbage free" mode where objects and buffers
are reused and temporary object allocation is avoided as much as possible.

h2. A Contrived Example
To highlight the difference, we used Java Flight Recorder to measure a simple application
that does nothing but logging a simple string as often as possible for about 12 seconds.

The application was configured to use Async Loggers, a RandomAccessFile appender and a "%d
%p %c\{1.} \[%t] %m %ex%n" pattern layout.

Mission Control shows that with Log4j 2.5 this application allocated memory at a rate of about
809 MB/sec, resulting in 141 minor collections. Log4j 2.6 does not allocate temporary objects
in this configuration, and as a result the same application with Log4j 2.6 had a memory allocation
rate of 1.6 MB/sec and 0 (zero) garbage collections.

| !log4j-2.5-FlightRecording.png|thumbnail! | !log4j-2.6-FlightRecording.png|thumbnail! |

|With Log4j 2.5: memory allocation rate 809 MB/sec, 141 minor collections.|Log4j 2.6 did not
allocate temporary objects: 0 (zero) garbage collections.|

h2. Enabling Garbage-free Logging

h4.Configuration

In Log4j 2.6, garbage-free logging is enabled by default, except for web applications. Log4j
will disable garbage-free logging if it detects that it is used in a web application (either
when the {{javax.servlet.Servlet}} is in the classpath or when the {{log4j2.is.webapp}} system
property is set to "true"). This is because garbage-free logging uses a number of ThreadLocal
fields, which can cause memory leaks when the thread pools of web application containers hold
references to these fields even after the web application is undeployed.

It is possible to manually disable garbage-free logging by setting system property {{log4j2.enable.threadlocals}}
to "false" before Log4j is initialized.

The above properties can also be specified by creating a file named {{log4j2.component.properties}}
and including this file in the classpath of the application.

| *Caution:* as of version 2.6, a Log4j configuration containing a {{<Properties>}}
section will result in temporary objects being created during steady-state logging.|

h4. Appenders

The following appenders are garbage-free: Console, File, RollingFile, RandomAccessFile, RollingRandomAccessFile,
MemoryMappedFile, and Socket.

Any other appenders (including Async) not in the above list create temporary objects during
steady-state logging. Use Async Loggers to log asynchronously in a garbage-free manner.

h4. Layouts

>From the built-in layouts, currently only PatternLayout is garbage-free, but only when
used with the following conversion patterns.

* ClassNamePatternConverter
* DatePatternConverter
* FileLocationPatternConverter
* LevelPatternConverter
* LineLocationPatternConverter
* LineSeparatorPatternConverter
* LiteralPatternConverter (unless literal contains '${')
* LoggerPatternConverter
* MarkerSimpleNamePatternConverter
* MessagePatternConverter
* MethodLocationPatternConverter
* NamePatternConverter
* NanoTimePatternConverter
* ThreadIdPatternConverter
* ThreadNamePatternConverter
* ThreadPriorityPatternConverter

Other PatternLayout conversion patterns, and some other Layouts are scheduled to be updated
to avoid creating temporary objects in a subsequent release.

| *Caution:* patterns containing regular expressions and lookups for property substitution
will result in temporary objects being created during steady-state logging.|

h4. Application Code and Autoboxing

We made an effort to make existing application logging code garbage-free without requiring
code changes, but there is one area where this was not possible. When logging primitive values
(i.e. int, double, boolean, etc.), autoboxing occurs and the JVM converts these primitive
values to their Object wrapper equivalents.

Log4j provides an {{Unboxer}} utility to prevent autoboxing of primitive parameters. This
utility contains a thread-local pool of reused StringBuilders. The {{Unboxer.box(primitive)}}
methods write directly into a StringBuilder, and the resulting text will be copied into the
final log message text without creating temporary objects.

{code}
import static org.apache.logging.log4j.util.Unboxer.box;
 
...
public void garbageFree() {
    logger.debug("Prevent primitive autoboxing {} {}", box(10L), box(2.6d));
}
{code}

|Caution: not all logging is garbage free. Specifically:
* The ThreadContext map and stack are not garbage-free yet.
* Logging more than 10 parameters creates vararg arrays.
* Logging very large messages (more than 518 characters) when all loggers are Async Loggers
will cause the internal StringBuilder in the RingBuffer to be trimmed back to their max size.
* Logging messages containing '${': substituting a ${variable} creates temporary objects.
* Logging a lambda as a parameter ({{logger.info("lambda value is {}", () -> callExpensiveMethod())}}
) creates a vararg array. Logging a lambda expression by itself is garbage-free: {{logger.debug(()
-> callExpensiveMethod())}}.
* The Logger.traceEntry and Logger.traceExit methods create temporary objects.|

h2. Performance

TBD

h2. Under the Hood

TBD 

_Stuff about what methods custom layouts and custom appenders should use to be garbage-free._

> 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
>         Attachments: 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