基准测试

性能对不同的人来说可能意味着不同的东西。在此上下文中常见的术语是吞吐量和延迟：吞吐量是容量的衡量标准，可以用单个数字表示：在一定时间内可以记录多少条消息。响应时间延迟是记录一条消息需要多长时间。这不能用单个数字表示，因为每次测量都有自己的响应时间，而我们通常最感兴趣的是异常值：有多少个异常值以及它们有多大。

在评估日志框架的性能时，以下问题可能会有所帮助

• 它的峰值吞吐量是多少？许多对外部事件做出反应的系统需要记录消息突发，然后是相对安静的时期。这个数字是在短时间内测量的最大吞吐量，它可以提供一些关于日志库如何处理突发的线索。对于需要以恒定的高速率记录大量数据的系统（例如批处理作业），这不太可能成为性能的有用衡量指标。
• 最大持续吞吐量是多少？这是长时间内平均的吞吐量。这是日志库“上限”容量的有用衡量指标。不建议响应式应用程序实际以这种速率记录日志，因为在这种负载下，它们可能会遇到抖动和较大的响应时间峰值。

• 它在各种负载下的响应时间行为如何？对于需要及时响应外部事件的应用程序来说，这是最重要的一个问题。响应时间是记录一条消息所需的总时间，是服务时间和等待时间的总和。服务时间是完成记录消息所需的工作的时间。随着工作负载的增加，服务时间通常变化不大：完成 X 量的工作总是需要 X 量的时间。等待时间是请求在被服务之前必须在队列中等待多长时间。随着工作负载的增加，等待时间通常会增长到服务时间的很多倍。

旁栏：为什么要关心响应时间延迟？ 通常测量和报告为延迟的实际上是服务时间，并且省略了服务时间峰值会为许多后续事件增加等待时间。这可能会呈现出比用户体验更乐观的結果。 右侧的图表说明了服务时间比响应时间乐观多少。该图表显示了相同系统在 100,000 条消息/秒的负载下的响应时间和服务时间。在 2400 万次测量中，只有大约 50 次超过 250 微秒，不到 0.001%。在仅服务时间的图表中，这几乎不可见。但是，根据负载的不同，在峰值之后需要一段时间才能赶上。 响应时间图表显示，实际上，比仅服务时间数字所暗示的更多事件受到这些延迟的影响。 要了解更多信息，请观看 Gil Tene 的开眼界演讲 如何不测量延迟。

异步日志 - 峰值吞吐量比较

异步日志记录对于处理事件突发非常有用。它的工作原理是，应用程序线程完成最少的工作量来捕获日志事件中所有必需的信息，然后将此日志事件放入队列中，以便稍后由后台线程处理。只要队列大小足够大，应用程序线程应该能够在日志记录调用上花费很少的时间，并能非常快地返回到业务逻辑。

事实证明，队列的选择对于峰值吞吐量至关重要。Log4j 2 的异步记录器使用 无锁数据结构，而 Logback、Log4j 1.2 和 Log4j 2 的异步附加器使用 ArrayBlockingQueue。对于阻塞队列，多线程应用程序在尝试入队日志事件时经常会遇到锁争用。

下面的图表说明了无锁数据结构对多线程场景中的吞吐量的影响。Log4j 2 在线程数量方面具有更好的可扩展性：具有更多线程的应用程序可以记录更多数据。其他日志库会遇到锁争用，并且总吞吐量在更多线程记录日志时保持不变或下降。这意味着对于其他日志库，每个单独的线程能够记录的数据更少。

请记住，这是峰值吞吐量：Log4j 2 的异步记录器在一定程度上提供了更好的吞吐量，但一旦队列已满，附加器线程就需要等待直到队列中出现可用插槽，并且吞吐量最多会下降到底层附加器的最大持续吞吐量。

有关详细信息，请参阅 异步记录器 手册页面。

异步日志响应时间

响应时间行为随工作负载和同时记录日志的线程数量的变化很大。 异步记录器 手册页面和 无垃圾日志记录 手册页面提供了一些图表，显示了在各种负载下的响应时间行为。

本节显示了另一个图表，显示了在 64,000 条消息/秒的适度总工作负载下，4 个线程同时记录日志时的响应时间延迟行为。在此负载和此硬件/操作系统/JVM 配置下，锁争用和上下文切换的作用较小，暂停主要是由次要垃圾回收引起的。垃圾回收暂停持续时间和频率可能会有很大差异：在测试 Log4j 1.2.17 异步附加器时，发生了 7 毫秒的次要 GC 暂停，而 Log4j 2 异步附加器测试只看到了略高于 2 毫秒的 GC 暂停。这并不一定意味着一个比另一个更好。

