日志不是越多越好:开发优化、常见坑与线上排查命令

日志不是越多越好:开发优化、常见坑与线上排查命令

Scroll Down

凌晨三点,磁盘告警响了——不是业务暴涨,是某个接口在循环里打了 log.info,一天滚了 80GB。更讽刺的是,真出故障时,运维在几 TB 日志里搜 ERROR,关键信息淹没在噪音里;还有些地方只打了 e.getMessage(),堆栈根本没落盘。

日志的目标只有两个:出问题能定位,平时别拖垮系统。 下面按「为什么要控量 → 怎么优化 → 有哪些坑 → 线上怎么查」来说。


一、为什么「打太多」比「不打」更危险

日志不是免费的。每次 log.info() 背后至少有三笔账:

成本 典型表现
CPU 字符串拼接、序列化大对象、格式化时间戳
IO 同步写盘阻塞业务线程;磁盘满触发轮转风暴
存储 采集、索引、ES 集群费用直线上升

Spring Boot 默认 Logback 同步写文件。QPS 上万时,日志 IO 经常比业务 SQL 还忙。我线上见过:日志占满磁盘 → 应用写日志失败 → 线程阻塞 → 接口超时,形成二次故障。


二、开发侧:六条可落地的优化原则

1. 级别用对,生产默认 INFO

# application-prod.yml
logging:
  level:
    root: INFO
    com.your.pkg.mapper: WARN   # MyBatis SQL 只在排障时临时开 DEBUG
    org.springframework: WARN

原则:DEBUG 留给本地和短期排障,不要长期开在生产。

2. 占位符 + 级别判断,别在参数里做重活

// 坏:字符串拼接,DEBUG 关了也会算
log.debug("user=" + userService.loadFullProfile(userId));

// 好:占位符 + 懒求值
if (log.isDebugEnabled()) {
    log.debug("user={}", userService.loadFullProfile(userId));
}

注意:{} 只避免字符串拼接,不会阻止参数求值——loadFullProfile() 仍会执行,重逻辑必须加 isDebugEnabled() 判断。

循环、定时任务、MQ 消费里尤其要克制——一条 INFO × 每秒 1 万次 ≈ 8.64 亿行/天。

3. 热路径采样,别全量打

private static final Logger log = LoggerFactory.getLogger(OrderService.class);

public void pay(Order order) {
    if (log.isInfoEnabled() && ThreadLocalRandom.current().nextInt(100) == 0) {
        log.info("pay sample orderId={}", order.getId());
    }
    // 业务逻辑...
}

或用 Micrometer + 指标代替逐笔日志。需要全链路时,靠 TraceId 关联,而不是每笔都打满。

4. 异步 Appender,降低 IO 阻塞

<!-- logback-spring.xml -->
<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
    <queueSize>8192</queueSize>
    <discardingThreshold>0</discardingThreshold>
    <neverBlock>true</neverBlock>
    <appender-ref ref="FILE"/>
</appender>

neverBlock=true 时队列满会丢日志——金融核心链路慎用,一般业务可接受。

5. MDC 统一上下文,一条日志说清「谁、哪、什么」

MDC.put("traceId", traceId);
MDC.put("uri", request.getRequestURI());
MDC.put("userId", String.valueOf(userId));
try {
    log.info("createOrder amount={}", amount);
} finally {
    MDC.clear();
}
// pattern 示例:[%X{traceId}] [%X{uri}] [%X{userId}],grep traceId 一次拉全链路

6. 轮转与保留,别让磁盘裸奔

logging:
  logback:
    rollingpolicy:
      max-file-size: 100MB
      max-history: 7
      total-size-cap: 5GB

三、七个常见坑(我踩过或看别人踩的)

1. 循环里打 INFO
for (item : list)log.info("processing {}", item) —— 列表 10 万条,日志 10 万行。

2. 大对象直接 {}
log.info("resp={}", hugeDto) 触发 toString() / JSON 序列化,一条日志几 KB 到几 MB。

3. 异常只打 message,不打 stack
log.error("fail: " + e.getMessage()) —— 丢了栈,等于白打。应 log.error("fail", e)

4. 重复打
AOP 统一记请求日志,方法里又 log.info 一遍——日志翻倍,还难读。

5. 敏感信息裸写
手机号、身份证、Token、密码出现在日志里——合规和安全双重雷。脱敏或干脆别打。

6. 生产临时开 DEBUG 忘关
排查完没改回去,磁盘和 CPU 慢慢被吃掉。建议用 Spring Boot Actuator /actuator/loggers 动态改,并设变更告警。

7. 把日志当数据库
「用户行为全量落日志,后面再分析」—— 日志系统不是 OLAP,该进 MQ/数仓的别塞 log 文件。


四、线上排查:常用日志命令速查

假设日志路径 /var/log/app/application.log,以下命令在 Linux 生产环境 可直接改路径复用(macOS 默认 grep 不支持 -P,可用 ggrep 或改写成 grep -o + awk)。

# 实时:tail -f / tail -F(轮转不丢)/ less +F(可暂停翻页)
tail -F /var/log/app/application.log

# 过滤:关键字、上下文、traceId、排除噪音
grep -E "ERROR|Exception" application.log
grep -C 5 "NullPointerException" application.log    # 前后 5 行
grep -A 20 "OutOfMemoryError" application.log
grep "traceId=abc123" application.log
grep -v "health" application.log | grep "ERROR"

# 时间窗(格式随 pattern 调整)
sed -n '/2026-09-04 14:00/,/2026-09-04 14:30/p' application.log

# 统计 TOP 异常
grep "ERROR" application.log | wc -l
grep -oP 'Exception: \K[^ ]+' application.log | sort | uniq -c | sort -rn | head -20

# 压缩/历史/多文件
zgrep "ERROR" application.log.2026-09-03.gz
find /var/log/app -name "*.log*" -mtime -3 -exec grep -l "traceId=abc123" {} \;

# 容器 / systemd
kubectl logs -f deploy/order-service --tail=500 --since=30m | grep ERROR
journalctl -u your-app.service -f --since "1 hour ago"

五、与项目结合:怎么定规范

  1. 分级规范:ERROR = 需告警;WARN = 可恢复异常;INFO = 关键业务节点;DEBUG = 开发/短期排障。
  2. 一条请求一条摘要:入口记 traceId + 耗时 + 结果码,细节放 DEBUG 或采样。
  3. CI / Review 检查:禁止 System.out.println;Code Review 或自定义静态规则拦截循环内 INFO、硬编码敏感词。
  4. 排障 SOP:先 grep traceId → 再 grep ERROR 看时间窗 → 最后 jstack/Arthas 对齐线程栈。

六、参考内容