Skip to content

出事的那几秒,日志恰好是空的 ​

服务重启了一次。想从日志里找重启前发生了什么,却发现重启前的最后一段日志是空白。另一次故障里,ERROR 日志都在,但前后的 INFO 上下文全没有,只知道哪个请求失败了,不知道它之前走到了哪一步。

为了不让写日志拖慢业务线程,日志通常配成异步的:业务线程把日志事件放进内存里的队列就返回,由后台线程写到磁盘或发到收集端。队列是有限的,后台线程写得再快也有跟不上的时候,进程也总有退出的一刻。这三处都会丢日志,而且默认配置下丢的时候不报错、不计数。

本文用 Logback 1.5.38 的 AsyncAppender 把每一处跑出来。实验见文末。

业务线程log.info(…)前 206 条各级别都收后 50 条只收 WARN 以上AsyncAppender 的队列:256 条后台线程守护线程下游文件 / 网络1剩余容量低于 51:INFO 及以下直接丢弃。记了 1001 条,写出 207 条2队列满:WARN、ERROR 的调用阻塞,业务线程 300 ms 内没有返回设成 neverBlock = true 则不阻塞,改为丢弃:50 条 ERROR 全部没有写出3关闭日志系统:只等 maxFlushTime(默认 1 秒)。3000 条里写出 504 条4main 返回或 System.exit:后台线程是守护线程,200 条里写出 0 条四处都不抛异常、不打印任何提示。下游越慢(磁盘满、日志收集端卡住),丢得越多,而那正是最需要日志的时候默认还不记录调用位置:下游拿到的类名、方法名、行号是问号
图 1 · 实测(Logback 1.5.38 的 AsyncAppender 默认配置):业务线程把日志放进一个 256 条的队列就返回,由一个后台线程写到下游。下游变慢时队列堆积:剩余容量低于 51 条后,INFO 及以下级别被直接丢弃,不报错;队列满后 WARN 与 ERROR 会让业务线程等在这里。关闭时后台线程只有 1 秒时间写完剩下的;进程直接退出时一条也不写。

一、默认配置 ​

text
队列长度 256,丢弃阈值 51(剩余容量低于它时丢弃 INFO 及以下),neverBlock = false,关闭时最多等 1000 ms,记录调用位置 = false

五个默认值,后面每一节对应一个。

实验里 AsyncAppender 的下游是一个可以被卡住、也可以设定每条耗时的 appender,代替变慢的磁盘或网络。

二、队列快满时:INFO 被悄悄丢掉 ​

让下游卡住,然后连续记 1001 条 INFO:

text
下游卡住期间记了 1001 条 INFO,全部立即返回;此时队列里有 206 条,剩余容量 50

业务线程没有受任何影响,每次调用都立即返回。但队列里只有 206 条:剩余容量低于 51 之后,AsyncAppender 把 TRACE、DEBUG、INFO 级别的事件直接丢弃,不进队列。下游恢复后实际写出的:

text
下游恢复并正常关闭后,实际写出的:INFO 207,WARN 50,ERROR 1(记了 INFO 1001、WARN 50、ERROR 1)

1001 条 INFO 写出了 207 条,其余 794 条没有留下任何痕迹。

这是一个有意的设计:队列的最后五分之一留给 WARN 和 ERROR,保证重要的日志有位置。代价就是开头的第二个现象。下游一慢,INFO 最先消失,而排查问题需要的上下文(请求参数、走了哪个分支、调了哪个下游)大多是 INFO。

把 discardingThreshold 设成 0 可以关掉这个行为,所有级别一视同仁:

text
discardingThreshold = 0,下游卡住期间记满队列后再记一条 INFO:业务线程 300 ms 内返回 = false;实际写出 INFO 258,WARN 0,ERROR 0

一条都没有丢,但队列满了之后 INFO 也会让业务线程等。这引出下一节。

三、队列满时:等,还是丢 ​

队列满了之后来了一条 ERROR:

text
再记 50 条 WARN(不在丢弃之列):队列里 256 条,剩余容量 0
队列满了之后再记一条 ERROR:业务线程 300 ms 内返回 = false

默认 neverBlock = false:队列满时,记日志的调用会阻塞,直到队列腾出位置。这时「异步」已经名存实亡,业务线程的速度被下游写日志的速度卡住。日志收集端不可用、磁盘写满、日志所在的网络盘抖动,都会通过这条路径让业务请求一起卡住;从线程转储里看到的是大量线程停在日志调用上。

另一个选择是 neverBlock = true:

text
neverBlock = true,下游卡住期间记 300 条 WARN 再记 50 条 ERROR:业务线程立即返回 = true;实际写出 INFO 1,WARN 256,ERROR 0

业务线程不再被阻塞,代价是队列满之后所有级别都丢:50 条 ERROR 一条都没有写出。

