You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by "Remko Popma (JIRA)" <ji...@apache.org> on 2016/04/03 09:09:25 UTC
[jira] [Comment Edited] (LOG4J2-1297) Document "gc-free"
configuration and performance
[ https://issues.apache.org/jira/browse/LOG4J2-1297?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15223145#comment-15223145 ]
Remko Popma edited comment on LOG4J2-1297 at 4/3/16 7:09 AM:
-------------------------------------------------------------
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!
With Log4j 2.5: memory allocation rate 809 MB/sec, 141 minor collections.
!log4j-2.6-FlightRecording.png!
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._
was (Author: remkop@yahoo.com):
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