2255 字
约 7 分钟
15
S06-X14 · 日志框架:门面、绑定与异步

线上 CPU 打满,火焰图排第一的是 ch.qos.logback.core.OutputStreamAppender 的写入;另一次是 ERROR 日志被队列静默丢弃,出事时只剩 INFO。两个问题成因不同,却都落在同一层:绑定关系与异步机制。代码里只该出现门面,实现与行为由 classpath 和配置决定。


1. 三个名字的关系

层 代表 作用 不该做的事
门面(facade) slf4j-api 只定义 Logger 接口与占位符语法 不含实现,不做 IO
实现(binding) logback-classic、log4j2 真正格式化、写盘、滚动 业务代码不直接依赖
桥接(bridge) jul-to-slf4j、log4j-over-slf4j、jcl-over-slf4j 把老 API 的调用转到 SLF4J 不能与同类实现同时出现

commons-logging、java.util.logging(JUL)是历史 API,靠桥接包并入 SLF4J;Spring 6 已改用 spring-jcl 自适应。


2. 多实现共存:谁赢,以及那条警告

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:.../logback-classic-1.5.6.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:.../slf4j-simple-1.7.36.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Actual binding is of type [ch.qos.logback.classic.util.ContextSelectorStaticBinder]
现象 含义 处理
multiple SLF4J bindings 两个 binding 共存,实际只用一个(谁被先加载谁赢,不保证稳定) mvn dependency:tree 找到多余来源并排除
Failed to load class StaticLoggerBinder 无 binding,退化为 NOP 补实现
Class path contains SLF4J bindings targeting slf4j-api versions 1.7.x or earlier 版本错配(2.x 门面 + 1.7 实现) 统一到同一大版本
<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter-web</artifactId>
  <exclusions>
    <exclusion>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-logging</artifactId>
    </exclusion>
  </exclusions>
</dependency>
<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter-log4j2</artifactId>
</dependency>

换实现必须排掉默认实现再引入新的——赢家由类加载顺序决定,可能随 jar 顺序变化,等于把日志行为交给运气。


3. 桥接包的循环依赖风险

桥接包 方向 与谁冲突
jul-to-slf4j JUL → SLF4J 与 slf4j-jdk14 冲突(反向)
log4j-over-slf4j Log4j 1.x API → SLF4J 与 slf4j-log4j12 互逆,两个同装必死循环
jcl-over-slf4j commons-logging → SLF4J 与 commons-logging 本体重复
log4j-to-slf4j Log4j2 API → SLF4J 与 log4j-slf4j-impl 冲突

最典型的栈溢出来自 log4j-over-slf4j 与 slf4j-log4j12 并存:Log4j 转 SLF4J,SLF4J 又转回 Log4j,无限递归,启动即 StackOverflowError。**判断只有一条:查依赖树里有没有互为反向的两个包。**JUL 桥接还需执行 SLF4JBridgeHandler.install(),光引 jar 不够。


4. 占位符与字符串拼接的代价

log.debug("order {} status {} user {}", orderId, status, userId);   // 惰性:不输出就不格式化
log.debug("order " + orderId + " status " + status);                // 立即拼接,DEBUG 关闭也付代价
写法 未开启该级别时的开销 参数里的异常
{} 占位符 极低(仅参数入栈) 最后一个 Throwable 会被打印栈
字符串拼接 每次调用都构造字符串 栈信息混进消息文本
log.error("fail: " + e.getMessage()) 丢失异常栈 只剩一行文本
log.error("fail", e) 正确 栈与消息分离,可结构化采集

占位符与参数数量不匹配时,SLF4J 不抛异常,而是原样输出多余的 {}、或把最后一个参数当 Throwable。"看起来正常但内容错位"只能靠规范约束。


5. 级别语义:ERROR 泛滥等于没有 ERROR

级别 该记什么 反例
ERROR 需要人介入、有业务损失、要触发告警 每次请求失败都 ERROR,但其实是用户输错密码
WARN 可自愈但需要关注、降级、重试成功 把每次重试都 WARN,形成噪声
INFO 状态变化:启动、配置加载、关键业务动作完成 每个 SQL 都 INFO
DEBUG 细节:入参出参、分支选择 生产默认开 DEBUG
TRACE 极细粒度,通常只在本地 线上开启导致 IO 打满

告警规则挂在 ERROR 上,所以 ERROR 的条数等于噪声水平。判断标准:这条 ERROR 是否该把值班的人叫起来。


6. 配置优先级

机制 优先级 说明
logging.config=classpath:xxx.xml 最高 显式指定,覆盖约定文件名
logback-spring.xml 高于 logback.xml 可用 <springProfile>、<springProperty>
logback.xml 约定名 被 Logback 自动加载,早于 Spring 环境就绪
logback-test.xml(test classpath) 测试期最高 单测不污染生产配置
<configuration>
  <springProperty scope="context" name="APP" source="spring.application.name" defaultValue="app"/>
  <springProfile name="prod">
    <root level="INFO"><appender-ref ref="ASYNC_FILE"/></root>
  </springProfile>
  <springProfile name="dev">
    <root level="DEBUG"><appender-ref ref="CONSOLE"/></root>
  </springProfile>
</configuration>

logback.xml 在 Spring 环境就绪之前加载,用不了 springProperty、拿不到 spring.profiles.active——这是"profile 区分不生效"的头号原因。