两个选项是在「日志可能拖住业务」和「日志可能丢」之间选一个,没有两全的配置:

  • 多数在线服务选不阻塞。日志丢失可以接受,业务线程因为日志卡死不能接受。
  • 审计、交易流水这类不能丢的记录,不应该走日志这条通道,而应该作为业务数据写进数据库或消息队列,并对失败做处理。

不论选哪个,队列长度 256 对有一定流量的服务都偏小,可以调大;同时需要一个能看到的信号:丢了多少。Logback 的 AsyncAppender 不提供丢弃计数,可以定期采集队列的剩余容量(getRemainingCapacity())作为指标,长期贴近 0 就说明下游跟不上。

四、关闭时:只等一秒 ​

text
队列里有 3000 条、下游每条 2 ms(写完要 6 秒)时关闭日志系统:stop() 在 0.9–1.5 秒内返回 = true,此时写出的不到一半 = true

实验的那一次,stop() 用了 1004 毫秒返回,这时 3000 条里写出了 504 条。关闭时后台线程最多有 maxFlushTime(默认 1000 毫秒)来写完队列里剩下的,时间到了就放弃。

text
maxFlushTime = 0(一直等到写完),500 条:写出 500

设成 0 表示一直等到写完。它会延长进程退出的时间,需要与容器的优雅退出时限一起考虑:Kubernetes 默认在 30 秒后强制结束进程,日志写不完同样会丢。

五、进程退出时:一条也不等 ​

后台线程是守护线程,不会阻止 JVM 退出。记 200 条日志(下游每条 5 毫秒)之后,用三种方式结束进程:

结束方式写出的条数
main 方法直接返回0
调用 System.exit(0)0
退出前先调用 LoggerContext.stop()(maxFlushTime = 0)200

前两种情况下,队列里的日志随进程一起消失。这就是开头第一个现象:进程退出前最后一段时间的日志,恰好是最想看的那一段,它们还在队列里。

要让退出前的日志写出来,必须有人在 JVM 退出时停止日志系统。Spring Boot 默认会注册关闭钩子来做这件事;独立的 Java 程序、定时任务、命令行工具需要自己配置(Logback 配置里的 <shutdownHook/>,或者自己注册钩子调用 LoggerContext.stop())。

关闭钩子只在正常退出时运行。进程被 kill -9、因为内存超限被内核杀掉、JVM 自身崩溃时,钩子不执行,队列里的日志必然丢失。所以「进程为什么死」这类信息不能只依赖应用自己的日志:容器的退出码、内核日志、JVM 的崩溃文件要另外收集。

实验过程中还碰到一个细节:同一个 LoggerContext 调用过一次 stop() 之后,如果不重新 start(),再次调用 stop() 不会去停止后来挂上的 appender。在测试代码或者会重新初始化日志的程序里,这会让「关闭时刷新」悄悄失效。

六、调用位置 ​

text
默认配置下,下游拿到的调用方法名 = ?;includeCallerData = true 时 = main

日志格式里的类名、方法名、行号(%class、%method、%line)需要在记日志的那个线程上获取调用栈。异步之后默认不取,输出的是问号。打开 includeCallerData 能拿到,但获取调用栈本身很慢,等于把省下来的时间又花了回去。常规做法是不依赖调用位置,靠 logger 名字(通常就是类名)和日志内容定位。

七、检查清单 ​

  • 知道日志框架的队列长度、丢弃规则和队列满时的策略,而不是「配了异步」就结束。
  • 明确选择阻塞还是丢弃;选丢弃时有指标能看到队列的水位。
  • 不能丢的记录不走日志通道。
  • 进程退出时有钩子停止日志系统;刷新等待的时间与优雅退出的时限匹配。
  • 进程被强杀时的信息另有来源。
  • 下游是网络(直接发到日志收集端)时,评估对端不可用时会怎样。更稳妥的结构是应用只写本地文件或标准输出,由独立的采集进程去读。
  • 做一次演练:让日志下游变慢或不可用,看业务是否受影响、丢了多少、有没有告警。

以上是 Logback AsyncAppender 的行为。Log4j2 的异步日志有自己的队列满策略与默认值,结论不能直接套用,但要回答的问题是同一组。异常信息本身在到达日志之前是怎么丢的,见出了错,日志里却没有可用的信息。


配套实验

  • codesphere-labs/engineering/async-logging-loss:Logback 1.5.38 的 AsyncAppender(JDK 25.0.4.1),下游是可以卡住、可以设定每条耗时的 appender:默认值、队列快满时丢弃 INFO、队列满时阻塞与丢弃、关闭时的等待、调用位置、三种进程结束方式下写出的条数(验证记录)

参考资料

文章以 CC BY-NC-SA 4.0 授权 · 代码片段以 MIT 授权