线上 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. 自测
multiple SLF4J bindings时实际生效的是哪一个?为什么说它"不保证稳定"?- 哪两个包同时存在会导致
StackOverflowError?怎么发现? discardingThreshold的默认值会丢哪个级别的日志?设成 0 之后还有丢的可能吗?logback.xml与logback-spring.xml的加载时机差别,决定了什么能力可用?- 线程池里 MDC 为什么会失效?
MDC.clear()为什么必须放在finally? totalSizeCap与maxHistory谁先触发删除?不设totalSizeCap的风险是什么?