| <!DOCTYPE html> |
| <!-- |
| | Generated by Apache Maven Doxia Site Renderer 1.9.1 from src/site/xdoc/manual/garbagefree.xml at 2020-04-25 |
| | Rendered using Apache Maven Fluido Skin 1.8 |
| --> |
| <html xmlns="http://www.w3.org/1999/xhtml" lang="en"> |
| <head> |
| <meta charset="UTF-8" /> |
| <meta name="viewport" content="width=device-width, initial-scale=1" /> |
| <meta name="generator" content="Apache Maven Doxia Site Renderer 1.9.1" /> |
| <meta name="author" content="Remko Popma" /> |
| <title>Log4j – Garbage-free Steady State Logging</title> |
| <link rel="stylesheet" href="../css/apache-maven-fluido-1.8.min.css" /> |
| <link rel="stylesheet" href="../css/site.css" /> |
| <link rel="stylesheet" href="../css/print.css" media="print" /> |
| <script src="../js/apache-maven-fluido-1.8.min.js"></script> |
| </head> |
| <body class="topBarDisabled"> |
| <div class="container-fluid"> |
| <header> |
| <div id="banner"> |
| <div class="pull-left"><a href="http://logging.apache.org" id="bannerLeft"><img src="../images/ls-logo.jpg" alt=""/></a></div> |
| <div class="pull-right"><a href="http://logging.apache.org/log4j/2.x" id="bannerRight"><img src="../images/logo.png" alt=""/></a></div> |
| <div class="clear"><hr/></div> |
| </div> |
| |
| <div id="breadcrumbs"> |
| <ul class="breadcrumb"> |
| <li id="publishDate">Last Published: 2020-04-25<span class="divider">|</span> |
| </li> |
| <li id="projectVersion">Version: 2.13.2</li> |
| <li class="pull-right"><span class="divider">|</span> |
| <a href="https://github.com/apache/logging-log4j2" class="externalLink" title="GitHub">GitHub</a></li> |
| <li class="pull-right"><span class="divider">|</span> |
| <a href="https://analysis.apache.org/dashboard/index/org.apache.logging.log4j:log4j" class="externalLink" title="Sonar">Sonar</a></li> |
| <li class="pull-right"><span class="divider">|</span> |
| <a href="../../../" title="Logging Services">Logging Services</a></li> |
| <li class="pull-right"><span class="divider">|</span> |
| <a href="https://www.apache.org/" class="externalLink" title="Apache">Apache</a></li> |
| <li class="pull-right"><a href="https://cwiki.apache.org/confluence/display/LOGGING/Log4j" class="externalLink" title="Logging Wiki">Logging Wiki</a></li> |
| </ul> |
| </div> |
| </header> |
| <div class="row-fluid"> |
| <header id="leftColumn" class="span2"> |
| <nav class="well sidebar-nav"> |
| <ul class="nav nav-list"> |
| <li class="nav-header"><img class="imageLink" src="../img/glyphicons/home.png" alt="Apache Log4j™ 2" border="0"/> Apache Log4j™ 2</li> |
| <li><a href="../index.html" title="About"><span class="none"></span>About</a></li> |
| <li><a href="../download.html" title="Download"><span class="none"></span>Download</a></li> |
| <li><a href="../javadoc.html" title="Javadoc"><span class="icon-chevron-right"></span>Javadoc</a></li> |
| <li><a href="../maven-artifacts.html" title="Maven, Ivy, Gradle Artifacts"><span class="icon-chevron-right"></span>Maven, Ivy, Gradle Artifacts</a></li> |
| <li><a href="../runtime-dependencies.html" title="Runtime Dependencies"><span class="none"></span>Runtime Dependencies</a></li> |
| <li><a href="../changelog.html" title="Changelog"><span class="none"></span>Changelog</a></li> |
| <li><a href="../faq.html" title="FAQ"><span class="none"></span>FAQ</a></li> |
| <li><a href="../performance.html" title="Performance"><span class="icon-chevron-right"></span>Performance</a></li> |
| <li><a href="../articles.html" title="Articles and Tutorials"><span class="none"></span>Articles and Tutorials</a></li> |
| <li><a href="../security.html" title="Security"><span class="none"></span>Security</a></li> |
| <li><a href="../support.html" title="Support"><span class="none"></span>Support</a></li> |
| <li><a href="../thanks.html" title="Thanks"><span class="none"></span>Thanks</a></li> |
| <li class="nav-header"><img class="imageLink" src="../img/glyphicons/pencil.png" alt="For Contributors" border="0"/> For Contributors</li> |
| <li><a href="../build.html" title="Building Log4j from Source"><span class="none"></span>Building Log4j from Source</a></li> |
| <li><a href="../guidelines.html" title="Guidelines"><span class="none"></span>Guidelines</a></li> |
| <li><a href="../javastyle.html" title="Style Guide"><span class="none"></span>Style Guide</a></li> |
| <li class="nav-header"><img class="imageLink" src="../img/glyphicons/book.png" alt="Manual" border="0"/> Manual</li> |
| <li><a href="../manual/index.html" title="Introduction"><span class="none"></span>Introduction</a></li> |
| <li><a href="../manual/architecture.html" title="Architecture"><span class="none"></span>Architecture</a></li> |
| <li><a href="../manual/compatibility.html" title="Log4j 1.x Compatibility"><span class="none"></span>Log4j 1.x Compatibility</a></li> |
| <li><a href="../manual/migration.html" title="Log4j 1.x Migration"><span class="none"></span>Log4j 1.x Migration</a></li> |
| <li><a href="../manual/api.html" title="Java API"><span class="icon-chevron-right"></span>Java API</a></li> |
| <li><a href="../manual/scala-api.html" title="Scala API"><span class="none"></span>Scala API</a></li> |
| <li><a href="../manual/configuration.html" title="Configuration"><span class="icon-chevron-right"></span>Configuration</a></li> |
| <li><a href="../manual/usage.html" title="Usage"><span class="icon-chevron-right"></span>Usage</a></li> |
| <li><a href="../manual/webapp.html" title="Web Applications and JSPs"><span class="icon-chevron-right"></span>Web Applications and JSPs</a></li> |
| <li><a href="../manual/lookups.html" title="Lookups"><span class="icon-chevron-right"></span>Lookups</a></li> |
| <li><a href="../manual/appenders.html" title="Appenders"><span class="icon-chevron-right"></span>Appenders</a></li> |
| <li><a href="../manual/layouts.html" title="Layouts"><span class="icon-chevron-right"></span>Layouts</a></li> |
| <li><a href="../manual/filters.html" title="Filters"><span class="icon-chevron-right"></span>Filters</a></li> |
| <li><a href="../manual/async.html" title="Async Loggers"><span class="icon-chevron-right"></span>Async Loggers</a></li> |
| <li class="active"><a href="#"><span class="icon-chevron-down"></span>Garbage-free Logging</a> |
| <ul class="nav nav-list"> |
| <li><a href="../manual/garbagefree.html#Config" title="Configuration"><span class="none"></span>Configuration</a></li> |
| <li><a href="../manual/garbagefree.html#Appenders" title="Supported Appenders"><span class="none"></span>Supported Appenders</a></li> |
| <li><a href="../manual/garbagefree.html#Layouts" title="Supported Layouts"><span class="none"></span>Supported Layouts</a></li> |
| <li><a href="../manual/garbagefree.html#Filters" title="Supported Filters"><span class="none"></span>Supported Filters</a></li> |
| <li><a href="../manual/garbagefree.html#api" title="API Changes"><span class="none"></span>API Changes</a></li> |
| <li><a href="../manual/garbagefree.html#codeImpact" title="Impact on Application Code"><span class="none"></span>Impact on Application Code</a></li> |
| <li><a href="../manual/garbagefree.html#Performance" title="Performance"><span class="none"></span>Performance</a></li> |
| <li><a href="../manual/garbagefree.html#UnderTheHood" title="Under the Hood"><span class="none"></span>Under the Hood</a></li> |
| </ul></li> |
| <li><a href="../manual/jmx.html" title="JMX"><span class="none"></span>JMX</a></li> |
| <li><a href="../manual/logsep.html" title="Logging Separation"><span class="none"></span>Logging Separation</a></li> |
| <li><a href="../manual/extending.html" title="Extending Log4j"><span class="icon-chevron-right"></span>Extending Log4j</a></li> |
| <li><a href="../manual/plugins.html" title="Plugins"><span class="icon-chevron-right"></span>Plugins</a></li> |
| <li><a href="../manual/customconfig.html" title="Programmatic Log4j Configuration"><span class="icon-chevron-right"></span>Programmatic Log4j Configuration</a></li> |
| <li><a href="../manual/customloglevels.html" title="Custom Log Levels"><span class="icon-chevron-right"></span>Custom Log Levels</a></li> |
| <li class="nav-header"><img class="imageLink" src="../img/glyphicons/tag.png" alt="Related Projects" border="0"/> Related Projects</li> |
| <li><a href="http://logging.apache.org/log4j/scala/index.html" class="externalLink" title="Log4j-Scala"><span class="none"></span>Log4j-Scala</a></li> |
| <li class="nav-header"><img class="imageLink" src="../img/glyphicons/link.png" alt="Legacy Sites" border="0"/> Legacy Sites</li> |
| <li><a href="http://logging.apache.org/log4j/1.2/" class="externalLink" title="Log4j 1.2 - End of Life"><span class="none"></span>Log4j 1.2 - End of Life</a></li> |
| <li><a href="http://logging.apache.org/log4j/log4j-2.3/" class="externalLink" title="Log4j 2.3 - Java 6"><span class="none"></span>Log4j 2.3 - Java 6</a></li> |
| <li><a href="http://logging.apache.org/log4j/log4j-2.12.1" class="externalLink" title="Log4j 2.12.1 - Java 7"><span class="none"></span>Log4j 2.12.1 - Java 7</a></li> |
| <li class="nav-header"><img class="imageLink" src="../img/glyphicons/cog.png" alt="Components" border="0"/> Components</li> |
| <li><a href="../log4j-api/index.html" title="API"><span class="none"></span>API</a></li> |
| <li><a href="../log4j-core/index.html" title="Implementation"><span class="none"></span>Implementation</a></li> |
| <li><a href="../log4j-jcl/index.html" title="Commons Logging Bridge"><span class="none"></span>Commons Logging Bridge</a></li> |
| <li><a href="../log4j-1.2-api/index.html" title="Log4j 1.2 API"><span class="none"></span>Log4j 1.2 API</a></li> |
| <li><a href="../log4j-slf4j-impl/index.html" title="SLF4J Binding"><span class="none"></span>SLF4J Binding</a></li> |
| <li><a href="../log4j-jul/index.html" title="JUL Adapter"><span class="none"></span>JUL Adapter</a></li> |
| <li><a href="../log4j-jpl/index.html" title="JDK Platform Logger"><span class="none"></span>JDK Platform Logger</a></li> |
| <li><a href="../log4j-to-slf4j/index.html" title="Log4j 2 to SLF4J Adapter"><span class="none"></span>Log4j 2 to SLF4J Adapter</a></li> |
| <li><a href="../log4j-flume-ng/index.html" title="Apache Flume Appender"><span class="none"></span>Apache Flume Appender</a></li> |
| <li><a href="../log4j-taglib/index.html" title="Log4j Tag Library"><span class="none"></span>Log4j Tag Library</a></li> |
| <li><a href="../log4j-jmx-gui/index.html" title="Log4j JMX GUI"><span class="none"></span>Log4j JMX GUI</a></li> |
| <li><a href="../log4j-web/index.html" title="Log4j Web Application Support"><span class="none"></span>Log4j Web Application Support</a></li> |
| <li><a href="../log4j-appserver/index.html" title="Log4j Application Server Integration"><span class="none"></span>Log4j Application Server Integration</a></li> |
| <li><a href="../log4j-couchdb/index.html" title="Log4j CouchDB appender"><span class="none"></span>Log4j CouchDB appender</a></li> |
| <li><a href="../log4j-mongodb2/index.html" title="Log4j MongoDB2 appender"><span class="none"></span>Log4j MongoDB2 appender</a></li> |
| <li><a href="../log4j-mongodb3/index.html" title="Log4j MongoDB3 appender"><span class="none"></span>Log4j MongoDB3 appender</a></li> |
| <li><a href="../log4j-cassandra/index.html" title="Log4j Cassandra appender"><span class="none"></span>Log4j Cassandra appender</a></li> |
| <li><a href="../log4j-iostreams/index.html" title="Log4j IO Streams"><span class="none"></span>Log4j IO Streams</a></li> |
| <li><a href="../log4j-liquibase/index.html" title="Log4j Liquibase Binding"><span class="none"></span>Log4j Liquibase Binding</a></li> |
| <li><a href="../log4j-docker/index.html" title="Log4j Docker Support"><span class="none"></span>Log4j Docker Support</a></li> |
| <li><a href="../log4j-spring-cloud-config/log4j-spring-cloud-config-client/index.html" title="Log4j Spring Cloud Config Client"><span class="none"></span>Log4j Spring Cloud Config Client</a></li> |
| <li class="nav-header"><img class="imageLink" src="../img/glyphicons/info.png" alt="Project Information" border="0"/> Project Information</li> |
| <li><a href="../dependency-convergence.html" title="Dependency Convergence"><span class="none"></span>Dependency Convergence</a></li> |
| <li><a href="../dependency-management.html" title="Dependency Management"><span class="none"></span>Dependency Management</a></li> |
| <li><a href="../team-list.html" title="Project Team"><span class="none"></span>Project Team</a></li> |
| <li><a href="../mail-lists.html" title="Mailing Lists"><span class="none"></span>Mailing Lists</a></li> |
| <li><a href="../issue-tracking.html" title="Issue Tracking"><span class="none"></span>Issue Tracking</a></li> |
| <li><a href="../license.html" title="Project License"><span class="none"></span>Project License</a></li> |
| <li><a href="../source-repository.html" title="Source Repository"><span class="none"></span>Source Repository</a></li> |
| <li><a href="../project-summary.html" title="Project Summary"><span class="none"></span>Project Summary</a></li> |
| <li class="nav-header"><img class="imageLink" src="../img/glyphicons/layers.png" alt="Project Reports" border="0"/> Project Reports</li> |
| <li><a href="../changes-report.html" title="Changes Report"><span class="none"></span>Changes Report</a></li> |
| <li><a href="../jira-report.html" title="JIRA Report"><span class="none"></span>JIRA Report</a></li> |
| <li><a href="../rat-report.html" title="RAT Report"><span class="none"></span>RAT Report</a></li> |
| </ul> |
| </nav> |
| <div class="well sidebar-nav"> |
| <hr /> |
| <div id="poweredBy"> |
| <div class="clear"></div> |
| <div class="clear"></div> |
| <div class="clear"></div> |
| <a href="http://maven.apache.org/" title="Built by Maven" class="poweredBy"><img class="builtBy" alt="Built by Maven" src="../images/logos/maven-feather.png" /></a> |
| </div> |
| </div> |
| </header> |
| <main id="bodyColumn" class="span10" > |
| |
| |
| <section> |
| <h2><a name="Garbage-free_Steady_State_Logging"></a>Garbage-free Steady State Logging</h2> |
| |
| |
| <p> |
| Garbage collection pauses are a common cause of latency spikes and for many systems |
| significant effort is spent on controlling these pauses. |
| </p> |
| |
| <p> |
| Many logging libraries, including previous versions of Log4j, allocate 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. |
| </p> |
| |
| <p> |
| From version 2.6, Log4j runs in "garbage free" mode by default |
| where objects and buffers are reused and no temporary objects are allocated as much as possible. |
| There is also a "low garbage" mode which is not completely garbage free but does not use ThreadLocal fields. |
| This is the default mode when Log4j <a href="#Config">detects</a> it is running in a web application. |
| |
| Finally, it is possible to switch off all garbage-free logic and run in "classic mode" instead. |
| For details, see the <a href="#Config">Configuration</a> section below. |
| </p> |
| <a name="jfr"></a> |
| <section> |
| <h3><a name="A_Contrived_Example"></a>A Contrived Example</h3> |
| |
| <p> |
| To highlight the difference that garbage-free logging can make, we used Java Flight Recorder |
| to measure a simple application that does nothing but log a simple string as often as possible |
| for about 12 seconds. |
| </p> |
| |
| <p> |
| The application was configured to use Async Loggers, a RandomAccessFile appender and a |
| "%d %p %c{1.} [%t] %m %ex%n" pattern layout. (Async Loggers used the Yield WaitStrategy.) |
| </p> |
| |
| <p> |
| Mission Control shows that with Log4j 2.5 this application allocates 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 has a memory allocation rate of 1.6 MB/sec and |
| was GC-free with 0 (zero) garbage collections. |
| </p> |
| |
| <table border="0" class="table table-striped"> |
| |
| <tr class="a"> |
| |
| <td> |
| <a href="../images/log4j-2.5-FlightRecording.png"><img src="../images/log4j-2.5-FlightRecording-thumbnail40pct.png" alt="" /></a><br /> |
| With Log4j 2.5: memory allocation rate 809 MB/sec, 141 minor collections. |
| </td> |
| |
| <td> |
| <a href="../images/log4j-2.6-FlightRecording.png"><img src="../images/log4j-2.6-FlightRecording-thumbnail40pct.png" alt="" /></a> |
| <br /> |
| Log4j 2.6 did not allocate temporary objects: 0 (zero) garbage collections. |
| </td> |
| </tr> |
| </table> |
| </section> |
| |
| <a name="Config"></a> |
| <section> |
| <h3><a name="Configuration"></a>Configuration</h3> |
| |
| <p>Garbage-free logging in Log4j 2.6 is partially implemented by reusing objects in ThreadLocal fields, |
| and partially by reusing buffers when converting text to bytes. |
| </p> |
| |
| <p> |
| ThreadLocal fields holding non-JDK classes can cause memory leaks in |
| web applications when the application server's thread pool continues to reference |
| these fields after the web application is undeployed. |
| To avoid causing memory leaks, Log4j will not use these ThreadLocals when |
| it detects that it is used in a web application |
| (when the javax.servlet.Servlet class is in the classpath, |
| or when system property log4j2.isWebapp is set to "true"). |
| </p> |
| |
| <p> |
| Some garbage-reducing functionality does not rely on ThreadLocals and is |
| enabled by default for all applications: |
| in Log4j 2.6, converting log events to text and text to bytes can be done by directly encoding text |
| into a reused ByteBuffer without creating intermediary Strings, char arrays and byte arrays. |
| So while logging is not completely garbage-free for web applications yet, |
| the pressure on the garbage collector can still be significantly reduced. |
| </p> |
| |
| <table border="0" class="table table-striped"> |
| <tr class="a"> |
| <td> |
| <p> |
| <b>Note 1:</b> as of version 2.6, a Log4j configuration containing a <Properties> section |
| will result in temporary objects being created during steady-state logging. |
| </p> |
| |
| <p> |
| <b>Note 2:</b> the Async Logger Timeout wait strategy (the default) and the Block wait strategy |
| cause java.util.concurrent.locks.AbstractQueuedSynchronizer$Node objects to be created. |
| The Yield and Sleep wait strategies are garbage-free. (See |
| <a href="async.html#SysPropsAllAsync">here</a> and |
| <a href="async.html#SysPropsMixedSync-Async">here</a>.) |
| </p> |
| </td></tr></table> |
| <section> |
| <h4><a name="Disabling_Garbage-free_Logging"></a>Disabling Garbage-free Logging</h4> |
| |
| <p> |
| There are two separate system properties for manually controlling the mechanisms Log4j uses to avoid |
| creating temporary objects: |
| </p> |
| |
| <ul> |
| |
| <li>log4j2.enableThreadlocals - if "true" (the default for non-web applications) |
| objects are stored in ThreadLocal fields and reused, otherwise new |
| objects are created for each log event.</li> |
| |
| <li>log4j2.enableDirectEncoders - if "true" (the default) log events are converted to text and this |
| text is converted to bytes without creating temporary objects. Note: |
| <i>synchronous</i> logging performance may be worse for multi-threaded applications in this mode due to |
| synchronization on the shared buffer. If your application is multi-threaded and logging performance |
| is important, consider using Async Loggers. |
| </li> |
| |
| <li>The ThreadContext map is <i>not</i> garbage-free by default, but from Log4j 2.7 it can be configured |
| to be garbage-free by setting system property log4j2.garbagefreeThreadContextMap to "true".</li> |
| </ul> |
| |
| <p> |
| Instead of system properties, the above properties can also be specified in a file named |
| log4j2.component.properties by including this file in the classpath of the application. |
| See the <a href="configuration.html#SystemProperties">manual regarding system properties</a> for more info. |
| </p> |
| <a name="Appenders"></a> |
| </section><section> |
| <h4><a name="Supported_Appenders"></a>Supported Appenders</h4> |
| |
| <p> |
| The following <a href="appenders.html">appenders</a> are garbage-free during steady-state logging: |
| </p> |
| |
| <ul> |
| |
| <li>Console</li> |
| |
| <li>File</li> |
| |
| <li>RollingFile (some temporary objects are created during file rollover)</li> |
| |
| <li>RandomAccessFile</li> |
| |
| <li>RollingRandomAccessFile (some temporary objects are created during file rollover)</li> |
| |
| <li>MemoryMappedFile</li> |
| </ul> |
| |
| <p> |
| Any other appenders not in the above list (including AsyncAppender) create temporary objects |
| during steady-state logging. Instead of AsyncAppender, use <a href="async.html">Async Loggers</a> |
| to log asynchronously in a garbage-free manner. |
| </p> |
| |
| <a name="Filters"></a> |
| </section><section> |
| <h4><a name="Supported_Filters"></a>Supported Filters</h4> |
| |
| <p> |
| The following <a href="filters.html">filters</a> are garbage-free during steady-state logging: |
| </p> |
| |
| <ul> |
| |
| <li>CompositeFilter (adding and removing element filters creates temporary objects for thread safety)</li> |
| |
| <li>DynamicThresholdFilter</li> |
| |
| <li>LevelRangeFilter (garbage free since 2.8)</li> |
| |
| <li>MapFilter (garbage free since 2.8)</li> |
| |
| <li>MarkerFilter (garbage free since 2.8)</li> |
| |
| <li>StructuredDataFilter (garbage free since 2.8)</li> |
| |
| <li>ThreadContextMapFilter (garbage free since 2.8)</li> |
| |
| <li>ThresholdFilter (garbage free since 2.8)</li> |
| |
| <li>TimeFilter (garbage free since 2.8 except when range must be recalculated once per day)</li> |
| </ul> |
| |
| <p> |
| Other filters like BurstFilter, RegexFilter and ScriptFilter are not trivial to make garbage free, |
| and there is currently no plan to change them. |
| </p> |
| <a name="Layouts"></a> |
| </section><section> |
| <h4><a name="Supported_Layouts"></a>Supported Layouts</h4> |
| |
| <section> |
| <h5><a name="GelfLayout"></a>GelfLayout</h5> |
| |
| <p>GelfLayout is garbage-free when used with compressionType="OFF", |
| as long as no additional field contains '${' (variable substitution).</p> |
| |
| </section><section> |
| <h5><a name="PatternLayout"></a>PatternLayout</h5> |
| |
| <p> |
| PatternLayout with the following limited set of conversion patterns is garbage-free. |
| Format modifiers to control such things as field width, padding, left and right justification will not |
| generate garbage. |
| </p> |
| |
| <table border="0" class="table table-striped" style="width: 80%"> |
| |
| <tr class="a"> |
| |
| <th>Conversion Pattern</th> |
| |
| <th>Description</th> |
| </tr> |
| |
| <tr class="b"> |
| |
| <td>%c{precision}, %logger{precision}</td> |
| |
| <td>Logger name</td> |
| </tr> |
| |
| <tr class="a"> |
| |
| <td>%d, %date</td> |
| |
| <td>Note: Only the predefined date formats are garbage-free: (millisecond separator may be either |
| a comma ',' or a period '.') |
| |
| <table border="0" class="table table-striped"> |
| |
| <tr class="b"> |
| |
| <th>Pattern</th> |
| |
| <th>Example</th> |
| </tr> |
| |
| <tr class="a"> |
| |
| <td>%d{DEFAULT}</td> |
| |
| <td>2012-11-02 14:34:02,781</td> |
| </tr> |
| |
| <tr class="b"> |
| |
| <td>%d{ISO8601}</td> |
| |
| <td>2012-11-02T14:34:02,781</td> |
| </tr> |
| |
| <tr class="a"> |
| |
| <td>%d{ISO8601_BASIC}</td> |
| |
| <td>20121102T143402,781</td> |
| </tr> |
| |
| <tr class="b"> |
| |
| <td>%d{ABSOLUTE}</td> |
| |
| <td>14:34:02,781</td> |
| </tr> |
| |
| <tr class="a"> |
| |
| <td>%d{DATE}</td> |
| |
| <td>02 Nov 2012 14:34:02,781</td> |
| </tr> |
| |
| <tr class="b"> |
| |
| <td>%d{COMPACT}</td> |
| |
| <td>20121102143402781</td> |
| </tr> |
| |
| <tr class="a"> |
| |
| <td>%d{HH:mm:ss,SSS}</td> |
| |
| <td>14:34:02,781</td> |
| </tr> |
| |
| <tr class="b"> |
| |
| <td>%d{dd MMM yyyy HH:mm:ss,SSS}</td> |
| |
| <td>02 Nov 2012 14:34:02,781</td> |
| </tr> |
| |
| <tr class="a"> |
| |
| <td>%d{HH:mm:ss}{GMT+0}</td> |
| |
| <td>18:34:02</td> |
| </tr> |
| |
| <tr class="b"> |
| |
| <td>%d{UNIX}</td> |
| |
| <td>1351866842</td> |
| </tr> |
| |
| <tr class="a"> |
| |
| <td>%d{UNIX_MILLIS}</td> |
| |
| <td>1351866842781</td> |
| </tr> |
| </table> |
| </td> |
| </tr> |
| |
| <tr class="a"> |
| |
| <td>%enc{pattern}, |
| %encode{pattern}</td> |
| |
| <td>Encodes special characters such as '\n' and HTML characters to help prevent |
| log forging and some XSS attacks that could occur when displaying logs in |
| a web browser - garbage-free since 2.8</td> |
| </tr> |
| |
| <tr class="b"> |
| |
| <td>%equals{pattern}{test}{substitution}, |
| %equalsIgnoreCase{pattern}{test}{substitution}</td> |
| |
| <td>Replaces occurrences of 'test', a string, with its replacement 'substitution' |
| in the string resulting from evaluation of the pattern - garbage-free since 2.8</td> |
| </tr> |
| |
| <tr class="a"> |
| |
| <td>%highlight{pattern}{style}</td> |
| |
| <td>Adds ANSI colors - garbage-free since 2.7 (unless nested pattern is not garbage free)</td> |
| </tr> |
| |
| <tr class="b"> |
| |
| <td>K{key}, map{key}, MAP{key} |
| </td> |
| |
| <td>Outputs the entries in a |
| <a href="../log4j-api/apidocs/org/apache/logging/log4j/message/MapMessage.html" class="javadoc">MapMessage</a>, |
| if one is present in the event - garbage-free since 2.8.</td> |
| </tr> |
| |
| <tr class="a"> |
| |
| <td>%m, %msg, %message</td> |
| |
| <td>Log message (garbage-free unless message text contains '${')</td> |
| </tr> |
| |
| <tr class="b"> |
| |
| <td>%marker</td> |
| |
| <td>The full name of the marker (including parents) - garbage-free since 2.8</td> |
| </tr> |
| |
| <tr class="a"> |
| |
| <td>%markerSimpleName</td> |
| |
| <td>The simple name of the marker (not including parents)</td> |
| </tr> |
| |
| <tr class="b"> |
| |
| <td>%maxLen, %maxLength</td> |
| |
| <td>Truncates another pattern to some max number of characters - garbage-free since 2.8</td> |
| </tr> |
| |
| <tr class="a"> |
| |
| <td>%n</td> |
| |
| <td>The platform dependent line separator</td> |
| </tr> |
| |
| <tr class="b"> |
| |
| <td>%N, %nano</td> |
| |
| <td>System.nanoTime() when the event was logged</td> |
| </tr> |
| |
| <tr class="a"> |
| |
| <td>%notEmpty{pattern}, |
| %varsNotEmpty{pattern}, |
| %variablesNotEmpty{pattern} |
| </td> |
| |
| <td>Outputs the result of evaluating the pattern if and only if |
| all variables in the pattern are not empty - garbage-free since 2.8</td> |
| </tr> |
| |
| <tr class="b"> |
| |
| <td>%p, %level</td> |
| |
| <td>The level of the logging event</td> |
| </tr> |
| |
| <tr class="a"> |
| |
| <td>%r, |
| %relative</td> |
| |
| <td>The number of milliseconds elapsed since the JVM was started until the creation of the logging event |
| - garbage-free since 2.8</td> |
| </tr> |
| |
| <tr class="b"> |
| |
| <td>%sn, %sequenceNumber</td> |
| |
| <td>A sequence number that will be incremented in every event - garbage-free since 2.8</td> |
| </tr> |
| |
| <tr class="a"> |
| |
| <td>%style{pattern}{ANSI style}</td> |
| |
| <td>Style the message - garbage-free since 2.7 (unless nested pattern is not garbage free)</td> |
| </tr> |
| |
| <tr class="b"> |
| |
| <td>%T, %tid, %threadId</td> |
| |
| <td>The ID of the thread that generated the logging event</td> |
| </tr> |
| |
| <tr class="a"> |
| |
| <td>%t, %tn, %thread, %threadName</td> |
| |
| <td>The name of the thread that generated the logging event</td> |
| </tr> |
| |
| <tr class="b"> |
| |
| <td>%tp</td> |
| |
| <td>The priority of the thread that generated the logging event</td> |
| </tr> |
| |
| <tr class="a"> |
| |
| <td>%X{key[,key2...]}, |
| %mdc{key[,key2...]}, |
| %MDC{key[,key2...]}</td> |
| |
| <td>Outputs the Thread Context Map (also known as the Mapped Diagnostic Context or MDC) |
| associated with the thread that generated the logging event - garbage-free since 2.8</td> |
| </tr> |
| |
| <tr class="b"> |
| |
| <td>literal text</td> |
| |
| <td>Garbage-free unless literal contains '${' (variable substitution)</td> |
| </tr> |
| </table> |
| |
| <p> |
| Other PatternLayout conversion patterns, and other Layouts may be updated |
| to avoid creating temporary objects in future releases. (Patches welcome!) |
| </p> |
| |
| <p> |
| <i>Note</i>: Logging exceptions and stack traces will create temporary objects with any layout. |
| (However, Layouts will only create these temporary objects when an exception actually occurs.) |
| We haven't figured out a way to log exceptions and stack traces without creating temporary objects. |
| That is unfortunate, but you probably still want to log them when they happen. |
| </p> |
| |
| <table border="0" class="table table-striped"> |
| <tr class="a"> |
| <td><b>Note:</b> patterns containing regular expressions and lookups for property substitution |
| will result in temporary objects being created during steady-state logging. |
| |
| <p> |
| Including location information is done by walking the stacktrace of an exception, which creates temporary |
| objects, so the following patterns are not garbage-free: |
| </p> |
| |
| <ul> |
| |
| <li>%C, %class - Class Name</li> |
| |
| <li>%F, %file - File Location</li> |
| |
| <li>%l, %location - Location</li> |
| |
| <li>%L, %line - Line Location</li> |
| |
| <li>%M, %method - Method Location</li> |
| </ul> |
| Also, the pattern converters for formatting Throwables are not garbage-free: |
| |
| <ul> |
| |
| <li>%ex, %exception, %throwable - The Throwable trace bound to the LoggingEvent</li> |
| |
| <li>%rEx, %rException %rThrowable - Same as %ex but with wrapping exceptions</li> |
| |
| <li>%xEx, %xException, %xThrowable - Same as %ex but with class packaging information</li> |
| |
| <li>%u, %uuid - Creates a new random or time-based UUID while formatting</li> |
| </ul> |
| |
| </td></tr></table> |
| <a name="api"></a> |
| </section></section><section> |
| <h4><a name="API_Changes"></a>API Changes</h4> |
| |
| <p> |
| Methods have been added to the Logger interface so that no vararg array objects are created |
| when logging messages with up to ten parameters. |
| </p> |
| |
| <p> |
| Also, methods have been added to the Logger interface to log java.lang.CharSequence messages. |
| User-defined objects that implement the CharSequence interface can be logged without creating |
| temporary objects: Log4j will try to turn CharSequence messages, |
| Object messages and message parameters |
| into text by appending them to a StringBuilder as a CharSequence. |
| This avoids calling toString() on these objects. |
| </p> |
| |
| <p> |
| An alternative is to implement the |
| <a class="externalLink" href="http://logging.apache.org/log4j/2.x/log4j-api/xref/org/apache/logging/log4j/util/StringBuilderFormattable.html">org.apache.logging.log4j.util.StringBuilderFormattable</a> |
| interface. |
| If an object is logged that implements this interface, its formatTo method is called instead of |
| toString(). |
| </p> |
| |
| <p> |
| Log4j may call toString() on message and parameter objects when garbage-free logging |
| is disabled (when system property log4j2.enableThreadlocals is set to "false".) |
| </p> |
| <a name="codeImpact"></a> |
| </section><section> |
| <h4><a name="Impact_on_Application_Code:_Autoboxing"></a>Impact on Application Code: Autoboxing</h4> |
| |
| <p> |
| We made an effort to make logging garbage-free without requiring code changes in existing applications, |
| but there is one area where this was not possible. |
| When logging primitive values (i.e. int, double, boolean, etc.) the JVM |
| autoboxes these primitive values to their Object wrapper equivalents, creating garbage. |
| </p> |
| |
| <p> |
| Log4j provides an Unbox utility to prevent autoboxing of primitive parameters. |
| This utility contains a thread-local pool of reused StringBuilders. |
| The Unbox.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. |
| </p> |
| |
| <div> |
| <pre class="prettyprint linenums">import static org.apache.logging.log4j.util.Unbox.box; |
| |
| ... |
| public void garbageFree() { |
| logger.debug("Prevent primitive autoboxing {} {}", box(10L), box(2.6d)); |
| } |
| </pre></div> |
| |
| <table border="0" class="table table-striped"> |
| <tr class="a"> |
| <td> |
| |
| <p> |
| <b>Note:</b> not all logging is garbage free. Specifically: |
| </p> |
| |
| <ul> |
| |
| <li>The ThreadContext map is not garbage-free by default, but can be configured to be garbage-free |
| by setting system property log4j2.garbagefreeThreadContextMap to "true".</li> |
| |
| <li>The ThreadContext stack is not garbage-free.</li> |
| |
| <li>Logging more than 10 parameters creates vararg arrays.</li> |
| |
| <li>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. |
| </li> |
| |
| <li>Logging messages containing '${': substituting a ${variable} creates temporary objects.</li> |
| |
| <li>Logging a lambda <i>as a parameter</i> |
| (logger.info("lambda value is {}", () -> callExpensiveMethod())) creates a vararg array. |
| Logging a lambda expression by itself is garbage-free: |
| logger.debug(() -> callExpensiveMethod()). |
| </li> |
| |
| <li>The Logger.traceEntry and Logger.traceExit methods create temporary objects.</li> |
| </ul> |
| </td></tr></table> |
| |
| <p> |
| </p> |
| |
| <p> |
| </p> |
| </section></section> |
| <a name="Performance"></a> |
| <section> |
| <h3><a name="Performance"></a>Performance</h3> |
| <a name="Latency"></a> |
| <section> |
| <h4><a name="Response_Time_Latency"></a>Response Time Latency</h4> |
| |
| <p>Response time is how long it takes to log a message under a certain load. |
| What is often reported as latency is actually <i>service time</i>: how long it took to perform the operation. |
| This hides the fact that a single spike in service time adds queueing delay for many of the subsequent operations. |
| Service time is easy to measure (and often looks good on paper) but is irrelevant for users since it |
| omits the time spent waiting for service. |
| For this reason we report response time: service time plus wait time. |
| See the <a href="../performance.html#responseTime">response time section</a> of the performance page for more detail. |
| </p> |
| |
| <p>The response time test results below were all derived from running the ResponseTimeTest class |
| which can be found in the Log4j 2 unit test source directory. If you want to run these tests yourself, |
| here are the command line options we used: |
| </p> |
| |
| <ul> |
| |
| <li>-Xms1G -Xmx1G (prevent heap resizing during the test)</li> |
| |
| |
| <li>-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector |
| -DAsyncLogger.WaitStrategy=busyspin (to use Async Loggers. The BusySpin wait strategy reduces some jitter.)</li> |
| |
| <li><b>classic mode: </b>-Dlog4j2.enable.threadlocals=false -Dlog4j2.enable.direct.encoders=false<br /> |
| <b>garbage-free mode: </b>-Dlog4j2.enable.threadlocals=true -Dlog4j2.enable.direct.encoders=true</li> |
| |
| <li>-XX:CompileCommand=dontinline,org.apache.logging.log4j.core.async.perftest.NoOpIdleStrategy::idle</li> |
| |
| <li>-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution |
| -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime (to eyeball GC and safepoint pauses)</li> |
| </ul> |
| |
| </section><section> |
| <h4><a name="Async_Loggers"></a>Async Loggers</h4> |
| |
| <p>The graph below compares "classic" logging to |
| garbage-free logging response time behaviour for Log4j's Async Loggers. |
| In the graph, "100k" means logging at a sustained load of 100,000 messages/second, "800k" is |
| a sustained load of 800,000 messages/second. |
| </p> |
| |
| <p><img src="../images/ResponseTimeAsyncClassicVsGcFree-label.png" alt="" /></p> |
| |
| <p>In <b>classic</b> mode we see numerous minor garbage collections which pause the application threads |
| for 3 milliseconds or more. This quickly adds up to response time delays of almost 10 |
| milliseconds. |
| As you can see in the graph, increasing the load shifts the curve to the left (there are more spikes). |
| This makes sense: logging more means more pressure on the garbage collector resulting in more minor GC pauses. |
| We experimented a little with reducing the load to 50,000 or even 5000 messages/second, |
| but this did not eliminate the 3 millisecond pauses, it just made them occur less frequently. |
| Note that all GC pauses in this test are minor GC pauses. We did not see any full garbage collections.</p> |
| |
| <p>In <b>garbage-free</b> mode, maximum response time remains well below 1 millisecond under a wide range of loads. |
| (Max 780 us at 800,000 messages/sec, max 407 us at 600,000 messages/sec, with the 99% around 5 us for |
| all loads up to 800,000 messages/sec.) Increasing or decreasing the load does not change the response time |
| behaviour. We did not investigate the cause of the 200-300 microsecond pauses we saw in these tests. |
| </p> |
| |
| <p> |
| When we increased the load further we begin to see larger response time pauses for both classic and |
| garbage-free logging. |
| At sustained loads of 1 million messages/second or more we start to approach the maximum throughput of |
| the underlying RandomAccessFile Appender (see the synchronous logging throughput chart below). |
| At these loads the ringbuffer starts to fill up and backpressure kicks in: attempting to add another message |
| when the ringbuffer is full will block until a free slot becomes available. We start to see response times |
| of tens of milliseconds or more; and attempting to increase the load even more results in larger and larger |
| response time spikes. |
| </p> |
| </section><section> |
| <h4><a name="Synchronous_File_Logging"></a>Synchronous File Logging</h4> |
| |
| <p>With synchronous file logging, garbage-free logging still performs better than classic logging, |
| but the difference is less pronounced. |
| </p> |
| |
| <p>At a workload of 100,000 messages/second, classic logging max response time was a little over 2 milliseconds |
| where garbage-free logging was a little over 1 millisecond. |
| When the workload is increased to 300,000 messages/second, classic logging shows response time pauses of 6 |
| milliseconds where the garbage-free response times were less than 3 milliseconds. |
| It may be possible to improve on this, we did not investigate further yet.</p> |
| |
| <p><img src="../images/ResponseTimeSyncClassicVsGcFree.png" alt="" /></p> |
| |
| <p>The above results are obtained with the ResponseTimeTest class which can be found in the Log4j 2 |
| unit test source directory, running on JDK 1.8.0_45 on RHEL 6.5 (Linux 2.6.32-573.1.1.el6.x86_64) |
| with 10-core Xeon CPU E5-2660 v3 @2.60GHz with hyperthreading switched on (20 virtual cores).</p> |
| |
| <a name="Throughput"></a> |
| </section><section> |
| <h4><a name="Classic_Logging_has_Slightly_Higher_Throughput"></a>Classic Logging has Slightly Higher Throughput</h4> |
| |
| <p>Throughput is slightly worse for garbage-free logging, compared to classic logging. |
| This is true for both synchronous and asynchronous logging. |
| The graph below compares the sustained throughput of synchronous logging to a file with Log4j 2.6 in |
| garbage-free mode, classic mode and Log4j 2.5.</p> |
| |
| <p><img src="../images/garbage-free2.6-SyncThroughputLinux.png" alt="Throughput of Log4j 2.6 in garbage-free mode is slightly worse than in classic mode, but on par with 2.5 and much better than alternatives logging libraries" /></p> |
| |
| <p>The results above are obtained with the |
| <a class="externalLink" href="http://openjdk.java.net/projects/code-tools/jmh/">JMH</a> Java benchmark harness. |
| See the FileAppenderBenchmark source code in the log4j-perf module.</p> |
| </section></section> |
| <a name="UnderTheHood"></a> |
| <section> |
| <h3><a name="Under_the_Hood"></a>Under the Hood</h3> |
| |
| <p> |
| Custom Message implementations that implement org.apache.logging.log4j.util.StringBuilderFormattable |
| can be converted to text by garbage-free Layouts without creating temporary objects. |
| PatternLayout uses this mechanism and other layouts that convert LogEvents to text |
| will likely also look for this interface. |
| </p> |
| |
| <p> |
| Custom Layouts that want to be garbage-free should implement the Encoder<LogEvent> interface. |
| For custom Layouts that convert a LogEvent to a text representation, |
| the org.apache.logging.log4j.core.layout.StringBuilderEncoder class may be useful to convert this |
| text to bytes in a garbage-free manner. |
| </p> |
| |
| <p> |
| Custom Appenders that want to be garbage-free should provide their Layout with a |
| ByteBufferDestination implementation that the Layout can directly write into. |
| </p> |
| |
| <p> |
| AbstractOutputStreamAppender has been modified to make the ConsoleAppender, (Rolling)FileAppender, |
| (Rolling)RandomAccessFileAppender and MemoryMappedFileAppender garbage-free. |
| An effort has been made to minimize impact on custom Appenders that extend |
| AbstractOutputStreamAppender, but it is impossible to guarantee that changing the superclass |
| will not impact any and all subclasses. Custom Appenders that extend |
| AbstractOutputStreamAppender should verify that they still function correctly. |
| In case there is a problem, system property log4j2.enable.direct.encoders can be set to "false" |
| to revert to the pre-Log4j 2.6 behaviour. |
| </p> |
| |
| </section> |
| </section> |
| |
| |
| </main> |
| </div> |
| </div> |
| <hr/> |
| <footer> |
| <div class="container-fluid"> |
| <div class="row-fluid"> |
| <p align="center">Copyright © 1999-2020 <a class="external" href="http://www.apache.org">The Apache Software Foundation</a>. All Rights Reserved.<br> |
| Apache Logging, Apache Log4j, Log4j, Apache, the Apache feather logo, and the Apache Logging project logo are trademarks of The Apache Software Foundation.</p> |
| </div> |
| </div> |
| </footer> |
| </body> |
| </html> |