This is an automated email from the ASF dual-hosted git repository. vy pushed a commit to branch doc/perf in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git
commit 99fcdb6b2f3a8437cf8cc71e66e81751f236a0ff Author: Volkan Yazıcı <vol...@yazi.ci> AuthorDate: Mon May 13 16:51:17 2024 +0200 Remove performance figures in `garbagefree.adoc` --- .../ResponseTimeAsyncClassicVsGcFree-label.png | Bin 31148 -> 0 bytes .../ResponseTimeAsyncLogging16Threads_8kEach.png | Bin 29429 -> 0 bytes ...ncLogging16Threads_8kEachLog4j2Only-labeled.png | Bin 41663 -> 0 bytes .../images/ResponseTimeSyncClassicVsGcFree.png | Bin 33240 -> 0 bytes .../images/garbage-free2.6-SyncThroughputLinux.png | Bin 24197 -> 0 bytes .../log4j-2.5-FlightRecording-thumbnail40pct.png | Bin 57992 -> 0 bytes .../ROOT/images/log4j-2.5-FlightRecording.png | Bin 68628 -> 0 bytes .../log4j-2.6-FlightRecording-thumbnail40pct.png | Bin 45221 -> 0 bytes .../ROOT/images/log4j-2.6-FlightRecording.png | Bin 50481 -> 0 bytes .../modules/ROOT/pages/manual/garbagefree.adoc | 164 +-------------------- 10 files changed, 2 insertions(+), 162 deletions(-) diff --git a/src/site/antora/modules/ROOT/images/ResponseTimeAsyncClassicVsGcFree-label.png b/src/site/antora/modules/ROOT/images/ResponseTimeAsyncClassicVsGcFree-label.png deleted file mode 100644 index 22994316c1..0000000000 Binary files a/src/site/antora/modules/ROOT/images/ResponseTimeAsyncClassicVsGcFree-label.png and /dev/null differ diff --git a/src/site/antora/modules/ROOT/images/ResponseTimeAsyncLogging16Threads_8kEach.png b/src/site/antora/modules/ROOT/images/ResponseTimeAsyncLogging16Threads_8kEach.png deleted file mode 100644 index 63e24fb7e8..0000000000 Binary files a/src/site/antora/modules/ROOT/images/ResponseTimeAsyncLogging16Threads_8kEach.png and /dev/null differ diff --git a/src/site/antora/modules/ROOT/images/ResponseTimeAsyncLogging16Threads_8kEachLog4j2Only-labeled.png b/src/site/antora/modules/ROOT/images/ResponseTimeAsyncLogging16Threads_8kEachLog4j2Only-labeled.png deleted file mode 100644 index 3202c2353f..0000000000 Binary files a/src/site/antora/modules/ROOT/images/ResponseTimeAsyncLogging16Threads_8kEachLog4j2Only-labeled.png and /dev/null differ diff --git a/src/site/antora/modules/ROOT/images/ResponseTimeSyncClassicVsGcFree.png b/src/site/antora/modules/ROOT/images/ResponseTimeSyncClassicVsGcFree.png deleted file mode 100644 index a4f19ac2a4..0000000000 Binary files a/src/site/antora/modules/ROOT/images/ResponseTimeSyncClassicVsGcFree.png and /dev/null differ diff --git a/src/site/antora/modules/ROOT/images/garbage-free2.6-SyncThroughputLinux.png b/src/site/antora/modules/ROOT/images/garbage-free2.6-SyncThroughputLinux.png deleted file mode 100644 index 80f9b6aac8..0000000000 Binary files a/src/site/antora/modules/ROOT/images/garbage-free2.6-SyncThroughputLinux.png and /dev/null differ diff --git a/src/site/antora/modules/ROOT/images/log4j-2.5-FlightRecording-thumbnail40pct.png b/src/site/antora/modules/ROOT/images/log4j-2.5-FlightRecording-thumbnail40pct.png deleted file mode 100644 index 2144149cbb..0000000000 Binary files a/src/site/antora/modules/ROOT/images/log4j-2.5-FlightRecording-thumbnail40pct.png and /dev/null differ diff --git a/src/site/antora/modules/ROOT/images/log4j-2.5-FlightRecording.png b/src/site/antora/modules/ROOT/images/log4j-2.5-FlightRecording.png deleted file mode 100644 index bd69464d43..0000000000 Binary files a/src/site/antora/modules/ROOT/images/log4j-2.5-FlightRecording.png and /dev/null differ diff --git a/src/site/antora/modules/ROOT/images/log4j-2.6-FlightRecording-thumbnail40pct.png b/src/site/antora/modules/ROOT/images/log4j-2.6-FlightRecording-thumbnail40pct.png deleted file mode 100644 index 46ec82b42f..0000000000 Binary files a/src/site/antora/modules/ROOT/images/log4j-2.6-FlightRecording-thumbnail40pct.png and /dev/null differ diff --git a/src/site/antora/modules/ROOT/images/log4j-2.6-FlightRecording.png b/src/site/antora/modules/ROOT/images/log4j-2.6-FlightRecording.png deleted file mode 100644 index e42b1de842..0000000000 Binary files a/src/site/antora/modules/ROOT/images/log4j-2.6-FlightRecording.png and /dev/null differ diff --git a/src/site/antora/modules/ROOT/pages/manual/garbagefree.adoc b/src/site/antora/modules/ROOT/pages/manual/garbagefree.adoc index 220a49fc4e..6f17cda830 100644 --- a/src/site/antora/modules/ROOT/pages/manual/garbagefree.adoc +++ b/src/site/antora/modules/ROOT/pages/manual/garbagefree.adoc @@ -14,60 +14,10 @@ See the License for the specific language governing permissions and limitations under the License. //// -= Garbage-free Steady State Logging -Remko Popma <rpo...@apache.org> - -//// -Different applications have different performance requirements. -Some only need to worry about throughput, but for many -the most important performance consideration is latency (response time). -Users of such applications would consider it a serious problem -if the system becomes unresponsive for more than a few seconds, or even milliseconds in some cases. -In financial trading for example predictable low latency is so important that it is often considered -worthwhile to trade off some throughput in return for a consistent response time. -//// - -Garbage collection pauses are a common cause of latency spikes and for -many systems significant effort is spent on controlling these pauses. - -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. - -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 link:#Config[detects] 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 -link:#Config[Configuration] section below. -[#jfr] -== A Contrived Example - -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. - -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.) - -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. - -.Using Log4j 2.5: memory allocation rate 809 MB/sec, 141 minor collections -image:log4j-2.5-FlightRecording-thumbnail40pct.png[xref=image$log4j-2.5-FlightRecording.png] += Garbage-free Steady State Logging -.Using Log4j 2.6: no temporary object allocations, 0 (zero) garbage collections -image:log4j-2.6-FlightRecording-thumbnail40pct.png[xref=image$log4j-2.6-FlightRecording.png] +include::partial$manual/garbagefree-intro.adoc[] [#Config] == Configuration @@ -432,116 +382,6 @@ temporary objects. The default is false. **** -[#Performance] -== Performance - -[#Latency] -=== Response Time Latency - -Response time is how long it takes to log a message under a certain -load. What is often reported as latency is actually _service time_: 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 xref:manual/performance.adoc#responseTime[response time -section] of the performance page for more detail. - -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: - -* -Xms1G -Xmx1G (prevent heap resizing during the test) -* -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector --DAsyncLogger.WaitStrategy=busyspin (to use Async Loggers. The BusySpin -wait strategy reduces some jitter.) -* *classic mode:* -Dlog4j2.enable.direct.encoders=false + -*garbage-free mode:* -Dlog4j2.enable.direct.encoders=true -* -XX:CompileCommand=dontinline,org.apache.logging.log4j.core.async.perftest.NoOpIdleStrategy::idle -* -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps --XX:+PrintTenuringDistribution -XX:+PrintGCApplicationConcurrentTime --XX:+PrintGCApplicationStoppedTime (to eyeball GC and safepoint pauses) - -=== Async Loggers - -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. - -image:ResponseTimeAsyncClassicVsGcFree-label.png[image] - -In *classic* 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. - -In *garbage-free* 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. - -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. - -=== Synchronous File Logging - -With synchronous file logging, garbage-free logging still performs -better than classic logging, but the difference is less pronounced. - -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. - -image:ResponseTimeSyncClassicVsGcFree.png[image] - -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). - -[#Throughput] -=== Classic Logging has Slightly Higher Throughput - -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. - -image:garbage-free2.6-SyncThroughputLinux.png[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] - -The results above are obtained with the -http://openjdk.java.net/projects/code-tools/jmh/[JMH] Java benchmark -harness. See the FileAppenderBenchmark source code in the log4j-perf-test -module. - [#UnderTheHood] == Under the Hood