出事的那几秒,日志恰好是空的
服务重启了一次。想从日志里找重启前发生了什么,却发现重启前的最后一段日志是空白。另一次故障里,ERROR 日志都在,但前后的 INFO 上下文全没有,只知道哪个请求失败了,不知道它之前走到了哪一步。
为了不让写日志拖慢业务线程,日志通常配成异步的:业务线程把日志事件放进内存里的队列就返回,由后台线程写到磁盘或发到收集端。队列是有限的,后台线程写得再快也有跟不上的时候,进程也总有退出的一刻。这三处都会丢日志,而且默认配置下丢的时候不报错、不计数。
本文用 Logback 1.5.38 的 AsyncAppender 把每一处跑出来。实验见文末。
一、默认配置
队列长度 256,丢弃阈值 51(剩余容量低于它时丢弃 INFO 及以下),neverBlock = false,关闭时最多等 1000 ms,记录调用位置 = false五个默认值,后面每一节对应一个。
实验里 AsyncAppender 的下游是一个可以被卡住、也可以设定每条耗时的 appender,代替变慢的磁盘或网络。
二、队列快满时:INFO 被悄悄丢掉
让下游卡住,然后连续记 1001 条 INFO:
下游卡住期间记了 1001 条 INFO,全部立即返回;此时队列里有 206 条,剩余容量 50业务线程没有受任何影响,每次调用都立即返回。但队列里只有 206 条:剩余容量低于 51 之后,AsyncAppender 把 TRACE、DEBUG、INFO 级别的事件直接丢弃,不进队列。下游恢复后实际写出的:
下游恢复并正常关闭后,实际写出的:INFO 207,WARN 50,ERROR 1(记了 INFO 1001、WARN 50、ERROR 1)1001 条 INFO 写出了 207 条,其余 794 条没有留下任何痕迹。
这是一个有意的设计:队列的最后五分之一留给 WARN 和 ERROR,保证重要的日志有位置。代价就是开头的第二个现象。下游一慢,INFO 最先消失,而排查问题需要的上下文(请求参数、走了哪个分支、调了哪个下游)大多是 INFO。
把 discardingThreshold 设成 0 可以关掉这个行为,所有级别一视同仁:
discardingThreshold = 0,下游卡住期间记满队列后再记一条 INFO:业务线程 300 ms 内返回 = false;实际写出 INFO 258,WARN 0,ERROR 0一条都没有丢,但队列满了之后 INFO 也会让业务线程等。这引出下一节。
三、队列满时:等,还是丢
队列满了之后来了一条 ERROR:
再记 50 条 WARN(不在丢弃之列):队列里 256 条,剩余容量 0
队列满了之后再记一条 ERROR:业务线程 300 ms 内返回 = false默认 neverBlock = false:队列满时,记日志的调用会阻塞,直到队列腾出位置。这时「异步」已经名存实亡,业务线程的速度被下游写日志的速度卡住。日志收集端不可用、磁盘写满、日志所在的网络盘抖动,都会通过这条路径让业务请求一起卡住;从线程转储里看到的是大量线程停在日志调用上。
另一个选择是 neverBlock = true:
neverBlock = true,下游卡住期间记 300 条 WARN 再记 50 条 ERROR:业务线程立即返回 = true;实际写出 INFO 1,WARN 256,ERROR 0业务线程不再被阻塞,代价是队列满之后所有级别都丢:50 条 ERROR 一条都没有写出。
两个选项是在「日志可能拖住业务」和「日志可能丢」之间选一个,没有两全的配置:
- 多数在线服务选不阻塞。日志丢失可以接受,业务线程因为日志卡死不能接受。
- 审计、交易流水这类不能丢的记录,不应该走日志这条通道,而应该作为业务数据写进数据库或消息队列,并对失败做处理。
不论选哪个,队列长度 256 对有一定流量的服务都偏小,可以调大;同时需要一个能看到的信号:丢了多少。Logback 的 AsyncAppender 不提供丢弃计数,可以定期采集队列的剩余容量(getRemainingCapacity())作为指标,长期贴近 0 就说明下游跟不上。
四、关闭时:只等一秒
队列里有 3000 条、下游每条 2 ms(写完要 6 秒)时关闭日志系统:stop() 在 0.9–1.5 秒内返回 = true,此时写出的不到一半 = true实验的那一次,stop() 用了 1004 毫秒返回,这时 3000 条里写出了 504 条。关闭时后台线程最多有 maxFlushTime(默认 1000 毫秒)来写完队列里剩下的,时间到了就放弃。
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。在测试代码或者会重新初始化日志的程序里,这会让「关闭时刷新」悄悄失效。
六、调用位置
默认配置下,下游拿到的调用方法名 = ?;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、队列满时阻塞与丢弃、关闭时的等待、调用位置、三种进程结束方式下写出的条数(验证记录)
参考资料
- Logback 文档:AsyncAppender(
queueSize、discardingThreshold、neverBlock、maxFlushTime、includeCallerData) - Logback 文档:Stopping logback-classic(关闭钩子)
- Log4j 2 文档:Asynchronous loggers
- Spring Boot 文档:Logging(日志系统的关闭钩子)
- Kubernetes 文档:Pod Lifecycle,Termination of Pods