bigywater.tech
Spring · 187

Logback AsyncAppender 默认只写下 2% 的 INFO 日志:异步日志的耗时与丢失率实测,以及 Log4j2 配 Disruptor 4.0.0 丢行

Logback 的 AsyncAppender 为什么这么快?异步日志会丢日志吗?Log4j2 的 AsyncAppender 和全异步各是什么表现?这篇用磁盘文件做满负载实测,并数文件行数验证有没有丢。

1.9%
Logback AsyncAppender 默认配置下,1 个线程满速打日志,文件里只有 1.9% 的行(第 2 轮 2.1%),耗时 63 ns
discardingThreshold = 0
关掉丢弃之后耗时回到 3226 ns,写入率 100.0%,和同步在同一量级
6.6%
Log4j2 全异步配 Disruptor 4.0.0、4 个线程各 200 万条时,文件只有 531631 行(6.6%);换 3.4.4 是 100.0%

1 个线程

实测 · 本机执行输出 
  Logback 同步 FileAppender:第 1 轮 5354 ± 3694 ns,写入率 100.0%(1834162 / 1834162);第 2 轮 5866 ± 10503 ns,写入率 100.0%(1386293 / 1386293)
  Logback AsyncAppender(默认:队列 256、discardingThreshold 默认):第 1 轮 63 ± 35 ns,写入率 1.9%(2612341 / 134908735);第 2 轮 192 ± 489 ns,写入率 2.1%(883032 / 42460683)
  Logback AsyncAppender(discardingThreshold = 0):第 1 轮 3226 ± 973 ns,写入率 100.0%(2610420 / 2610420);第 2 轮 11975 ± 15438 ns,写入率 100.0%(808587 / 808587)
  Log4j2 同步 FileAppender:第 1 轮 3184 ± 1694 ns,写入率 100.0%(2514349 / 2514349);第 2 轮 5927 ± 6584 ns,写入率 100.0%(1506339 / 1506339)
  Log4j2 AsyncAppender(bufferSize = 256):第 1 轮 4900 ± 5506 ns,写入率 100.0%(1885693 / 1885693);第 2 轮 6640 ± 9777 ns,写入率 100.0%(1419108 / 1419108)
  Log4j2 全异步 AsyncLogger(Disruptor):第 1 轮 3534 ± 1349 ns,写入率 100.0%(2452842 / 2452842);第 2 轮 3796 ± 1091 ns,写入率 100.0%(2081018 / 2081018)

Logback 异步默认快是因为丢了大部分 INFO。

4 个线程

实测 · 本机执行输出 
  Logback 同步 FileAppender:第 1 轮 20980 ± 8953 ns,写入率 100.0%(1544063 / 1544063);第 2 轮 21470 ± 4802 ns,写入率 100.0%(1538740 / 1538740)
  Logback AsyncAppender(默认:队列 256、discardingThreshold 默认):第 1 轮 476 ± 167 ns,写入率 3.2%(2158739 / 67655273);第 2 轮 453 ± 99 ns,写入率 2.8%(1969601 / 69934872)
  Logback AsyncAppender(discardingThreshold = 0):第 1 轮 14033 ± 8963 ns,写入率 100.0%(2446391 / 2446391);第 2 轮 15210 ± 13708 ns,写入率 100.0%(2260459 / 2260459)
  Log4j2 同步 FileAppender:第 1 轮 19112 ± 10201 ns,写入率 100.0%(1731821 / 1731821);第 2 轮 24941 ± 15075 ns,写入率 100.0%(1343939 / 1343939)
  Log4j2 AsyncAppender(bufferSize = 256):第 1 轮 20740 ± 6764 ns,写入率 100.0%(1645957 / 1645957);第 2 轮 24859 ± 9029 ns,写入率 100.0%(1396555 / 1396555)
  Log4j2 全异步 AsyncLogger(Disruptor):第 1 轮 17140 ± 9314 ns,写入率 100.0%(2077804 / 2077804);第 2 轮 17506 ± 18612 ns,写入率 100.0%(2102648 / 2102648)

不丢的几种都被磁盘速度卡住。

Disruptor 版本

实测 · 本机执行输出 
  Disruptor 3.4.4:4 个线程各 2000000 次,共调用 8000000 次,文件里 8000000 行,写入率 100.0%
  Disruptor 4.0.0:4 个线程各 2000000 次,共调用 8000000 次,文件里 531631 行,写入率 6.6%

4.0.0 配 Log4j 2.25.5 多线程丢行,3.4.4 不丢。

分步演示

AsyncLog
本步的对象

    本文用到的工具与边界

    • 本机 macOS 27 arm64 / OpenJDK 21.0.12(Homebrew) / Spring Boot 4.0.8(Spring Framework 7.0.9、Tomcat 11.0.24) / Spring Cloud 2025.1.3;用 javac 编译、java 直接运行,依赖由 Maven 从 Maven Central 解析;数字每次运行会有小幅抖动(Logback 1.5.38,Log4j2 2.25.5,SLF4J 2.0.18,Disruptor 3.4.4 与 4.0.0;JMH 1.37 avgt,3 次预热加 5 次测量各 1 秒,1 个 fork,整套基准跑两轮,分别 1 个线程与 4 个线程;日志写到本机磁盘的临时文件,日志格式含时间、级别、线程名、日志器名;测完关闭日志系统后数文件行数,与基准里的调用计数对比;这轮测量时机器上的磁盘负载有波动,两轮之间的耗时相差较大,误差范围也不小)
    • 没有验证:日志产生速度低于磁盘速度时(更接近线上)各方案的耗时;immediateFlush 关闭或使用 BufferedIO 的同步写入;Logback AsyncAppender 的 queueSize 增大后的丢失率;neverBlock 的取舍;Log4j2 AsyncLogger 在 Disruptor 4.0.0 下多线程丢行的原因(这里是 Log4j2 还是 Disruptor 的问题);Boot 里用 starter-log4j2 配置异步的写法;GC 压力与内存占用;日志落到 Kafka 或网络 appender 时的表现
    京ICP备2026067502号-1京公网安备11010502063487号