无垃圾稳态记录

垃圾收集暂停是造成延迟尖峰的常见原因，并且对于许多系统而言，要花费大量精力来控制这些暂停。

许多日志记录库(包括 Log4j 的早期版本)在稳态日志记录期间分配临时对象，例如日志事件对象，字符串，char 数组，字节数组等。这会增加垃圾收集器的压力，并增加发生 GC 暂停的频率。

从 2.6 版开始，Log4j 默认情况下以“无垃圾”模式运行，其中对象和缓冲区被重用，并且没有分配尽可能多的临时对象。还有一个“低垃圾”模式，该模式不是完全没有垃圾，但是不使用 ThreadLocal 字段。当 Log4j detects在 Web 应用程序中运行时，这是默认模式。最后，可以关闭所有无垃圾逻辑并改为在“经典模式”下运行。有关详细信息，请参见下面的Configuration部分。

人为的例子

为了强调无垃圾记录可以带来的不同，我们使用 Java Flight Recorder 来测量一个简单的应用程序，该应用程序只会在大约 12 秒的时间内记录一次简单的字符串，什么也不做。

该应用程序配置为使用异步 Logger，RandomAccessFile 附加程序和“％d％p％c{1.} [％t]％m％ex％n”模式布局。 (异步 Logger 使用了 Yield WaitStrategy.)

任务控制显示，使用 Log4j 2.5，此应用程序以大约 809 MB /秒的速度分配内存，从而产生了 141 个次要集合。 Log4j 2.6 在此配置中不会分配临时对象，因此，具有 Log4j 2.6 的同一应用程序的内存分配速率为 1.6 MB /秒，并且不带垃圾回收(零(零个))。

使用 Log4j 2.5：内存分配速率 809 MB /秒，141 个次要集合。	Log4j 2.6 没有分配临时对象：0(零)垃圾回收。

Configuration

Log4j 2.6 中的无垃圾日志记录部分通过重用 ThreadLocal 字段中的对象来实现，部分通过在将文本转换为字节时重用缓冲区来实现。

当取消部署 Web 应用程序之后，应用程序服务器的线程池 continue 引用这些字段时，包含非 JDK 类的 ThreadLocal 字段可能会导致 Web 应用程序中的内存泄漏。为了避免引起内存泄漏，当 Log4j 检测到已在 Web 应用程序中使用它时(当 javax.servlet.Servlet 类在 Classpath 中，或者系统属性 log4j2.isWebapp 设置为“ true”时，它将不使用这些 ThreadLocals)。 )。

某些减少垃圾的功能不依赖 ThreadLocals，而是默认情况下为所有应用程序启用：在 Log4j 2.6 中，可以通过将文本直接编码为重用的 ByteBuffer 而不创建中间字符串，char 数组来将日志事件转换为文本和将文本转换为字节。和字节数组。因此，尽管日志记录对于 Web 应用程序而言还不是完全没有垃圾的，但仍然可以显着减轻垃圾收集器的压力。

注 1： 从 2.6 版开始，包含\ 部分的 Log4j 配置将导致在稳态日志记录期间创建临时对象。
注 2： 异步 Logger 超时 await 策略(默认设置)和阻止 await 策略会导致创建 java.util.concurrent.locks.AbstractQueuedSynchronizer $ Node 对象。Yield 和睡眠 await 策略是无垃圾的。 (请参见here和here。)

禁用无垃圾记录

有两个单独的系统属性，用于手动控制 Log4j 避免创建临时对象的机制：

• log4j2.enableThreadlocals-如果将“ true”(非 Web 应用程序的默认值)对象存储在 ThreadLocal 字段中并重新使用，否则为每个日志事件创建新的对象。

• log4j2.enableDirectEncoders-如果将“ true”(默认)日志事件转换为文本，并且将此文本转换为字节，而不创建临时对象。注意：由于共享缓冲区上的同步，在这种模式下，多线程应用程序的同步日志记录性能可能会更差。如果您的应用程序是多线程的并且日志记录的性能很重要，请考虑使用异步日志 Logger。

• ThreadContextMap 默认情况下不是无垃圾的，但是从 Log4j 2.7 起，可以通过将系统属性 log4j2.garbagefreeThreadContextMap 设置为“ true”，将其配置为无垃圾。

除了系统属性，还可以通过在名为 log4j2.component.properties 的文件中指定上述属性，方法是将该文件包含在应用程序的 Classpath 中。有关更多信息，请参见有关系统属性的手册。

Supported Appenders

以下appenders在稳态日志记录期间是无垃圾的：

• Console

• File

• RollingFile(一些临时对象在文件过渡期间创建)

• RandomAccessFile

• RollingRandomAccessFile(一些临时对象是在文件过渡期间创建的)