通常，在所有我们测试的配置中，无垃圾异步记录器具有最佳的响应时间行为。

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

异步日志参数化消息

许多日志库提供了一个用于记录参数化消息的 API。这使得应用程序代码看起来像这样

logger.debug("Entry number: {} is {}", i, entry[i]);

if (logger.isDebugEnabled()) {
    logger.debug("Entry number: " + i + " is " + entry[i].toString());
}

如果确实启用了 DEBUG 级别，那么在某个时候需要格式化消息。在异步记录日志时，应用程序线程可能会在后台线程有机会记录日志之前更改消息参数。这将在日志文件中显示错误的值。为了防止这种情况，Log4j 2、Log4j 1.2 和 Logback 在将日志事件传递给后台线程之前在应用程序线程中格式化消息文本。

这样做是安全的，但格式化会带来性能成本。下面的图表比较了使用各种日志库记录带参数的消息的吞吐量。这些都是异步日志调用，因此这些数字不包括磁盘 I/O 的成本，并代表了*峰值*吞吐量。

JUL (java.util.logging) 没有内置的异步 Handler。 MemoryHandler 是最接近的可用选项，因此我们将其包含在内。MemoryHandler *不会*执行对当前参数状态进行快照的安全操作（它只是保留对原始参数对象的引用），因此在单线程情况下速度非常快。但是，当更多应用程序线程同时记录时，锁争用的成本超过了这种收益。

从绝对数字来看，*Log4j 2 的异步记录器与其他日志框架相比表现良好，但请注意，消息格式化成本随着参数数量的增加而急剧增加。在这一领域，Log4j 2 还有待改进：我们希望将此成本保持得更加稳定。*

以上结果适用于 JUL (java.util.logging) 1.8.0_45、Log4j 2.6、Log4j 1.2.17 和 Logback 1.1.7，并使用 JMH Java 基准测试工具获得。请参阅 log4j-perf 模块中的 AsyncAppenderLog4j1Benchmark、AsyncAppenderLog4j2Benchmark、AsyncAppenderLogbackBenchmark、AsyncLoggersBenchmark 和 MemoryHandlerJULBenchmark 源代码。

带有调用者位置信息的异步日志记录

某些布局可以显示应用程序中进行日志记录调用的类、方法和行号。在 Log4j 2 中，此类布局选项的示例包括 HTML locationInfo，或模式之一 %C 或 $class、%F 或 %file、%l 或 %location、%L 或 %line、%M 或 %method。为了提供调用者位置信息，日志库将对堆栈进行快照，并遍历堆栈跟踪以查找位置信息。

下面的图表显示了从单个线程异步记录时捕获调用者位置信息对性能的影响。我们的测试表明，*捕获调用者位置对所有日志库的影响相似，并且会使异步日志记录速度降低约 30-100 倍*。

以上结果适用于 JUL (java.util.logging) 1.8.0_45、Log4j 2.6、Log4j 1.2.17 和 Logback 1.1.7，并使用 JMH Java 基准测试工具获得。请参阅 log4j-perf 模块中的 AsyncAppenderLog4j1LocationBenchmark、AsyncAppenderLog4j2LocationBenchmark、AsyncAppenderLogbackLocationBenchmark、AsyncLoggersLocationBenchmark 和 MemoryHandlerJULLocationBenchmark 源代码。

同步文件日志记录 - 持续吞吐量比较

本节讨论了将日志记录到文件的最大持续吞吐量。在任何系统中，最大持续吞吐量都由其最慢的组件决定。在日志记录的情况下，这是追加器，消息格式化和磁盘 I/O 在这里进行。因此，我们将查看对文件的简单*同步*日志记录，不使用队列或后台线程。

下面的图表将 Log4j 2.6 的 RandomAccessFile 追加器与 Log4j 1.2.17、Logback 1.1.7 和 Java 实用程序日志记录 (JUL) 在 Oracle Java 1.8.0_45 上的相应 File 追加器进行比较。ImmediateFlush 设置为 false，适用于支持此功能的所有记录器。JUL 结果适用于 XMLFormatter（在我们的测量中，它的速度大约是 SimpleFormatter 的两倍）。

当更多线程同时记录时，Log4j 2 的持续吞吐量会略有下降，但其细粒度锁定发挥了作用，吞吐量保持相对较高。其他日志框架的吞吐量在多线程应用程序中急剧下降：Log4j 1.2 的吞吐量是其单线程容量的 1/4，Logback 的吞吐量是其单线程容量的 1/10，而 JUL 的吞吐量随着线程数量的增加而稳定下降，从其单线程吞吐量的 1/4 降至 1/10。

