| <!DOCTYPE html> |
| <!-- |
| | Generated by Apache Maven Doxia Site Renderer 1.9.1 from src/site/xdoc/performance.xml at 2020-02-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" /> |
| <meta name="author" content="Ralph Goers" /> |
| <title>Log4j – Performance</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-02-25<span class="divider">|</span> |
| </li> |
| <li id="projectVersion">Version: 2.13.1</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 class="active"><a href="#"><span class="icon-chevron-down"></span>Performance</a> |
| <ul class="nav nav-list"> |
| <li><a href="performance.html#benchmarks" title="Benchmarks"><span class="none"></span>Benchmarks</a></li> |
| <li><a href="performance.html#loglibComparison" title="Logging Library Comparison"><span class="none"></span>Logging Library Comparison</a></li> |
| <li><a href="performance.html#asyncLogging" title="Async Logging Comparison"><span class="none"></span>Async Logging Comparison</a></li> |
| <li><a href="performance.html#asyncLoggingResponseTime" title="Async Logging Latency"><span class="none"></span>Async Logging Latency</a></li> |
| <li><a href="performance.html#asyncLoggingWithParams" title="Parameters"><span class="none"></span>Parameters</a></li> |
| <li><a href="performance.html#asyncLoggingWithLocation" title="Location"><span class="none"></span>Location</a></li> |
| <li><a href="performance.html#fileLoggingComparison" title="File Logging Comparison"><span class="none"></span>File Logging Comparison</a></li> |
| <li><a href="performance.html#filtering" title="Filtering Comparison"><span class="none"></span>Filtering Comparison</a></li> |
| <li><a href="performance.html#tradeoffs" title="Trade-offs"><span class="none"></span>Trade-offs</a></li> |
| </ul></li> |
| <li><a href="articles.html" title="Articles and Tutorials"><span class="none"></span>Articles and Tutorials</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><a href="manual/garbagefree.html" title="Garbage-free Logging"><span class="icon-chevron-right"></span>Garbage-free Logging</a></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-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="Performance"></a>Performance</h2> |
| |
| |
| <p>Apart from functional requirements, an important reason for selecting a logging library is often how well it |
| fulfills non-functional requirements like reliability and performance.</p> |
| |
| <p>This page compares the performance of a number of logging frameworks |
| (java.util.logging "JUL", Logback, Log4j 1.2 and Log4j 2.6), |
| and documents some performance trade-offs for Log4j 2 functionality. |
| </p> |
| <a name="benchmarks"></a> |
| <section> |
| <h3><a name="Benchmarks"></a>Benchmarks</h3> |
| |
| <p>Performance can mean different things to different people. Common terms in this context are |
| throughput and latency: <i>Throughput</i> is a measure of capacity and can be expressed in a single number: |
| how many messages can be logged in a certain period of time. |
| <i>Response time latency</i> is how long it takes to log a message. |
| This cannot be expressed in a single number because each measurement has its own |
| response time and we are often most interested in the outliers: how many there were and how large they were.</p> |
| |
| <p>When evaluating a logging framework's performance these may be useful questions to ask:</p> |
| |
| <ul> |
| |
| <li>What is its <b>peak throughput</b>? |
| Many systems that react to external events need to log bursts of messages followed by periods of |
| relative quiet. |
| This number is the maximum throughput measured over a short period of time and gives some idea |
| of how well the logging library deals with bursts. |
| For systems that need to log a lot at a constant high rate (for example, batch jobs) |
| this is less likely to be a useful measure of performance.</li> |
| |
| <li>What is the <b>maximum sustained throughput</b>? This is the throughput averaged over a long time. |
| This is a useful measure of the "upper limit" of the capacity of the logging library. |
| It is not recommended that reactive applications actually log at this rate since under this load |
| they will likely experience jitter and large response time spikes.</li> |
| <a name="responseTime"></a> |
| |
| <li> |
| <p>What is its <b>response time</b> behaviour under various loads? |
| This is the most important question for applications that need to react to external events in a timely manner. |
| Response time is the total amount of time it takes to log a message and is the sum of the |
| service time and wait time. |
| The <b>service time</b> is the time it takes to do the work to log the message. |
| As the workload increases, the service time often varies little: |
| to do X amount of work it always takes X amount of time. |
| The <b>wait time</b> is how long the request had to wait in a queue before being serviced. |
| <i>As the workload increases, wait time often grows to many times the service time.</i> |
| </p> |
| </li> |
| </ul> |
| <a name="responseTimeVsServiceTime"></a> |
| |
| <table border="0" class="table table-striped"> |
| |
| <tr class="a"> |
| <td> |
| <section><section> |
| <h5><a name="Sidebar:_Why_Care_About_Response_Time_Latency.3F"></a>Sidebar: Why Care About Response Time Latency?</h5> |
| |
| <table class="table table-striped" border="0" style="border: 0"> |
| |
| <tr class="b" style="border: 0"> |
| |
| <td width="50%" style="border: 0"> |
| <p> |
| What is often measured and reported as <i>latency</i> is actually <i>service time</i>, |
| and omits that a service time spike adds wait time for many subsequent events. |
| This may present results that are more optimistic than what users experience. |
| </p> |
| <p> |
| The graph on the right illustrates how much more optimistic service time is than response time. |
| The graph shows response time and service time for the same system under a load of 100,000 messages |
| per second. Out of 24 million measurements, only ~50 are more than 250 microseconds, less than 0.001%. |
| In a service time-only graph this would hardly be visible. |
| However, the depending on the load it will take a while to catch up after a spike. |
| </p> |
| <p> |
| The response time graph shows that in reality many more events are |
| impacted by these delays than the service time numbers alone would suggest. |
| </p> |
| |
| <p> |
| To learn more, watch Gil Tene's eye-opening presentation |
| <a class="externalLink" href="http://www.infoq.com/presentations/latency-response-time">How NOT to measure |
| latency</a>. |
| </p> |
| </td> |
| |
| <td width="50%" style="border: 0"><a href="images/ResponseTimeVsServiceTimeAsyncLoggers.png"><img src="images/ResponseTimeVsServiceTimeAsyncLoggers.png" width="480" height="288" alt="" /></a> |
| </td> |
| </tr> |
| </table> |
| </td></tr> |
| </table> |
| <a name="loglibComparison"></a> |
| </section></section></section><section> |
| <h3><a name="Logging_Library_Performance_Comparison"></a>Logging Library Performance Comparison</h3> |
| |
| <a name="asyncLogging"></a> |
| <section> |
| <h4><a name="Asynchronous_Logging_-_Peak_Throughput_Comparison"></a>Asynchronous Logging - Peak Throughput Comparison</h4> |
| |
| <p>Asynchronous logging is useful to deal with bursts of events. How this works is that |
| a minimum amount of work is done by the application thread to capture all required information in a log event, |
| and this log event is then put on a queue for later processing by a background thread. |
| As long as the queue is sized large enough, the application threads should be able to spend |
| very little time on the logging call and return to the business logic very quickly. |
| </p> |
| |
| <p>It turns out that the choice of queue is extremely important for peak throughput. |
| Log4j 2's Async Loggers use a |
| <a class="externalLink" href="http://lmax-exchange.github.com/disruptor/">lock-free data structure</a>, whereas |
| Logback, Log4j 1.2 and Log4j 2's Asynchronous Appenders use an ArrayBlockingQueue. |
| With a blocking queue, multi-threaded applications often experience lock contention when trying to |
| enqueue the log event. |
| </p> |
| |
| <p>The graph below illustrates the difference a lock-free data structure can make to throughput |
| in multi-threaded scenarios. <i>Log4j 2 scales better with the number of threads: |
| an application with more threads can log more. The other logging libraries suffer |
| from lock contention and total throughput stays constant or drops when more threads are logging. |
| This means that with the other logging libraries, each individual thread will be able to log less.</i></p> |
| |
| <p>Bear in mind that this is <i>peak</i> throughput: Log4j 2's Async Loggers give better throughput up to a point, but |
| once the queue is full, the appender thread needs to wait until a slot becomes available in the queue, |
| and throughput will drop to the maximum sustained throughput of the underlying appenders at best. |
| </p> |
| |
| <p><img src="images/async-throughput-comparison.png" alt="Peak throughput comparison" /> |
| </p> |
| |
| <p>For details, see the <a href="manual/async.html">Async |
| Loggers</a> manual page.</p> |
| |
| <a name="asyncLoggingResponseTime"></a> |
| </section><section> |
| <h4><a name="Asynchronous_Logging_Response_Time"></a>Asynchronous Logging Response Time</h4> |
| |
| <p>Response time behaviour varies a lot with the workload and the number of threads that log concurrently. |
| The <a href="manual/async.html#Latency">Async Loggers</a> manual page and the |
| <a href="manual/garbagefree.html#Latency">garbage-free logging</a> manual page |
| provide some graphs showing response time behaviour under various loads. |
| </p> |
| |
| <p>This section shows another graph showing response time latency behaviour |
| under a modest total workload of 64,000 messages per second, with 4 threads logging concurrently. |
| At this load and on this hardware/OS/JVM configuration, lock contention and context switches play less of a role |
| and the pauses are mostly caused by minor garbage collections. |
| Garbage collection pause duration and frequency can vary a lot: when testing the Log4j 1.2.17 |
| Async Appender |
| a minor GC pause of 7 milliseconds occurred while the Log4j 2 Async Appender test only saw |
| a GC pause of a little over 2 milliseconds. This does not necessarily mean that one is better than the other. |
| </p> |
| |
| <p>Generally, garbage-free async loggers had the best response time behaviour |
| in all configurations we tested. </p> |
| |
| <p><img src="images/ResponseTimeAsyncLogging4Threads@16kEach.png" alt="" /></p> |
| |
| <p>The above result was 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="asyncLoggingWithParams"></a> |
| </section><section> |
| <h4><a name="Asynchronous_Logging_Parameterized_Messages"></a>Asynchronous Logging Parameterized Messages</h4> |
| |
| <p>Many logging libraries offer an API for logging parameterized messages. |
| This enables application code to look something like this:</p> |
| <div> |
| <pre> |
| logger.debug("Entry number: {} is {}", i, entry[i]);</pre></div> |
| In the above example, the fully formatted message text is not created unless the DEBUG level is enabled for the logger. |
| Without this API, you would need three lines of code to accomplish the same: |
| |
| <div> |
| <pre> |
| if (logger.isDebugEnabled()) { |
| logger.debug("Entry number: " + i + " is " + entry[i].toString()); |
| }</pre></div> |
| |
| |
| <p>If the DEBUG level <i>is</i> enabled, then at some point the message needs to be formatted. |
| When logging asynchronously, the message parameters may be changed |
| by the application thread before the background thread had a chance to log the message. |
| This would show the wrong values in the log file. |
| To prevent this, Log4j 2, Log4j 1.2 and Logback format the message text in the application thread |
| <i>before</i> passing off the log event to the background thread.</p> |
| |
| <p>This is the safe thing to do, but the formatting has a performance cost. |
| The graph below compares the throughput of logging messages with parameters using various logging libraries. |
| These are all asynchronous logging calls, so these numbers do not include the cost of disk I/O |
| and represent <i>peak</i> throughput.</p> |
| |
| <p>JUL (java.util.logging) does not have a built-in asynchronous Handler. |
| <a class="externalLink" href="https://docs.oracle.com/javase/8/docs/api/java/util/logging/MemoryHandler.html">MemoryHandler</a> |
| is the nearest thing available so we included it here. |
| MemoryHandler does <i>not</i> do the safe thing of taking a snapshot |
| of the current parameter state (it just keeps a reference to the original parameter objects), |
| and as a result it is very fast when single-threaded. |
| However, when more application threads are logging concurrently, the cost of lock contention outweighs this gain.</p> |
| |
| <p>In absolute numbers, <i>Log4j 2's Async Loggers perform well compared to the other logging |
| frameworks, but notice that the message formatting cost increases sharply with the number of parameters. |
| In this area, Log4j 2 still has work to do to improve: we would like to keep this cost more constant.</i> |
| </p> |
| |
| <p><img src="images/ParamMsgThrpt1-4T.png" alt="" /></p> |
| |
| <p>The results above are for JUL (java.util.logging) 1.8.0_45, Log4j 2.6, Log4j 1.2.17 and Logback 1.1.7, |
| and were obtained with the |
| <a class="externalLink" href="http://openjdk.java.net/projects/code-tools/jmh/">JMH</a> Java benchmark harness. |
| See the AsyncAppenderLog4j1Benchmark, AsyncAppenderLog4j2Benchmark, AsyncAppenderLogbackBenchmark, |
| AsyncLoggersBenchmark and the MemoryHandlerJULBenchmark source code in the log4j-perf module. |
| </p> |
| |
| <a name="asyncLoggingWithLocation"></a> |
| </section><section> |
| <h4><a name="Asynchronous_Logging_with_Caller_Location_Information"></a>Asynchronous Logging with Caller Location Information</h4> |
| |
| <p> |
| Some layouts can show the class, method and line number in the application where the logging call was made. |
| In Log4j 2, examples of such layout options are HTML |
| <a href="layouts.html#HtmlLocationInfo">locationInfo</a>, |
| or one of the patterns <a href="layouts.html#PatternClass">%C or $class</a>, |
| <a href="layouts.html#PatternFile">%F or %file</a>, |
| <a href="layouts.html#PatternLocation">%l or %location</a>, |
| <a href="layouts.html#PatternLine">%L or %line</a>, |
| <a href="layouts.html#PatternMethod">%M or %method</a>. |
| In order to provide caller location information, the logging library |
| will take a snapshot of the stack, and walk the stack trace to find the location information. |
| </p> |
| |
| <p> |
| The graph below shows the performance impact of capturing caller location information when logging |
| asynchronously from a single thread. Our tests show that <i>capturing caller location has a similar impact |
| across all logging libraries, and slows down asynchronous |
| logging by about 30-100x</i>. |
| </p> |
| |
| <p><img src="images/AsyncWithLocationThrpt1T-labeled.png" alt="" /></p> |
| |
| <p>The results above are for JUL (java.util.logging) 1.8.0_45, Log4j 2.6, Log4j 1.2.17 and Logback 1.1.7, |
| and were obtained with the |
| <a class="externalLink" href="http://openjdk.java.net/projects/code-tools/jmh/">JMH</a> Java benchmark harness. |
| See the AsyncAppenderLog4j1LocationBenchmark, AsyncAppenderLog4j2LocationBenchmark, |
| AsyncAppenderLogbackLocationBenchmark, AsyncLoggersLocationBenchmark and the |
| MemoryHandlerJULLocationBenchmark source code in the log4j-perf module. |
| </p> |
| |
| <a name="fileLoggingComparison"></a> |
| </section><section> |
| <h4><a name="Synchronous_File_Logging_-_Sustained_Throughput_Comparison"></a>Synchronous File Logging - Sustained Throughput Comparison</h4> |
| |
| <p>This section discusses the maximum sustained throughput of logging to a file. |
| In any system, the maximum sustained throughput is determined by its slowest component. |
| In the case of logging, this is the appender, where the message formatting and disk I/O takes place. |
| For this reason we will look at simple <i>synchronous</i> logging to a file, |
| without queues or background threads.</p> |
| |
| <p>The graph below compares Log4j 2.6's RandomAccessFile appender |
| to the respective File appenders of Log4j 1.2.17, Logback 1.1.7 and |
| Java util logging (JUL) on Oracle Java 1.8.0_45. ImmediateFlush was set to false for all |
| loggers that support this. The JUL results are for the XMLFormatter (which in our measurements was |
| about twice as fast as the SimpleFormatter).</p> |
| |
| <p><i>Log4j 2's sustained throughput drops a little when more threads are logging simultaneously, |
| but its fine-grained locking pays off and throughput stays relatively high. |
| The other logging frameworks' throughput drops dramatically in multi-threaded applications: |
| Log4j 1.2 has 1/4th of its single-threaded capacity, |
| Logback has 1/10th of its single-threaded capacity, and JUL steadily drops from 1/4th to 1/10th of its |
| single-threaded throughput as more threads are added.</i></p> |
| |
| <p><img src="images/SyncThroughputLoggerComparisonLinux.png" alt="" /></p> |
| |
| <p>The synchronous logging throughput 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> |
| <h4><a name="Synchronous_File_Logging_-_Response_Time_Comparison"></a>Synchronous File Logging - Response Time Comparison</h4> |
| |
| <p>Response time for synchronous file logging varies a lot with the workload and the |
| number of threads. Below is a sample for a workload of 32,000 events per second, |
| with 2 threads logging 16,000 events per second each.</p> |
| |
| <p><img src="images/SynchronousFileResponseTime2T32k-labeled.png" alt="" /></p> |
| |
| <p>The above result was 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="filtering"></a> |
| </section><section> |
| <h4><a name="Filtering_by_Level"></a>Filtering by Level</h4> |
| |
| <p>The most basic filtering a logging framework provides is filtering by log level. |
| When logging is turned off entirely or just for a set of Levels, the cost of a log request consists |
| of a number of method invocations plus an integer comparison. |
| Unlike Log4j, Log4j 2 Loggers don't "walk a hierarchy". |
| Loggers point directly to the Logger configuration that best matches the Logger's name. |
| This incurs extra overhead when the Logger is first created but reduces the overhead every |
| time the Logger is used. |
| </p> |
| </section><section> |
| <h4><a name="Advanced_Filtering"></a>Advanced Filtering</h4> |
| |
| <p> |
| Both Logback and Log4j 2 support advanced filtering. Logback calls them TurboFilters while |
| Log4j 2 has a single Filter object. Advanced filtering provides the capability to filter |
| LogEvents using more than just the Level before the events are passed to Appenders. |
| However, this flexibility does come with some cost. |
| Since multi-threading can also have an impact on the |
| performance of advanced filtering, the chart below shows the difference in performance of filtering based |
| on a Marker or a Marker's parent.</p> |
| |
| <p> |
| The "Simple Marker" comparison checks to see if a Marker that has no references |
| to other markers matches the requested Marker. The "Parent Marker" comparison checks to see |
| if a Marker that does have references to other markers matches the requested Marker. </p> |
| |
| <p>It appears that coarse-grained synchronization in SLF4J can impact performance in |
| multi-threaded scenarios. See |
| <a class="externalLink" href="http://jira.qos.ch/browse/SLF4J-240">SLF4J-240</a>.</p> |
| |
| <p><img src="images/MarkerFilterCostComparison.png" alt="" /></p> |
| |
| <p>Log4j and Logback also support filtering |
| on a value in the Log4j ThreadContext vs filtering in Logback on a value in the MDC. |
| The graph below shows that the performance difference between Log4j 2 and Logback |
| is small for the ThreadContext filter. |
| </p> |
| <p><img src="images/ThreadContextFilterCostComparison.png" alt="" /></p> |
| |
| <p>The Filter comparison 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 MarkerFilterBenchmark and MDCFilterBenchmark in the log4j-perf module for details on these |
| benchmarks.</p> |
| <a name="tradeoffs"></a> |
| </section></section><section> |
| <h3><a name="Trade-offs"></a>Trade-offs</h3> |
| <a name="whichAppender"></a> |
| <section> |
| <h4><a name="Which_Log4j_2_Appender_to_Use.3F"></a>Which Log4j 2 Appender to Use?</h4> |
| |
| <p>Assuming that you selected Log4j 2 as your logging framework, |
| next you may be interested in learning what the performance trade-offs are for |
| selecting a specific Log4j 2 configuration. For example, there are three appenders |
| for logging to a file: the File, RandomAccessFile and MemoryMappedFile appenders. |
| Which one should you use?</p> |
| |
| <p>If performance is all you care about, the graphs below show your best choice is either |
| the MemoryMappedFile appender or the RandomAccessFile appender. |
| Some things to bear in mind: |
| </p> |
| |
| <ul> |
| |
| <li>MemoryMappedFile appender does not have a rolling variant yet.</li> |
| |
| <li>When the log file size exceeds the MemoryMappedFile's region length, the file needs to be remapped. |
| This can be a very expensive operation, taking several seconds if the region is large.</li> |
| |
| <li>MemoryMappedFile appender creates a presized file from the beginning and fills it up gradually. |
| This can confuse tools like tail; many such tools don't work very well with memory mapped files.</li> |
| |
| <li>On Windows, using a tool like tail on a file created by RandomAccessFile appender |
| can hold a lock on this file which may prevent Log4j from opening the file again when the |
| application is restarted. In a development environment where you expect to restart your application |
| regularly while using tools like tail to view the log file contents, the File appender may be |
| a reasonable trade-off between performance and flexibility. For production environments |
| performance may have higher priority.</li> |
| </ul> |
| |
| <p> |
| The graph below shows sustained throughput for the console and file appenders in Log4j 2.6, |
| and for reference also provides the 2.5 performance.</p> |
| |
| <p>It turns out that the garbage-free text encoding logic in 2.6 gives |
| these appenders a performance boost compared to Log4j 2.5. |
| It used to be that the RandomAccessFile appender was significantly faster, |
| especially in multi-threaded scenarios, but with the 2.6 release the File appender |
| performance has improved and the performance difference between these two appender is smaller.</p> |
| |
| <p>Another takeaway is just how much of a performance drag logging to the console can be. |
| Considering logging to a file and using a tool like tail to watch the file change in real time.</p> |
| |
| <p><img src="images/Log4j2AppenderThroughputComparison-linux.png" alt="" /></p> |
| |
| <p>On Windows, the results are similar but the RandomAccessFile and MemoryMappedFile appenders outperform |
| the plain File appender in multi-threaded scenarios. |
| The absolute numbers are higher on Windows: we don't know why but it looks like Windows |
| handles lock contention better than Linux.</p> |
| |
| <p><img src="images/Log4j2AppenderThroughputComparison-windows.png" alt="" /></p> |
| |
| <p>The Log4j 2 appender comparison 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 Log4j2AppenderComparisonBenchmark source code in the log4j-perf module.</p> |
| |
| |
| </section></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> |