• MemoryMappedFile

不在上面列表中的任何其他附加程序(包括 AsyncAppender)在稳态日志记录期间创建临时对象。代替 AsyncAppender，使用Async Loggers以无垃圾方式异步登录。

Supported Filters

以下filters在稳态日志记录期间是无垃圾的：

• CompositeFilter(添加和删除元素过滤器会创建临时对象以确保线程安全)

• DynamicThresholdFilter

• LevelRangeFilter(从 2.8 开始免费垃圾)

• MapFilter(从 2.8 开始免费使用垃圾)

• MarkerFilter(从 2.8 开始免费垃圾)

• StructuredDataFilter(从 2.8 开始免费使用垃圾)

• ThreadContextMapFilter(从 2.8 开始免费垃圾)

• ThresholdFilter(从 2.8 开始免费使用垃圾)

• TimeFilter(从 2.8 开始免费，除非必须每天重新计算一次范围)

其他过滤器(例如 BurstFilter，RegexFilter 和 ScriptFilter)对于释放垃圾来说并非易事，目前还没有计划对其进行更改。

Supported Layouts

GelfLayout

当与 compressionType =“ OFF”一起使用时，GelfLayout 是无垃圾的，只要没有其他字段包含'$ {'(变量替换)即可。

PatternLayout

具有以下有限转换模式集的 PatternLayout 是无垃圾的。用于控制字段宽度，填充，左右对齐的格式修饰符不会产生垃圾。

Conversion Pattern	Description
%c{precision}, %logger{precision}	Logger name
%d, %date	注意：只有 sched 义的日期格式是无垃圾的：(毫秒分隔符可以是逗号“或”或句点“.”)
	图案例子	％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}	2012 年 11 月 2 日 14：34：02,781		％d{COMPACT}	20121102143402781		％d{HH:mm:ss,SSS}	14：34：02,781		％d{dd MMM yyyy HH:mm:ss,SSS}	2012 年 11 月 2 日 14：34：02,781		％d{HH:mm:ss}{GMT+0}	18:34:02		％d{UNIX}	1351866842		％d{UNIX_MILLIS}	1351866842781
％enc{pattern}，％encode{pattern}	对特殊字符(例如' n'和 HTML 字符)进行编码，以帮助防止伪造日志以及在 Web 浏览器中显示日志时可能发生的某些 XSS 攻击-自 2.8 起无垃圾！
％equals{pattern}{test}{substitution}，％equalsIgnoreCase{pattern}{test}{substitution}	替换字符串“ test”的出现，并替换由模式评估产生的字符串中的“ substitution”-自 2.8 开始，无垃圾
％highlight{pattern}{style}	添加 ANSI 颜色-从 2.7 开始是无垃圾的(除非嵌套模式不是无垃圾的)
	K{key}，map{key}，MAP{key}	如果事件中存在一个，则输出MapMessage中的条目-从 2.8 开始是无垃圾的。