以上同步日志记录吞吐量结果使用 JMH Java 基准测试工具获得。请参阅 log4j-perf 模块中的 FileAppenderBenchmark 源代码。

同步文件日志记录 - 响应时间比较

同步文件日志记录的响应时间随工作负载和线程数量的变化很大。以下是一个示例，工作负载为每秒 32,000 个事件，两个线程分别记录每秒 16,000 个事件。

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

按级别过滤

日志框架提供的最基本的过滤是按日志级别过滤。当完全关闭日志记录或仅针对一组级别关闭日志记录时，日志请求的成本包括多个方法调用加上一个整数比较。与 Log4j 不同，Log4j 2 记录器不会“遍历层次结构”。记录器直接指向最匹配记录器名称的记录器配置。这会在记录器首次创建时产生额外的开销，但会减少每次使用记录器时的开销。

高级过滤

Logback 和 Log4j 2 都支持高级过滤。Logback 将其称为 TurboFilters，而 Log4j 2 只有一个 Filter 对象。高级过滤提供了使用除级别之外的其他方法在事件传递到追加器之前过滤 LogEvents 的功能。但是，这种灵活性确实会带来一些成本。由于多线程也会影响高级过滤的性能，因此下面的图表显示了基于标记或标记的父级进行过滤的性能差异。

“简单标记”比较检查没有对其他标记的引用的标记是否与请求的标记匹配。“父标记”比较检查是否有对其他标记的引用的标记是否与请求的标记匹配。

似乎 SLF4J 中的粗粒度同步会影响多线程场景中的性能。请参阅 SLF4J-240。

Log4j 和 Logback 还支持对 Log4j ThreadContext 中的值进行过滤，而 Logback 支持对 MDC 中的值进行过滤。下面的图表显示了 Log4j 2 和 Logback 之间的性能差异对于 ThreadContext 过滤器来说很小。

以上过滤器比较结果使用 JMH Java 基准测试工具获得。请参阅 log4j-perf 模块中的 MarkerFilterBenchmark 和 MDCFilterBenchmark，了解有关这些基准测试的详细信息。

使用哪个 Log4j 2 追加器？

假设您选择 Log4j 2 作为您的日志框架，接下来您可能想知道选择特定 Log4j 2 配置的性能权衡是什么。例如，有三种追加器用于将日志记录到文件：File、RandomAccessFile 和 MemoryMappedFile 追加器。您应该使用哪一个？

如果您只关心性能，下面的图表显示了您的最佳选择是 MemoryMappedFile 追加器或 RandomAccessFile 追加器。需要注意一些事项

• MemoryMappedFile 追加器目前还没有滚动变体。
• 当日志文件大小超过 MemoryMappedFile 的区域长度时，需要重新映射文件。这可能是一个非常昂贵的操作，如果区域很大，可能需要几秒钟。
• MemoryMappedFile 追加器从一开始就创建一个预先指定大小的文件，并逐渐填充它。这可能会使像 tail 这样的工具感到困惑；许多此类工具在处理内存映射文件时效果不佳。
• 在 Windows 上，使用像 tail 这样的工具在由 RandomAccessFile 追加器创建的文件上可能会对该文件保持锁定，这可能会阻止 Log4j 在应用程序重新启动时再次打开该文件。在开发环境中，您希望在使用像 tail 这样的工具查看日志文件内容时定期重新启动应用程序，File 追加器可能是性能和灵活性之间合理的权衡。对于生产环境，性能可能具有更高的优先级。

下面的图表显示了 Log4j 2.6 中的控制台和文件追加器的持续吞吐量，并作为参考还提供了 2.5 的性能。

事实证明，2.6 中的无垃圾文本编码逻辑使这些追加器与 Log4j 2.5 相比获得了性能提升。过去，RandomAccessFile 追加器明显更快，尤其是在多线程场景中，但随着 2.6 版本的发布，File 追加器的性能有所提高，这两个追加器之间的性能差异变小了。

另一个结论是，将日志记录到控制台会带来多少性能拖累。考虑将日志记录到文件，并使用像 tail 这样的工具实时观察文件的变化。

在 Windows 上，结果类似，但 RandomAccessFile 和 MemoryMappedFile 追加器在多线程场景中优于普通的 File 追加器。Windows 上的绝对数字更高：我们不知道原因，但看起来 Windows 处理锁争用的能力比 Linux 好。

以上 Log4j 2 追加器比较结果使用 JMH Java 基准测试工具获得。请参阅 log4j-perf 模块中的 Log4j2AppenderComparisonBenchmark 源代码。