7. 异步 Appender:异步不等于不丢

<appender name="ASYNC_FILE" class="ch.qos.logback.classic.AsyncAppender">
  <queueSize>4096</queueSize>
  <discardingThreshold>0</discardingThreshold>
  <neverBlock>false</neverBlock>
  <includeCallerData>false</includeCallerData>
  <appender-ref ref="FILE"/>
</appender>
参数 含义 默认 风险
queueSize 有界队列长度 256 太小 → 高并发下频繁丢
discardingThreshold 队列剩余低于该比例时丢弃 TRACE/DEBUG/INFO 队列长度的 20% 默认会丢 INFO;设 0 表示不丢
neverBlock 队列满时是否阻塞业务线程 false(阻塞) true 时丢日志保吞吐
includeCallerData 是否采集调用方类名行号 false 开启后需抓栈,开销明显

三条结论:默认 discardingThreshold 会丢 INFO;即使设 0,neverBlock=true 时队列满仍丢,且丢的是新来的,可能是 ERROR;进程 kill -9 时队列里全部丢失。正确姿势是 discardingThreshold=0 + neverBlock=false,把"丢日志"换成"短暂阻塞"。


8. MDC 在异步与线程池中丢失

MDC.put("traceId", traceId);
executor.submit(() -> log.info("async task"));   // traceId 丢失

// 解法:装饰任务,复制上下文
public class MdcTaskDecorator implements TaskDecorator {
    public Runnable decorate(Runnable r) {
        Map<String, String> ctx = MDC.getCopyOfContextMap();
        return () -> {
            if (ctx != null) MDC.setContextMap(ctx);
            try { r.run(); } finally { MDC.clear(); }
        };
    }
}
场景 MDC 是否保留 修法
同一线程同步调用 是 —
线程池执行 否 TaskDecorator 装饰
@Async 否 配置 TaskDecorator
异步 Appender 写盘 是(复制在 LoggingEvent) 无需处理
跨服务调用 否 透传 header + 追踪系统

MDC.clear() 必须在 finally 里:线程池线程复用,不清就把上一个请求的 traceId 带过去。


9. 切割、保留与结构化

<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
  <file>logs/app.log</file>
  <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
    <fileNamePattern>logs/app.%d{yyyy-MM-dd}.%i.log.gz</fileNamePattern>
    <maxFileSize>100MB</maxFileSize>
    <maxHistory>15</maxHistory>
    <totalSizeCap>10GB</totalSizeCap>
  </rollingPolicy>
</appender>
参数 决定 配错的后果
maxFileSize 单文件上限 太大 → 单文件巨大,grep 与采集器都吃力
maxHistory 保留天数 太小 → 出事后日志已删
totalSizeCap 总占用上限,到顶后删最旧 不设 → 磁盘写满,服务挂
.gz 后缀 自动压缩 改后缀名即改行为,无需额外配置

结构化日志交给采集器(Filebeat/Fluent Bit/Loki)解析时,字段命名必须稳定:

{"ts":"2026-11-09T08:20:38Z","level":"ERROR","traceId":"a1b2","service":"order","msg":"pay failed","costMs":38}

ts 用 ISO-8601 带时区、level 全大写、traceId 固定拼写。字段名被采集规则依赖后,改名即破坏性变更。


10. 排错表:常见坑

坑 表现 修法
用 System.out / printStackTrace 日志文件里没有、无法按级别过滤、无时间戳 统一走门面
日志里拼大对象 CPU 与 IO 双高,GC 压力上升 只打标识与摘要,debug 级别打详情
异步队列满丢 ERROR 出事时无日志 discardingThreshold=0,neverBlock=false
多环境配置混用 生产打 DEBUG,磁盘半天写满 logback-spring.xml + springProfile
桥接包互逆 启动 StackOverflowError 查依赖树,去掉反向包
MDC 未清理 日志串线,traceId 张冠李戴 finally { MDC.clear(); }

11. 边界表

场景 该用的手段 理由
高频访问日志 异步 Appender + 限流 同步写盘直接压在业务线程上
需要按请求串联 MDC + 跨线程装饰器 线程池不继承上下文
审计/合规日志 独立 Appender + 同步刷盘 不能丢,异步不保证
多服务聚合 结构化 JSON + traceId 文本正则解析不可维护
容器化 输出 stdout 容器内写文件随重启丢失

12. 自测

  1. multiple SLF4J bindings 时实际生效的是哪一个?为什么说它"不保证稳定"?
  2. 哪两个包同时存在会导致 StackOverflowError?怎么发现?
  3. discardingThreshold 的默认值会丢哪个级别的日志?设成 0 之后还有丢的可能吗?
  4. logback.xml 与 logback-spring.xml 的加载时机差别,决定了什么能力可用?
  5. 线程池里 MDC 为什么会失效?MDC.clear() 为什么必须放在 finally?
  6. totalSizeCap 与 maxHistory 谁先触发删除?不设 totalSizeCap 的风险是什么?
S06-X14 · 日志框架:门面、绑定与异步
https://www.clxhxhhr.top/posts/5987/
作者
clxstart
发布于
2024-12-31
许可协议
CC BY-NC-SA 4.0
评论
0 条
还没有评论,先写一条吧。