％m，％msg，％message	日志消息(除非消息文本包含“ $ {”，否则是免费的)
％marker	标记的全名(包括父代)-自 2.8 起无垃圾
％markerSimpleName	标记的简单名称(不包括 parent)
％maxLen，％maxLength	将另一个模式截断为某些最大字符数-自 2.8 起无垃圾
％n	平台相关的行分隔符
％N，％nano	System.nanoTime()在记录事件时
％notEmpty{pattern}，％varsNotEmpty{pattern}，％variablesNotEmpty{pattern}	仅当模式中的所有变量都不为空时才输出评估模式的结果-自 2.8 起无垃圾
％p，％level	记录事件的级别
％r，％relative	从启动 JVM 到创建日志记录事件为止所经过的毫秒数-自 2.8 开始无垃圾
％sn，％sequenceNumber	在每个事件中都会递增的序列号-自 2.8 起无垃圾
％style{pattern}{ANSI style}	设置消息的样式-自 2.7 起无垃圾(除非嵌套模式不是无垃圾的)
％T，％tid，％threadId	生成日志事件的线程的 ID
％t，％tn，％thread，％threadName	生成日志事件的线程的名称
％tp	生成日志事件的线程的优先级
％X{key[,key2...]}，％mdc{key[,key2...]}，％MDC{key[,key2...]}	输出与生成日志事件的线程相关联的线程上下文 Map(也称为 Map 诊断上下文或 MDC)-自 2.8 起无垃圾！
Literals 文本	无垃圾，除非 Literals 包含“ $ {”(变量替换)

其他 PatternLayout 转换模式和其他 Layout 可能会更新，以避免在以后的版本中创建临时对象。 (欢迎补丁！)

注意：记录异常和堆栈跟踪将创建具有任何布局的临时对象。 (但是，布局仅在实际发生异常时才创建这些临时对象.)我们还没有找到一种在不创建临时对象的情况下记录异常和堆栈跟踪的方法。不幸的是，但是您可能仍希望在它们发生时对其进行记录。

注意： 包含正则表达式和用于属性替换的查找的模式将导致在稳态记录期间创建临时对象。
包含位置信息是通过遍历异常的 stacktrace 来完成的，该异常会创建临时对象，因此以下模式不是无垃圾的： ％C，％class-类名 ％F，％file-文件位置 ％l，％location-位置 ％L，％line-行位置 ％M，％method-方法位置 同样，用于格式化 Throwables 的模式转换器也不是没有垃圾的： ％ex，％exception，％throwable-绑定到 LoggingEvent 的 Throwable 跟踪 ％rEx，％rException％rThrowable-与％ex 相同，但有包装异常 ％xEx，％xException，％xThrowable-与％ex 相同，但具有类包装信息 ％u，％uuid-在格式化	时创建新的随机或基于时间的 UUID

API Changes

已将方法添加到 Logger 界面，以便在记录带有最多十个参数的消息时不会创建 vararg 数组对象。

另外，已将方法添加到 Logger 接口以记录 java.lang.CharSequence 消息。可以记录实现 CharSequence 接口的用户定义对象，而无需创建临时对象：Log4j 将尝试通过将 CharSequence 消息，Object 消息和消息参数作为 CharSequence 附加到 StringBuilder 来将其转换为文本。这样可以避免在这些对象上调用 toString()。

另一种方法是实现org.apache.logging.log4j.util.StringBuilderFormattable接口。如果记录了实现此接口的对象，则将调用其 formatTo 方法而不是 toString()。

禁用无垃圾日志记录时(系统属性 log4j2.enableThreadlocals 设置为“ false”时，Log4j 可以在消息和参数对象上调用 toString()。)

对应用程序代码的影响：自动装箱

我们努力在不更改现有应用程序代码的情况下实现了无日志记录的垃圾记录，但是在某些领域这是不可能的。当记录原始值(即 int，double，boolean 等)时，JVM 将这些原始值自动装箱到其对象包装器等效项中，从而产生垃圾。

Log4j 提供了 UnboxUtil，以防止原始参数自动装箱。该 Util 包含一个线程本地的重用 StringBuilders 池。 Unbox.box(primitive)方法直接写入 StringBuilder，结果文本将被复制到最终的日志消息文本中，而无需创建临时对象。

import static org.apache.logging.log4j.util.Unbox.box;

...
public void garbageFree() {
    logger.debug("Prevent primitive autoboxing {} {}", box(10L), box(2.6d));
}

注意： 并非所有日志记录都是无垃圾的。特别：

ThreadContextMap 默认情况下不是无垃圾的，但是可以通过将系统属性 log4j2.garbagefreeThreadContextMap 设置为“ true”来配置为无垃圾。
ThreadContext 堆栈不是没有垃圾的。
记录 10 个以上的参数将创建 vararg 数组。
当所有 Logger 均为异步 Logger 时，记录非常大的消息(超过 518 个字符)将导致 RingBuffer 中的内部 StringBuilder 被调整为最大大小。
记录包含'${': substituting a ${}的消息会创建临时对象。
记录一个 lambda 作为参数(logger.info(“ lambda 值为 {}”，()-> callExpensiveMethod()))将创建一个 vararg 数组。本身记录 lambda 表达式是无垃圾的：logger.debug(()-> callExpensiveMethod())。
Logger.traceEntry 和 Logger.traceExit 方法创建临时对象。

Performance

响应时间延迟

响应时间是在一定负载下记录消息所花费的时间。通常被称为延迟的实际上是服务时间：执行操作所花费的时间。这掩盖了一个事实，即服务时间的一个高峰会增加许多后续操作的排队延迟。服务时间很容易衡量(并且通常看起来很不错)，但对用户而言却无关紧要，因为它省去了 await 服务的时间。因此，我们报告响应时间：服务时间加 await 时间。有关更多详细信息，请参见性能页面的响应时间部分。

下面的响应时间测试结果全部来自运行 ResponseTimeTest 类，可以在 Log4j 2 单元测试源目录中找到该类。如果您想自己运行这些测试，请使用以下命令行选项：

• -Xms1G -Xmx1G(防止在测试期间调整堆大小)

• -DLog4jContextSelector = org.apache.logging.log4j.core.async.AsyncLoggerContextSelector -DAsyncLogger.WaitStrategy = busyspin(使用异步 Logger.BusySpinawait 策略可减少一些抖动.)

• 经典模式： -Dlog4j2.enable.threadlocals = false -Dlog4j2.enable.direct.encoders = false
  无垃圾模式： -Dlog4j2.enable.threadlocals = true -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(用于监视 GC 和安全点暂停)

Async Loggers

下图将 Log4j 的异步 Logger 的“经典”记录与无垃圾记录响应时间行为进行了比较。在图中，“ 100k”表示以 100,000 消息/秒的持续负载进行记录，“ 800k”表示 800,000 消息/秒的持续负载。

在“经典”模式下，我们看到大量次要垃圾回收，这些垃圾回收会使应用程序线程暂停 3 毫秒或更长时间。这很快就增加了将近 10 毫秒的响应时间延迟。如您在图表中所见，增加负载将曲线向左移动(存在更多尖峰)。这是有道理的：更多的日志记录意味着对垃圾收集器施加更大的压力，从而导致更小的 GC 暂停。我们做了一些实验，将负载减少到 50,000 甚至 5000 条消息/秒，但这并没有消除 3 毫秒的暂停，只是使它们的发生频率降低了。请注意，此测试中的所有 GC 暂停都是次要的 GC 暂停。我们没有看到任何完整的垃圾回收。

在“无垃圾”模式下，在各种负载下，最大响应时间仍远低于 1 毫秒。 (最大 780 us，800,000 消息/秒，最大 407 us，600,000 消息/秒，其中 99％围绕 5 us 达到 800,000 消息/秒的所有负载.)增加或减少负载不会改变响应时间。我们没有调查在这些测试中看到的 200-300 微秒暂停的原因。

当我们进一步增加负载时，我们开始看到经典和无垃圾记录的响应时间都有较大的暂停。在 100 万条消息/秒或更多的持续负载下，我们开始接近底层 RandomAccessFile Appender 的最大吞吐量(请参见下面的同步日志记录吞吐量图表)。在这些负载下，环形缓冲区开始填满，反压开始起作用：在环形缓冲区已满时尝试添加另一条消息将阻塞，直到有可用插槽可用为止。我们开始看到响应时间为数十毫秒或更长；尝试进一步增加负载会导致越来越大的响应时间峰值。

同步文件记录

使用同步文件日志记录，无垃圾记录日志仍然比传统日志记录更好，但是区别不那么明显。

在 10 万条消息/秒的工作量下，传统日志记录的最大响应时间略超过 2 毫秒，而无垃圾日志记录的响应时间则超过 1 毫秒。当工作负载增加到 300,000 条消息/秒时，经典日志记录显示响应时间暂停为 6 毫秒，而无垃圾响应时间少于 3 毫秒。有可能对此进行改进，我们尚未进一步调查。

以上结果是使用 ResponseTimeTest 类获得的，该类可以在 Log4j 2 单元测试源目录中找到，该目录在具有 10 核 Xeon 的 RHEL 6.5(Linux 2.6.32-573.1.1.el6.x86_64)上的 JDK 1.8.0_45 上运行 CPU E5-2660 v3 @ 2.60GHz，超线程已打开(20 个虚拟内核)。

经典日志记录的吞吐量略高

与传统日志记录相比，无垃圾日志记录的吞吐量稍差一些。对于同步和异步日志记录都是如此。下图比较了使用无垃圾模式，经典模式和 Log4j 2.5 的 Log4j 2.6 将同步日志记录与文件的持续吞吐量。

以上结果是使用JMH Java 基准测试工具获得的。请参阅 log4j-perf 模块中的 FileAppenderBenchmark 源代码。

Under The Hood

实现 org.apache.logging.log4j.util.StringBuilderFormattable 的自定义消息实现可以通过无垃圾的 Layouts 转换为文本，而无需创建临时对象。 PatternLayout 使用此机制，其他将 LogEvents 转换为文本的布局也可能会寻找此接口。

希望无垃圾的自定义布局应实现 Encoder<LogEvent>接口。对于将 LogEvent 转换为文本表示形式的自定义布局，org.apache.logging.log4j.core.layout.StringBuilderEncoder 类对于以无垃圾方式将此文本转换为字节可能有用。

希望无垃圾的自定义 Appender 应该为其布局提供 ByteBufferDestination 实现，该布局可以直接写入其中。

已对 AbstractOutputStreamAppender 进行修改，以使 ConsoleAppender，(Rolling)FileAppender，(Rolling)RandomAccessFileAppender 和 MemoryMappedFileAppender 无垃圾。已尽力将对扩展 AbstractOutputStreamAppender 的自定义 Appender 的影响减至最小，但无法保证更改超类不会影响任何子类和所有子类。扩展 AbstractOutputStreamAppender 的自定义 Appender 应该验证它们是否仍然正常运行。如果出现问题，可以将系统属性 log4j2.enable.direct.encoders 设置为“ false”，以恢复到 Log4j 2.6 之前的性能。