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 c7c1686b1239acff1187b88e42f47b0af980cde0 Author: Volkan Yazıcı <vol...@yazi.ci> AuthorDate: Tue May 14 10:03:15 2024 +0200 Rewrite `garbagefree.adoc` --- src/site/antora/modules/ROOT/nav.adoc | 4 +- .../antora/modules/ROOT/pages/manual/async.adoc | 3 +- .../modules/ROOT/pages/manual/garbagefree.adoc | 495 +++++++-------------- .../antora/modules/ROOT/pages/manual/layouts.adoc | 196 +++++++- .../modules/ROOT/pages/manual/performance.adoc | 8 +- .../ROOT/partials/premature-optimization.adoc | 24 + .../ROOT/partials/properties-async-logger.adoc | 8 +- .../partials/properties-garbage-collection.adoc | 12 +- .../modules/ROOT/partials/properties-meta.adoc | 3 +- .../ROOT/partials/properties-thread-context.adoc | 10 +- 10 files changed, 399 insertions(+), 364 deletions(-) diff --git a/src/site/antora/modules/ROOT/nav.adoc b/src/site/antora/modules/ROOT/nav.adoc index b7789787fd..417383b7fc 100644 --- a/src/site/antora/modules/ROOT/nav.adoc +++ b/src/site/antora/modules/ROOT/nav.adoc @@ -48,8 +48,6 @@ * xref:manual/layouts.adoc[] ** xref:manual/json-template-layout.adoc[] * xref:manual/filters.adoc[] -* xref:manual/async.adoc[] -* xref:manual/garbagefree.adoc[] * xref:manual/extending.adoc[] * xref:manual/plugins.adoc[] * xref:manual/customconfig.adoc[] @@ -57,6 +55,8 @@ * xref:manual/jmx.adoc[] * xref:manual/logsep.adoc[] * xref:manual/performance.adoc[] +** xref:manual/async.adoc[] +** xref:manual/garbagefree.adoc[] .References * xref:plugin-reference.adoc[Plugin reference] diff --git a/src/site/antora/modules/ROOT/pages/manual/async.adoc b/src/site/antora/modules/ROOT/pages/manual/async.adoc index a8b814c416..7a26567d74 100644 --- a/src/site/antora/modules/ROOT/pages/manual/async.adoc +++ b/src/site/antora/modules/ROOT/pages/manual/async.adoc @@ -14,8 +14,7 @@ See the License for the specific language governing permissions and limitations under the License. //// -= Lock-free Asynchronous Loggers for Low-Latency Logging -Remko Popma <rpo...@apache.org> += Asynchronous loggers Asynchronous logging can improve your application's performance by executing the I/O operations in a separate thread. Log4j 2 makes a diff --git a/src/site/antora/modules/ROOT/pages/manual/garbagefree.adoc b/src/site/antora/modules/ROOT/pages/manual/garbagefree.adoc index 6f17cda830..cb658d2919 100644 --- a/src/site/antora/modules/ROOT/pages/manual/garbagefree.adoc +++ b/src/site/antora/modules/ROOT/pages/manual/garbagefree.adoc @@ -15,406 +15,219 @@ limitations under the License. //// -= Garbage-free Steady State Logging +// Properties crowd the ToC, hence limit the exposed levels +:page-toclevels: 2 -include::partial$manual/garbagefree-intro.adoc[] - -[#Config] -== Configuration - -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. - -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 xref:manual/configuration.adoc#log4j2.isWebapp[log4j2.isWebapp] is set to `true`). - -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. - -NOTE: As of version 2.6, a Log4j configuration containing a -`<Properties>` section will result in temporary objects being created -during steady-state logging. - -NOTE: as of version 2.18.0, the default Async Logger wait strategy used by Log4j -(Timeout) is garbage-free. Some of the wait strategies included in LMAX disruptor 3.4.4, -especially `TimeoutBlockingWaitStrategy` and `BlockingWaitStrategy` (Block) -are not garbage-free since they -cause `java.util.concurrent.locks.AbstractQueuedSynchronizer$Node` objects to be created. -The default wait strategy used by Log4j uses a synchronized block instead of a ReentrantLock to avoid this problem. -The Yield and Sleep wait strategies are garbage-free. (For configuring predefined wait strategies, see -xref:manual/async.adoc#SysPropsAllAsync[here] and -xref:manual/async.adoc#SysPropsMixedSync-Async[here], -you may also configure a xref:manual/async.adoc#WaitStrategy[custom wait strategy].) - -=== Disabling Garbage-free Logging - -There are separate system properties for manually controlling the -mechanisms Log4j uses to avoid creating temporary objects: - -* xref:manual/configuration.adoc#log4j2.enableThreadlocals[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. -* xref:manual/configuration.adoc#log4j2.enableDirectEncoders[log4j2.enableDirectEncoders] - if "true" (the default) -log events are -converted to text and this text is converted to bytes without creating -temporary objects. Note: _synchronous_ 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. -* The ThreadContext map is _not_ garbage-free by default, but from Log4j -2.7 it can be configured to be garbage-free by setting system property -xref:manual/configuration.adoc#log4j2.garbagefreeThreadContextMap[log4j2.garbagefreeThreadContextMap] to "true". - -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 -xref:manual/configuration.adoc#SystemProperties[manual regarding system -properties] for more info. += Garbage-free logging -[#Appenders] -=== Supported Appenders +include::partial$manual/garbagefree-intro.adoc[] -The following xref:manual/appenders.adoc[appenders] are garbage-free during -steady-state logging: +include::partial$premature-optimization.adoc[] -* Console -* File -* RollingFile (some temporary objects are created during file rollover) -* RandomAccessFile -* RollingRandomAccessFile (some temporary objects are created during -file rollover) -* MemoryMappedFile +The act of logging is an interplay between the logging API (i.e., Log4j API) where the programmer publishes logs and a logging implementation (i.e., Log4j Core) where published logs get consumed; filtered, enriched, encoded, and written to files, databases, network sockets, etc. +Both parties contain different features with different memory allocation characteristics. +To achieve an end-to-end garbage-free logging system, they need to work hand in hand. +Hence, we will discuss both: -Any other appenders not in the above list (including AsyncAppender) -create temporary objects during steady-state logging. Instead of -AsyncAppender, use xref:manual/async.adoc[Async Loggers] to log asynchronously -in a garbage-free manner. +. xref:#Config[] +. xref:#api[] -[#Filters] -=== Supported Filters +[#impatient] +== For the impatient -The following xref:manual/filters.adoc[filters] are garbage-free during -steady-state logging: +If you want to have a garbage-free Log4j setup, but don't want to spend time with associated details, you can start with setting the following system properties to `true`: -* CompositeFilter (adding and removing element filters creates temporary -objects for thread safety) -* DynamicThresholdFilter -* LevelRangeFilter (garbage free since 2.8) -* MapFilter (garbage free since 2.8) -* MarkerFilter (garbage free since 2.8) -* StructuredDataFilter (garbage free since 2.8) -* ThreadContextMapFilter (garbage free since 2.8) -* ThresholdFilter (garbage free since 2.8) -* TimeFilter (garbage free since 2.8 except when range must be recalculated once per day) - -Other filters like BurstFilter, RegexFilter and ScriptFilter are not -trivial to make garbage free, and there is currently no plan to change -them. +* xref:#log4j2.enableThreadlocals[`log4j2.enableThreadlocals`] +* xref:#log4j2.garbagefreeThreadContextMap[`log4j2.garbagefreeThreadContextMap`] -[#Layouts] -=== Supported Layouts +This should be sufficient for a majority of use cases. +If not for yours, keep on reading. -==== GelfLayout - -GelfLayout is garbage-free when used with compressionType="OFF", as long as no additional field contains '${' (variable substitution). - -==== JsonTemplateLayout - -`JsonTemplateLayout` is garbage-free with -xref:manual/json-template-layout.adoc#faq-garbage-free[a few exceptions]. +[#Config] +== Log4j Core configuration -==== PatternLayout +In order to have a garbage-free Log4j Core, you need to -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. +* xref:#properties[configure it using properties], +* and employ garbage-free xref:#Layouts[layouts], xref:Appenders[appenders], and xref:#Filters[filters]. -[cols="1m,2"] -|=== -|Conversion Pattern |Description +[#core-properties] +=== Properties -|%c\{precision}, %logger\{precision} -|Logger name +Garbage-free logging can be configured for Log4j Core using properties listed below. +(See xref:manual/configuration.adoc[] on details how you can set these properties.) -|%d, %date -a| -Note: Only the predefined date formats are garbage-free: (millisecond -separator may be either a comma ',' or a period '.') +include::partial$properties-meta.adoc[leveloffset=+2] -[cols="1m,1"] -!=== -!Pattern !Example +include::partial$properties-garbage-collection.adoc[leveloffset=+2,tag=!api] -!%d\{DEFAULT} -!2012-11-02 14:34:02,781 +[#Layouts] +=== Layouts -!%d\{ISO8601} -!2012-11-02T14:34:02,781 +The following xref:manual/layouts.adoc[layouts] can be configured to run garbage-free during steady-state logging. +To understand which configuration knobs exhibit what kind of allocation behaviour, see their dedicated pages. -!%d\{ISO8601_BASIC} -!20121102T143402,781 +// Maintain the alphabetical ordering while making changes, please! +* xref:manual/layouts.adoc#GELFLayout[`GelfLayout`] +* xref:manual/json-template-layout.adoc#faq-garbage-free[`JsonTemplateLayout`] +* xref:manual/layouts.adoc#PatternLayout-gcfree[`PatternLayout`] -!%d\{ABSOLUTE} -!14:34:02,781 +.Implementation notes +[%collapsible] +==== +Garbage-free xref:manual/layouts.adoc[layouts] need to implement the `Encoder<LogEvent>` interface. +link:../javadoc/log4j-core/org/apache/logging/log4j/core/layout/StringBuilderEncoder.html[`StringBuilderEncoder`] helps with encoding text to bytes in a garbage-free manner. +==== -!%d\{DATE} -!02 Nov 2012 14:34:02,781 +[#Appenders] +=== Appenders -!%d\{COMPACT} -!20121102143402781 +The following xref:manual/appenders.adoc[appenders] are garbage-free during steady-state logging: -!%d{HH:mm:ss,SSS} -!14:34:02,781 +// Maintain the alphabetical ordering while making changes, please! +* xref:manual/appenders.adoc#ConsoleAppender[`ConsoleAppender`] +* xref:manual/appenders.adoc#FileAppender[`FileAppender`] +* xref:manual/appenders.adoc#MemoryMappedFileAppender[`MemoryMappedFileAppender`] +* xref:manual/appenders.adoc#RandomAccessFileAppender[`RandomAccessFileAppender`] +* xref:manual/appenders.adoc#RollingFileAppender[`RollingFileAppender`] (except during rollover) +* xref:manual/appenders.adoc#RollingRandomAccessFileAppender[`RollingRandomAccessFileAppender`] (except during rollover) -!%d{dd MMM yyyy HH:mm:ss,SSS} -!02 Nov 2012 14:34:02,781 +Any other appender not shared in the above list (including xref:manual/appenders.adoc#AsyncAppender[`AsyncAppender`]) is not garbage-free. -!%d{HH:mm:ss}{GMT+0} -!18:34:02 +.Implementation notes +[%collapsible] +==== +Garbage-free xref:manual/appenders.adoc[appenders] need to provide their xref:manual/layouts.adoc[layout] with a `ByteBufferDestination` implementation that the layout can directly write into. -!%d\{UNIX} -!1351866842 +[NOTE] +===== +`AbstractOutputStreamAppender` has been modified to make the following appenders garbage-free: -!%d\{UNIX_MILLIS} -!1351866842781 -!=== +* `ConsoleAppender` +* `(Rolling)FileAppender` +* `(Rolling)RandomAccessFileAppender` +* `MemoryMappedFileAppender` -|%enc\{pattern}, %encode\{pattern} -|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 +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, xref:#log4j2.enableDirectEncoders[the `log4j2.enableDirectEncoders` system property] can be set to `false` to revert to the pre-Log4j 2.6 behaviour. +===== +==== -|%equals\{pattern}\{test}\{substitution}, -%equalsIgnoreCase\{pattern}\{test}\{substitution} -|Replaces occurrences -of 'test', a string, with its replacement 'substitution' in the string -resulting from evaluation of the pattern - garbage-free since 2.8 +[#Filters] +=== Filters -|%highlight\{pattern}\{style} -|Adds ANSI colors - garbage-free since 2.7 -(unless nested pattern is not garbage free) +The following xref:manual/filters.adoc[filters] are garbage-free during steady-state logging: -|%K\{key}, %map\{key}, %MAP\{key} -|Outputs the entries in a -link:../javadoc/log4j-api/org/apache/logging/log4j/message/MapMessage.html[MapMessage], -if one is present in the event - garbage-free since 2.8. +// Maintain the alphabetical ordering while making changes, please! +* xref:manual/filters.adoc#CompositeFilter[`CompositeFilter`] (adding and removing element filters creates temporary +objects for thread safety) +* xref:manual/filters.adoc#DynamicThresholdFilter[`DynamicThresholdFilter`] +* xref:manual/filters.adoc#LevelRangeFilter[`LevelRangeFilter`] (garbage-free since `2.8`) +* xref:manual/filters.adoc#MapFilter[`MapFilter`] (garbage-free since `2.8`) +* xref:manual/filters.adoc#MarkerFilter[`MarkerFilter`] (garbage-free since `2.8`) +* xref:manual/filters.adoc#StructuredDataFilter[`StructuredDataFilter`] (garbage-free since `2.8`) +* xref:manual/filters.adoc#ThreadContextMapFilter[`ThreadContextMapFilter]` (garbage-free since `2.8`) +* xref:manual/filters.adoc#ThresholdFilter[`ThresholdFilter`] (garbage-free since `2.8`) +* xref:manual/filters.adoc#TimeFilter[`TimeFilter`] (garbage-free since `2.8` except when range must be recalculated once per day) -|%m, %msg, %message -|Log message (garbage-free unless message text -contains '${') +Any other filter not shared in the above list is not garbage-free. -|%marker -|The full name of the marker (including parents) - garbage-free -since 2.8 +[#core-limitations] +=== Limitations -|%markerSimpleName -|The simple name of the marker (not including -parents) +There are certain caveats associated with the configuration of garbage-free logging: -|%maxLen, %maxLength -|Truncates another pattern to some max number of -characters - garbage-free since 2.8 +[#core-limitation-properties] +`<Properties>` section:: -|%n -|The platform dependent line separator +A configuration containing xref:manual/configuration.adoc#PropertySubstitution[a `<Properties>` section] will result in temporary objects being created during steady-state logging. -|%N, %nano -|System.nanoTime() when the event was logged +[#core-limitation-async-logger-wait-strategy] +Asynchronous logger wait strategies:: -|%notEmpty\{pattern}, %varsNotEmpty\{pattern}, -%variablesNotEmpty\{pattern} -|Outputs the result of evaluating the -pattern if and only if all variables in the pattern are not empty - -garbage-free since 2.8 +As of version `2.18.0`, the default xref:manual/async.adoc[asynchronous logger] wait strategy (i.e., `Timeout`) is garbage-free while running against both LMAX Disruptor 3 and 4. +See xref:manual/async.adoc#log4j2.asyncLoggerWaitStrategy[`log4j2.asyncLoggerWaitStrategy`] for details on predefined wait strategies. -|%p, %level -|The level of the logging event +[#api] +== Log4j API configuration and usage -|%r, %relative -|The number of milliseconds elapsed since the JVM was -started until the creation of the logging event - garbage-free since 2.8 +In order to have a garbage-free Log4j API, you need to -|%sn, %sequenceNumber -|A sequence number that will be incremented in -every event - garbage-free since 2.8 +* xref:#api-config[configure it using properties], +* and xref:#api-usage[use garbage-free API methods]. -|%style\{pattern}{ANSI style} -|Style the message - garbage-free since -2.7 (unless nested pattern is not garbage free) +[#api-config] +=== Configuration -|%T, %tid, %threadId -|The ID of the thread that generated the logging -event +Garbage-free logging can be configured for Log4j API using properties listed below. +(See xref:manual/configuration.adoc[] on details how you can set these properties.) -|%t, %tn, %thread, %threadName -|The name of the thread that generated -the logging event +include::partial$properties-garbage-collection.adoc[leveloffset=+2,tag=api] -|%tp -|The priority of the thread that generated the logging event +include::partial$properties-thread-context.adoc[leveloffset=+2,tag=gcfree] -|%X{key[,key2...]}, %mdc{key[,key2...]}, %MDC{key[,key2...]} -|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 - -|literal text -|Garbage-free unless literal contains '${' (variable -substitution) -|=== - -Other PatternLayout conversion patterns, and other Layouts may be -updated to avoid creating temporary objects in future releases. (Patches -welcome!) - -NOTE: 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. - -**** -NOTE: patterns containing regular expressions and lookups for property -substitution will result in temporary objects being created during -steady-state logging. - -Including location information is done by walking the stacktrace of an -exception, which creates temporary objects, so the following patterns -are not garbage-free: - -* %C, %class - Class Name -* %F, %file - File Location -* %l, %location - Location -* %L, %line - Line Location -* %M, %method - Method Location - -Also, the pattern converters for formatting Throwables are not -garbage-free: - -* %ex, %exception, %throwable - The Throwable trace bound to the -LoggingEvent -* %rEx, %rException %rThrowable - Same as %ex but with wrapping -exceptions -* %xEx, %xException, %xThrowable - Same as %ex but with class packaging -information -* %u, %uuid - Creates a new random or time-based UUID while formatting - -**** +[#api-usage] +=== Usage -[#api] -=== API Changes +xref:manual/api.adoc[Log4j API] contains several features to facilitate garbage-free logging: -Methods have been added to the `Logger` interface so that no vararg -array objects are created when logging messages with up to ten -parameters. +[#api-vararg] +==== Parameterized message arguments -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. +The `Logger` interface contains methods for parameterized messages up to 10 arguments. +Logging more than 10 parameters creates https://docs.oracle.com/javase/8/docs/technotes/guides/language/varargs.html[vararg arrays]. -An alternative is to implement the -http://logging.apache.org/log4j/2.x/log4j-api/xref/org/apache/logging/log4j/util/StringBuilderFormattable.html[`org.apache.logging.log4j.util.StringBuilderFormattable`] -interface. If an object is logged that implements this interface, its -`formatTo` method is called instead of `toString()`. +[#api-encode-custom-object] +==== Encoding custom objects -Log4j may call toString() on message and parameter objects when garbage-free logging is disabled (when system property log4j2.enableThreadlocals is set to "false".) +When a message parameter contains an unknown type by the layout, it will encode by calling `toString()` on these objects. +Most objects don't have garbage-free `toString()` methods. +Objects themselves can implement their own garbage-free encoders by either extending from https://docs.oracle.com/javase/8/docs/api/java/lang/CharSequence.html[Java's `CharSequence`] or link:../javadoc/log4j-api/org/apache/logging/log4j/util/StringBuilderFormattable.html[Log4j's `StringBuilderFormattable`]. [#codeImpact] -=== Impact on Application Code: Autoboxing - -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. +==== Avoiding autoboxing -Log4j provides an `Unbox` utility to prevent autoboxing of primitive -parameters. This utility contains a thread-local pool of reused -`StringBuilder`s. 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. +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. +https://docs.oracle.com/javase/tutorial/java/data/autoboxing.html[When logging primitive values (i.e., `int`, `double`, `boolean`, etc.) the JVM autoboxes these primitive values to their `Object` wrapper equivalents, creating garbage.] +Log4j provides an `Unbox` utility to prevent autoboxing of primitive parameters: [source,java] ---- import static org.apache.logging.log4j.util.Unbox.box; -// ... -public void garbageFree() { - logger.debug("Prevent primitive autoboxing {} {}", box(10L), box(2.6d)); -} +LOGGER.debug("Prevent primitive autoboxing {} {}", box(10L), box(2.6d)); ---- -**** -NOTE: not all logging is garbage free. Specifically: - -* 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". -* The ThreadContext stack is not garbage-free. -* Logging more than 10 parameters creates vararg arrays. -* Logging very large messages (more than 518 characters) when all -loggers are Async Loggers will cause the internal StringBuilder in the -RingBuffer to be trimmed back to their max size. -* Logging messages containing '${': substituting a `$\{variable}` creates -temporary objects. -* Logging a lambda _as a parameter_ -(`logger.info("lambda value is {}", () -> callExpensiveMethod())`) -creates a vararg array. Logging a lambda expression by itself is -garbage-free: `logger.debug(() -> callExpensiveMethod())`. -* The `Logger.traceEntry` and `Logger.traceExit` methods create -temporary objects. -* Time calculations are not garbage free when log4j2.usePreciseClock is set to true. -The default is false. -**** - -[#UnderTheHood] -== Under the Hood - -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. - -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. - -Custom Appenders that want to be garbage-free should provide their -Layout with a `ByteBufferDestination` implementation that the Layout can -directly write into. - -`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. +This utility contains a `ThreadLocal` pool of reused ``StringBuilder``s. +The pool size is configured by xref:#log4j2.unboxRingbufferSize[the `log4j2.unboxRingbufferSize` system property]. +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. -//// -TODO Applications that wish to reuse custom Message instances with Async Loggers should let -their Message classes implement the `org.apache.logging.log4j.message.ReusableMessage` interface. -TODO This is not sufficient: see LOG4J2-1342, would be nice if we could solve this in a generic way. -//// +[#api-limitations] +=== Limitations + +Not all Log4j API feature set is garbage-free, specifically: + +* The `ThreadContext` map (aka. MDC) is not garbage-free by default, but can be configured to be garbage-free by setting xref:#log4j2.garbagefreeThreadContextMap[the `log4j2.garbagefreeThreadContextMap` system property] to `true`. +* The `ThreadContext` stack is not garbage-free. +* Logging very large messages (i.e., more than xref:#log4j2.maxReusableMsgSize[`log4j2.maxReusableMsgSize`] characters, which defaults to 518), when all loggers are xref:manual/async.adoc[asynchronous loggers], will cause the internal `StringBuilder` in the +`RingBuffer` to be trimmed back to their configured maximum size. +* Logging messages containing `$\{variable}` substitutions creates temporary objects. +* Logging a lambda as a parameter: ++ +[source,java] +---- +LOGGER.info("lambda value is {}", () -> callExpensiveMethod()); +---- ++ +creates a vararg array. +Logging a lambda expression by itself: ++ +[source,java] +---- +LOGGER.debug(() -> callExpensiveMethod()); +---- ++ +is garbage-free. +* The link:../javadoc/log4j-api/org/apache/logging/log4j/Logger.html#traceEntry()[`traceEntry()`] and link:../javadoc/log4j-api/org/apache/logging/log4j/Logger.html#traceExit()[`traceExit()`] methods create temporary objects. +* Time calculations are not garbage-free when the `log4j2.usePreciseClock` system property (defaults to `false`) is set to `true`. diff --git a/src/site/antora/modules/ROOT/pages/manual/layouts.adoc b/src/site/antora/modules/ROOT/pages/manual/layouts.adoc index 07730ad70a..3a24bfb703 100644 --- a/src/site/antora/modules/ROOT/pages/manual/layouts.adoc +++ b/src/site/antora/modules/ROOT/pages/manual/layouts.adoc @@ -165,9 +165,14 @@ required for using CSV layouts. [#GELFLayout] == GELF Layout -Lays out events in the Graylog Extended Log Format (GELF) 1.1. +Encodes log events the https://go2docs.graylog.org/current/getting_in_log_data/gelf.html#GELFPayloadSpecification[the GELF specification] version `1.1`. +Compresses JSON to GZIP or ZLIB (`compressionType`) if log event data is larger than 1024 bytes (`compressionThreshold`). +This layout does not implement chunking. -This layout compresses JSON to GZIP or ZLIB (`compressionType`) if log event data is larger than 1024 bytes (`compressionThreshold`). This layout does not implement chunking. +[TIP] +==== +Unless compression is needed, we advise you to use xref:manual/json-template-layout.adoc[JSON Template Layout] instead, which provides GELF layout support out of the box and offers a far richer set of features. +==== Configure as follows to send to a Graylog 2.x server with UDP: @@ -225,10 +230,7 @@ To include any custom field in the output, use following syntax: Custom fields are included in the order they are declared. The values support xref:manual/lookups.adoc[lookups]. -See also: - -* The https://docs.graylog.org/en/latest/pages/gelf.html#gelf[GELF specification] - +GELF Layout is garbage-free when used with `compressionType="OFF"` and as long as no additional field contains `${` (variable substitution). [#HTMLLayout] == HTML Layout @@ -1788,6 +1790,188 @@ should be used. </PatternLayout> ---- +[#PatternLayout-gcfree] +=== Garbage-free configuration + +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. + +[cols="1m,2"] +|=== +|Conversion Pattern |Description + +|%c\{precision}, %logger\{precision} +|Logger name + +|%d, %date +a| +Note: Only the predefined date formats are garbage-free: (millisecond +separator may be either a comma ',' or a period '.') + +[cols="1m,1"] +!=== +!Pattern !Example + +!%d\{DEFAULT} +!2012-11-02 14:34:02,781 + +!%d\{ISO8601} +!2012-11-02T14:34:02,781 + +!%d\{ISO8601_BASIC} +!20121102T143402,781 + +!%d\{ABSOLUTE} +!14:34:02,781 + +!%d\{DATE} +!02 Nov 2012 14:34:02,781 + +!%d\{COMPACT} +!20121102143402781 + +!%d{HH:mm:ss,SSS} +!14:34:02,781 + +!%d{dd MMM yyyy HH:mm:ss,SSS} +!02 Nov 2012 14:34:02,781 + +!%d{HH:mm:ss}{GMT+0} +!18:34:02 + +!%d\{UNIX} +!1351866842 + +!%d\{UNIX_MILLIS} +!1351866842781 +!=== + +|%enc\{pattern}, %encode\{pattern} +|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 + +|%equals\{pattern}\{test}\{substitution}, +%equalsIgnoreCase\{pattern}\{test}\{substitution} +|Replaces occurrences +of 'test', a string, with its replacement 'substitution' in the string +resulting from evaluation of the pattern - garbage-free since 2.8 + +|%highlight\{pattern}\{style} +|Adds ANSI colors - garbage-free since 2.7 +(unless nested pattern is not garbage free) + +|%K\{key}, %map\{key}, %MAP\{key} +|Outputs the entries in a +link:../javadoc/log4j-api/org/apache/logging/log4j/message/MapMessage.html[MapMessage], +if one is present in the event - garbage-free since 2.8. + +|%m, %msg, %message +|Log message (garbage-free unless message text +contains '${') + +|%marker +|The full name of the marker (including parents) - garbage-free +since 2.8 + +|%markerSimpleName +|The simple name of the marker (not including +parents) + +|%maxLen, %maxLength +|Truncates another pattern to some max number of +characters - garbage-free since 2.8 + +|%n +|The platform dependent line separator + +|%N, %nano +|System.nanoTime() when the event was logged + +|%notEmpty\{pattern}, %varsNotEmpty\{pattern}, +%variablesNotEmpty\{pattern} +|Outputs the result of evaluating the +pattern if and only if all variables in the pattern are not empty - +garbage-free since 2.8 + +|%p, %level +|The level of the logging event + +|%r, %relative +|The number of milliseconds elapsed since the JVM was +started until the creation of the logging event - garbage-free since 2.8 + +|%sn, %sequenceNumber +|A sequence number that will be incremented in +every event - garbage-free since 2.8 + +|%style\{pattern}{ANSI style} +|Style the message - garbage-free since +2.7 (unless nested pattern is not garbage free) + +|%T, %tid, %threadId +|The ID of the thread that generated the logging +event + +|%t, %tn, %thread, %threadName +|The name of the thread that generated +the logging event + +|%tp +|The priority of the thread that generated the logging event + +|%X{key[,key2...]}, %mdc{key[,key2...]}, %MDC{key[,key2...]} +|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 + +|literal text +|Garbage-free unless literal contains '${' (variable +substitution) +|=== + +Other PatternLayout conversion patterns, and other Layouts may be +updated to avoid creating temporary objects in future releases. (Patches +welcome!) + +NOTE: 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. + +[NOTE] +==== +patterns containing regular expressions and lookups for property +substitution will result in temporary objects being created during +steady-state logging. + +Including location information is done by walking the stacktrace of an +exception, which creates temporary objects, so the following patterns +are not garbage-free: + +* %C, %class - Class Name +* %F, %file - File Location +* %l, %location - Location +* %L, %line - Line Location +* %M, %method - Method Location + +Also, the pattern converters for formatting Throwables are not +garbage-free: + +* %ex, %exception, %throwable - The Throwable trace bound to the +LoggingEvent +* %rEx, %rException %rThrowable - Same as %ex but with wrapping +exceptions +* %xEx, %xException, %xThrowable - Same as %ex but with class packaging +information +* %u, %uuid - Creates a new random or time-based UUID while formatting +==== + [#RFC5424Layout] == RFC5424 Layout diff --git a/src/site/antora/modules/ROOT/pages/manual/performance.adoc b/src/site/antora/modules/ROOT/pages/manual/performance.adoc index b655f230b4..cced659d63 100644 --- a/src/site/antora/modules/ROOT/pages/manual/performance.adoc +++ b/src/site/antora/modules/ROOT/pages/manual/performance.adoc @@ -105,13 +105,7 @@ While this would work for cases where the message can be dropped due to insuffic Below sections walk you through a set of features that can have significant impact on the performance of Log4j Core. -[IMPORTANT] -==== -Extra tuning of any application will deviate you away from defaults and add up to the maintenance load. -You are strongly advised to measure your application's overall performance and then, if Log4j is found to be an important bottleneck factor, tune it carefully. -When this happens, we also recommend you to evaluate your assumptions on a regular basis to check if they still hold. -Remember, https://en.wikipedia.org/wiki/Program_optimization#When_to_optimize[premature optimization is the root of all evil]. -==== +include::partial$premature-optimization.adoc[] [TIP] ==== diff --git a/src/site/antora/modules/ROOT/partials/premature-optimization.adoc b/src/site/antora/modules/ROOT/partials/premature-optimization.adoc new file mode 100644 index 0000000000..f48573a3ec --- /dev/null +++ b/src/site/antora/modules/ROOT/partials/premature-optimization.adoc @@ -0,0 +1,24 @@ +//// + Licensed to the Apache Software Foundation (ASF) under one or more + contributor license agreements. See the NOTICE file distributed with + this work for additional information regarding copyright ownership. + The ASF licenses this file to You under the Apache License, Version 2.0 + (the "License"); you may not use this file except in compliance with + the License. You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +//// + +[IMPORTANT] +==== +Extra tuning of any application will deviate you away from defaults and add up to the maintenance load. +You are strongly advised to measure your application's overall performance and then, if Log4j is found to be an important bottleneck factor, tune it carefully. +When this happens, we also recommend you to evaluate your assumptions on a regular basis to check if they still hold. +Remember, https://en.wikipedia.org/wiki/Program_optimization#When_to_optimize[premature optimization is the root of all evil]. +==== diff --git a/src/site/antora/modules/ROOT/partials/properties-async-logger.adoc b/src/site/antora/modules/ROOT/partials/properties-async-logger.adoc index c42deebc48..3907722a49 100644 --- a/src/site/antora/modules/ROOT/partials/properties-async-logger.adoc +++ b/src/site/antora/modules/ROOT/partials/properties-async-logger.adoc @@ -64,17 +64,21 @@ The value needs to be a fully qualified class name of a custom `WaitStrategy` im Block:: a strategy that uses a lock and condition variable for the I/O thread waiting for log events. Block can be used when throughput and low-latency are not as important as CPU resource. -Recommended for resource constrained/virtualised environments. +Recommended for resource constrained/virtualized environments. +This wait strategy is not xref:manual/garbagefree.adoc[garbage free]. Timeout:: a variation of the `Block` strategy that will periodically wake up from the lock condition `await()` call. -This ensures that if a notification is missed somehow the consumer thread is not stuck but will recover with a small latency delay (see <<log4j2.asyncLoggerTimeout>>) +This ensures that if a notification is missed somehow the consumer thread is not stuck but will recover with a small latency delay, see <<log4j2.asyncLoggerTimeout>>. +This wait strategy is xref:manual/garbagefree.adoc[garbage free]. Sleep:: a strategy that initially spins, then uses a `Thread.yield()`, and eventually parks for the minimum number of nanos the OS and JVM will allow while the I/O thread is waiting for log events (see <<log4j2.asyncLoggerRetries>> and <<log4j2.asyncLoggerSleepTimeNs>>). Sleep is a good compromise between performance and CPU resource. This strategy has very low impact on the application thread, in exchange for some additional latency for actually getting the message logged. +This wait strategy is xref:manual/garbagefree.adoc[garbage free]. Yield:: is a strategy that uses a `Thread.yield()` for waiting for log events after an initially spinning. Yield is a good compromise between performance and CPU resource, but may use more CPU than `Sleep` in order to get the message logged to disk sooner. +This wait strategy is xref:manual/garbagefree.adoc[garbage free]. [id=log4j2.asyncLoggerTimeout] == `log4j2.asyncLoggerTimeout` diff --git a/src/site/antora/modules/ROOT/partials/properties-garbage-collection.adoc b/src/site/antora/modules/ROOT/partials/properties-garbage-collection.adoc index eab7578a32..9b0765e653 100644 --- a/src/site/antora/modules/ROOT/partials/properties-garbage-collection.adoc +++ b/src/site/antora/modules/ROOT/partials/properties-garbage-collection.adoc @@ -56,6 +56,8 @@ The size in ``char``s of the link:../https://docs.oracle.com/javase/8/docs/api/j This setting is only used if <<log4j2.enableDirectEncoders>> is set to `true`. +// tag::api[] + [id=log4j2.initialReusableMsgSize] == `log4j2.initialReusableMsgSize` @@ -81,7 +83,9 @@ In GC-free mode, this property determines the initial size of the reusable ``Str In GC-free mode, this property determines the maximum size of the reusable ``StringBuilder``s used by link:../javadoc/log4j-api/org/apache/logging/log4j/message/ReusableMessage[ReusableMessages] for formatting purposes. The default value allows is equal to `2 × (2 × log4j.initialReusableMsgSize + 2) + 2` and allows the -``StringBuilder`` to be resized twice by the current JVM resize algorithm. +`StringBuilder` to be resized twice by the current JVM resize algorithm. + +// end::api[] [id=log4j2.layoutStringBuilderMaxSize] == `log4j2.layoutStringBuilderMaxSize` @@ -95,6 +99,8 @@ The default value allows is equal to `2 × (2 × log4j.initialReusable This property determines the maximum size of the reusable ``StringBuilder``s used to format link:../javadoc/log4j-core/org/apache/logging/log4j/core/LogEvent[LogEvents]. +// tag::api[] + [id=log4j2.unboxRingbufferSize] == `log4j2.unboxRingbufferSize` @@ -107,4 +113,6 @@ This property determines the maximum size of the reusable ``StringBuilder``s use The link:../javadoc/log4j-api/org/apache/logging/log4j/util/Unbox[Unbox] utility class can be used by users to format primitive values without incurring in the boxing allocation cost. -This property specifies the maximum number of primitive arguments to a log message that will be cached and usually does not need to be changed. \ No newline at end of file +This property specifies the maximum number of primitive arguments to a log message that will be cached and usually does not need to be changed. + +// end::api[] diff --git a/src/site/antora/modules/ROOT/partials/properties-meta.adoc b/src/site/antora/modules/ROOT/partials/properties-meta.adoc index 22d0659418..088ed5d351 100644 --- a/src/site/antora/modules/ROOT/partials/properties-meta.adoc +++ b/src/site/antora/modules/ROOT/partials/properties-meta.adoc @@ -48,4 +48,5 @@ Setting this property to `true` switches Log4j Core into "garbage-free mode" (_" In this mode Log4j uses ``ThreadLocal``s for object pooling to prevent object allocations. -This mode is incompatible with <<log4j2.isWebapp>>. \ No newline at end of file +https://docs.oracle.com/en/java/javase/{java-target-version}/docs/api/java.base/java/lang/ThreadLocal.html[`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. +Hence, to avoid causing memory leaks, `log4j2.enableThreadlocals` by default reflects the opposite of xref:#log4j2.isWebapp[`log4j2.isWebapp`]. diff --git a/src/site/antora/modules/ROOT/partials/properties-thread-context.adoc b/src/site/antora/modules/ROOT/partials/properties-thread-context.adoc index 8ae3dfbfd3..a3936eb2e4 100644 --- a/src/site/antora/modules/ROOT/partials/properties-thread-context.adoc +++ b/src/site/antora/modules/ROOT/partials/properties-thread-context.adoc @@ -50,6 +50,8 @@ If `true`, the `ThreadContext` stack is disabled. If `true`, the `ThreadContext` map is disabled. +// tag::gcfree[] + [id=log4j2.threadContextMap] == `log4j2.threadContextMap` @@ -69,6 +71,8 @@ WebApp:: a web application-safe implementation, that only binds JRE classes to ` CopyOnWrite:: a copy-on-write implementation, GarbageFree:: a garbage-free implementation. +// end::gcfree[] + [id=isThreadContextMapInheritable] == `log4j2.isThreadContextMapInheritable` @@ -81,6 +85,8 @@ GarbageFree:: a garbage-free implementation. If `true` uses an `InheritableThreadLocal` to copy the thread context map to newly created threads. +// tag::gcfree[] + [id=log4j2.garbagefreeThreadContextMap] == `log4j2.garbagefreeThreadContextMap` @@ -90,4 +96,6 @@ If `true` uses an `InheritableThreadLocal` to copy the thread context map to new | Default value | `false` |=== -If set to `true` selects a garbage-free thread context map implementation. \ No newline at end of file +If set to `true` selects a garbage-free thread context map implementation. + +// end::gcfree[]