📚 课程目录第4章日志分析基础

日志分析基础：如何从日志中快速定位批次问题

先说句实在话。我在排查批次问题的时候，80% 的时间都花在看日志上。

日志这东西，说简单也简单，就是一行一行的文本。说复杂也复杂，生产环境一天能刷出几个 G 的日志。你不掌握方法，那就是大海捞针。特别是批次任务，动辄处理几万几十万条数据，问题往往藏在一堆正常日志中间。

这章我们就聊聊，怎么从日志里快速捞出那些关键线索。

日志级别：你的第一道过滤器

日志级别不是摆设。很多团队级别乱用，全队都是 INFO，真正出问题的时候根本找不到重点。我个人习惯：一定要把级别当成过滤器来设计。

级别	什么时候用	你该关注什么
ERROR	系统无法自动恢复的异常，比如数据库连接失败	必须人工介入，优先排查
WARN	能恢复但值得注意的情况，比如重试第 3 次才成功	可能存在潜在风险，值得记录
INFO	关键流程节点，比如批次开始、结束、处理条数	用来了解任务整体进度
DEBUG	开发阶段或临时排查时使用	生产环境要关掉，否则日志量爆炸

一个小建议：批次任务中，ERROR 级别的日志最好包含上下文标识，比如批次 ID 或记录 ID。否则你看到一行 "NullPointerException"，根本不知道是哪条数据出的问题。

说回实用场景。我建议你在项目里这样配置日志输出：

# logback.xml 示例
<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
  <file>logs/batch-${BATCH_ID}.log</file>
  <encoder>
    <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
  </encoder>
</appender>

注意：上面的配置里文件名用到了 ${BATCH_ID}，就是从环境变量或启动参数里拿到的批次 ID。这样每个批次有自己的日志文件，排查起来非常方便。

关键信息提取：日志行里的黄金

拿到日志文件，你不能从头读到尾。你得知道哪些信息才是关键。我把它总结为五要素。

时间戳 —— 精度要到毫秒。批次任务通常跨几分钟到几小时，时间能帮你快速圈定问题时间段。
线程名 / 进程 ID —— 批次任务可能是多线程或多进程并行，你要知道是哪条执行单元出的问题。
追踪 ID / 请求 ID —— 单条数据处理的唯一标识。没有这个，你无法把日志行和数据记录关联起来。
日志等级 —— 前面提过，先抓住 ERROR 和 WARN。
上下文数据 —— 比如 "处理用户ID=12345，余额=100.00"。没有上下文，你看不懂这条日志在说什么。

看个实际的日志行：

2025-01-15 14:23:45.678 [batch-worker-3] ERROR c.example.batch.UserProcessor - 
tracingId=txn-20250115-0001-0000012345 | 用户ID=998877 | 处理充值失败 | 余额不足

你想想看，这一行包含了五要素里的全部信息。时间、线程、级别、追踪 ID、业务上下文，全都有。我拿到这样的日志，能直接去数据库查这条记录，看看当时余额到底是多少。

有些团队日志写得很粗糙：

2025-01-15 14:23:45 ERROR - Something wrong

说实话，这种日志等于没写。你根本不知道哪里 wrong，哪条数据 wrong。

组织你的日志分析流程

光有理论知识不够，还得有一套分析流程。这套流程，我在很多项目里都用过，效果还不错。

核心思路：先全局扫描，再局部深入。

这张图其实代表了我自己排查问题的习惯。第一步不是去看报错细节，而是先确定"什么时候开始报错的"。我见过太多人上来就搜 "Exception"，结果搜出一大堆历史遗留的警告，浪费半天时间。

实战案例：从一行日志到定位根因

说个真实案例。之前有个批次任务，每天凌晨跑，偶尔会报数据不一致。日志量大概 2GB 一天，人肉翻是不现实的。

我当时做了这么几件事：

确定时间窗口——通过任务调度平台的记录，发现报错集中在 02:15 - 02:20 之间。
按级别过滤——用 grep 抓出 ERROR 日志：

grep "2025-01-15 02:1[5-9]" app.log | grep "ERROR"

很快发现了一批相似日志：

2025-01-15 02:15:12.345 [pool-4-thread-1] ERROR - tracingId=1234 | 账务处理失败 | 余额不足
2025-01-15 02:15:18.678 [pool-4-thread-1] ERROR - tracingId=5678 | 账务处理失败 | 余额不足
2025-01-15 02:15:22.890 [pool-4-thread-1] ERROR - tracingId=9012 | 账务处理失败 | 余额不足

发现没有？线程名全是 pool-4-thread-1。其他线程正常，就这一条线程异常。这非常可疑。

然后我顺着 tracingId 去查数据库，发现这些用户都是刚好在批次处理时被其他系统扣了款，导致余额临时不足。问题是：为什么只有这条线程碰到这种情况？

继续查日志，发现 pool-4-thread-1 处理的任务恰好是按用户 ID 分段中的一段，这段用户所在的业务线在那段时间正好在发优惠券，触发了并发扣款。最终根因是：另一个定时任务和批次任务的时间窗口重叠了。

复盘时的启发：如果日志里没有线程名和 tracingId，这个案例根本没法定。你可能只能看到一堆 "余额不足" 的 ERROR，然后怀疑是代码 bug，但实际上只是任务调度冲突。

常用的日志分析命令

我习惯用 shell 命令快速过滤日志。以下是我常用的几招：

# 1. 按时间范围截取
sed -n '/2025-01-15 02:15:00/,/2025-01-15 02:20:00/p' app.log > window.log

# 2. 统计 ERROR 级频繁出现的异常类型
grep -oP 'ERROR - \K.*' window.log | sort | uniq -c | sort -rn

# 3. 提取某个 tracingId 的全部日志
grep 'tracingId=1234' window.log

# 4. 分析各线程的错误数
grep 'ERROR' window.log | grep -oP '\[.*?\] ' | sort | uniq -c | sort -rn

小心：在生产环境直接操作大日志文件时，要考虑文件大小。我个人习惯先用 head -n 1000 看一下文件头，确认格式没问题再批量处理。别把服务器搞 OOM 了。

日志系统设计的三点建议

最后，说三点我踩过的坑，现在一直在遵循：

日志要带唯一标识——每次批次任务的开始，生成一个 UUID 写入日志，后续所有关联日志都带上这个 ID。否则多个批次混在一起时，你根本分不清。
错误日志不要只记 Exception.getMessage()——一定要带上堆栈。我见过有人只记 "NullPointerException"，没有堆栈，等于没记。堆栈能告诉你具体是哪行代码出了问题。
按批次号滚动输出——不要把所有日志写到一个文件里。每个批次一个文件，或者每个时间窗口一个文件。我习惯在文件名里带上 batch-{batchId}-{timestamp}.log 的结构。