异步日志记录——峰值吞吐量比较
异步日志记录对于处理突发事件非常有用。它的工作原理是,应用程序线程在一个日志事件中捕获所有需要的信息,然后将这个日志事件放在一个队列中,以便稍后处理后台线程。只要队列大小足够大,应用程序线程就应该能够在日志调用上花费很少的时间,并且非常快地返回到业务逻辑。
事实证明,队列的选择对于峰值吞吐量非常重要。Log4j 2的异步记录器使用了一个无锁定的数据结构,而Logback、Log4j 1.2和Log4j 2的异步应用程序使用了一个ArrayBlockingQueue。有了阻塞队列,多线程应用程序在尝试对日志事件进行排队时通常会遇到锁争用。
下面的图表说明了在多线程场景中,无锁数据结构对吞吐量的影响。Log4j 2随着线程数量的增加而变得更好:一个拥有更多线程的应用程序可以进行更多的日志记录。其他的日志记录库受到锁争用的影响,当更多的线程被记录时,总吞吐量保持不变或下降。这意味着,在其他日志库中,每个单独的线程都可以减少日志记录。
记住这是峰值吞吐量:Log4j 2的异步Loggers提供更好的吞吐量在一定程度上,但是一旦队列已满,appender线程需要等到一个槽可用的队列,而吞吐量将降到最优的潜在应用程序的最大持续吞吐量。
异步日志记录响应时间
响应时间的行为与工作负载和并发日志的线程数量有很大的不同。异步日志记录器手册页和垃圾日志记录手册页提供了一些图表,显示了在各种负载下的响应时间行为。
本节展示另一个图,显示响应时间延迟的行为,在适当的总工作负载下,每秒64,000条消息,同时有4个线程并发地记录。在这个负载和这个hardware/os/jvm配置中,锁争用和上下文切换的作用更小,而暂停主要是由小的垃圾收集引起的。垃圾收集暂停的时间和频率会有很大的变化:当测试Log4j 1.2.17时,Async Appender的一个小GC暂停7毫秒,而Log4j 2的异步应用程序测试只看到了一个略超过2毫秒的GC暂停。这并不一定意味着一个人比另一个人好。
一般来说,没有垃圾的异步日志记录器在我们测试的所有配置中都具有最佳的响应时间行为。
上面的结果是在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.60 GHz和超线程切换(20个虚拟内核)。
异步日志参数化信息
许多日志库提供了用于记录参数化消息的API。这使应用程序代码看起来像这样:
logger.debug("Entry number: {} is {}", i, entry[i]);
在上面的示例中,除非为logger启用了调试级别,否则不会创建完全格式化的消息文本。如果没有这个API,您将需要三行代码来完成相同的工作:
if (logger.isDebugEnabled()) {
logger.debug("Entry number: " + i + " is " + entry[i].toString());
}
如果启用了调试级别,那么在某个时候需要对消息进行格式化。在异步进行日志记录时,在后台线程有机会记录消息之前,应用程序线程可能会更改消息参数。这会在日志文件中显示错误的值。为了防止这一点,Log4j 2、Log4j 1.2和Logback在应用程序线程中格式化了消息文本,然后将日志事件传递给后台线程。
这是安全的事情,但是格式化有一个性能代价。下图将日志消息的吞吐量与使用各种日志库的参数进行了比较。这些都是异步的日志记录调用,因此这些数字不包括磁盘输入/输出的成本,并且表示峰值吞吐量。
JUL(java.util.logging)没有内置的异步处理程序。MemoryHandler是最接近的东西,所以我们把它包含在这里。MemoryHandler不安全的获取当前参数状态的快照(它只保留对原始参数对象的引用),因此,当单线程时,它非常快。但是,当更多的应用程序线程并发地进行日志记录时,锁争用的成本就会超过这个收益。
在绝对数量上,Log4j 2的异步日志记录器与其他日志框架相比性能良好,但是注意到消息格式成本随着参数的数量而急剧增加。在这个领域,Log4j 2仍然有工作要做:我们希望保持这个成本更稳定。
上面的结果是JUL(Java.util.log)1.8.0 45、Log4j 2.6、Log4j 1.2.17和Logback 1.1.7,并使用JMH Java基准测试工具获得。看到AsyncAppenderLog4j1Benchmark AsyncAppenderLog4j2Benchmark、AsyncAppenderLogbackBenchmark AsyncLoggersBenchmark和MemoryHandlerJULBenchmark log4j-perf模块的源代码。
与调用方位置信息的异步日志记录
一些布局可以显示应用程序的类、方法和行号。在Log4j 2中,此类布局选项的示例是HTML locationInfo,或其中一个模式%C或$class、%F或%file、%l或%location、%l或%line、%M或%method。为了提供调用者位置信息,日志库将获取堆栈的快照,并遍历堆栈跟踪以查找位置信息。
下面的图表显示了在从单个线程异步记录日志时捕获调用者位置信息的性能影响。我们的测试表明,捕获调用者的位置在所有日志库中都有类似的影响,并使异步日志记录的速度降低了大约30-100x。
上面的结果是JUL(Java.util.log)1.8.0 45、Log4j 2.6、Log4j 1.2.17和Logback 1.1.7,并使用JMH Java基准测试工具获得。看到AsyncAppenderLog4j1LocationBenchmark AsyncAppenderLog4j2LocationBenchmark、AsyncAppenderLogbackLocationBenchmark AsyncLoggersLocationBenchmark和MemoryHandlerJULLocationBenchmark log4j-perf模块的源代码。
同步文件日志记录——持续的吞吐量比较
本节讨论日志记录到文件的最大持续吞吐量。在任何系统中,最大的持续吞吐量由其最慢的组件决定。在日志记录中,这是appender,其中消息格式化和磁盘输入输出发生了。出于这个原因,我们将查看简单的同步日志记录到一个文件,没有队列或后台线程。
下面的图表将Log4j 2.6的随机访问文件appender与Log4j 1.2.17、Logback 1.1.7和Java util(JUL)在Oracle Java 1.8.0 45上的文件appender进行了比较。对于支持这一点的所有日志记录器,立即刷新被设置为false。JUL结果用于XMLFormatter(在我们的测量中,它的速度是SimpleFormatter的两倍)。
当更多的线程同时进行日志记录时,Log4j 2的持续吞吐量降低了一点,但是它的细粒度锁定获得了回报,吞吐量相对较高。其他日志框架的吞吐量在多线程应用程序中急剧下降:Log4j 1.2拥有单线程容量的1/4,Logback的单线程容量是1/10,并且随着更多线程的增加,JUL的单线程吞吐量也从1/4下降到1/10。
通过JMH Java基准测试,可以获得上面的同步日志吞吐量。请参阅log4j-perf模块中的fileappender基准源代码。
同步文件日志-响应时间比较
同步文件日志记录的响应时间与工作负载和线程数量有很大的不同。下面是每秒3.2万个事件的示例,其中2个线程每秒记录1.6万个事件。
上面的结果是在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.60 GHz和超线程切换(20个虚拟内核)。
过滤的水平
日志框架提供的最基本的过滤是通过日志级别进行过滤。当日志被完全关闭或仅用于一组级别时,日志请求的成本由许多方法调用和一个整数比较组成。与Log4j不同的是,Log4j 2记录器不“走一个层次结构”。日志记录器直接指向日志记录器的配置,它最好匹配日志记录器的名称。当记录器第一次创建时,这会带来额外的开销,但是每次使用日志记录器时都会减少开销。
高级过滤
Logback和Log4j 2都支持高级过滤。Logback称其为涡轮过滤器,而Log4j 2则有一个单一的过滤器对象。高级过滤提供了对日志事件进行过滤的功能,而不仅仅是将事件传递给Appenders之前的级别。然而,这种灵活性确实需要付出一定的代价。由于多线程还可能对高级过滤的性能产生影响,下面的图表显示了基于标记或标记的父类进行过滤的性能差异。
“简单的标记”比较检查是否有一个没有引用其他标记的标记与所请求的标记相匹配。“父标记”比较检查是否有引用其他标记的标记与所请求的标记匹配。
在SLF4J中,粗粒度的同步可能会影响多线程场景中的性能。看到slf4j - 240。
Log4j和Logback还支持在Log4j ThreadContext中对一个值进行过滤,而对MDC的一个值进行过滤。下面的图表显示了Log4j 2和Logback之间的性能差异对于ThreadContext过滤器来说是很小的。
上面的过滤比较结果是用JMH Java基准测试工具获得的。有关这些基准的详细信息,请参阅log4j-perf模块中的markerfilter基准和mdcfilter基准。
权衡
哪个Log4j 2 Appender使用?
假设您选择Log4j 2作为您的日志框架,那么接下来您可能会对选择特定的Log4j 2配置的性能权衡感兴趣。例如,有三个用于记录文件的应用程序:File、RandomAccessFile 和MemoryMappedFile appenders。你应该用哪一个?
如果性能是您所关心的,下面的图表显示了您最好的选择,要么是MemoryMappedFile appender,要么是RandomAccessFile appender。有些事情要记住:
MemoryMappedFile appender还没有一个滚动的变体。
当日志文件的大小超过了MemoryMappedFile的区域长度时,需要重新对该文件进行重新处理。这可能是一项非常昂贵的操作,如果该区域很大的话,需要几秒钟的时间。
MemoryMappedFile appender从一开始就创建一个主文件,并逐渐填充它。这可能会混淆像tail这样的工具;许多这样的工具不能很好地处理内存映射文件。
在Windows上,使用RandomAccessFile appender创建的文件这样的工具,可以在这个文件上持有一个锁,这可以防止Log4j在重新启动应用程序时再次打开文件。在开发环境中,您希望定期重新启动应用程序,同时使用tail等工具来查看日志文件内容,在性能和灵活性之间,File appender可能是一个合理的权衡。对于生产环境,性能可能具有更高的优先级。
下面的图表显示了Log4j 2.6中console和file appenders的持续吞吐量,参考也提供了2.5的性能。
事实证明,2.6版本的无垃圾文本编码逻辑与Log4j 2.5相比,使这些应用程序性能得到了提升。过去,RandomAccessFile appender的速度要快得多,特别是在多线程场景中,但是随着2.6版本的发布,File appender的性能得到了改善,这两个应用程序之间的性能差异也更小了。
另一个要点是,将日志记录拖到控制台上的性能有多少。考虑将日志记录到一个文件中,并使用像tail这样的工具实时监视文件的更改。
在Windows上,结果是类似的,但RandomAccessFile和MemoryMappedFile appenders应用程序在多线程场景中比普通文件appender更好。Windows的绝对数字更高:我们不知道为什么,但看起来Windows处理锁争用比Linux更好。
上面的Log4j 2 appender比较结果是用JMH Java基准测试工具获得的。看到log4j-perf Log4j2AppenderComparisonBenchmark源代码模块。
参考: Performance