日志输出格式:Pattern 布局、时间戳、线程名、类名、行号的定制

日志格式这东西,看着不起眼,但真出了问题你就知道它有多重要了。我记得有一次线上排查一个死锁问题,几十个线程的日志混在一起,时间戳只精确到秒,线程名全是默认的"Thread-1"、"Thread-2"……那叫一个痛苦。从那以后,我对日志格式的要求就变得特别苛刻。

说白了,日志格式就是你的"现场还原工具"。格式定得好,问题定位快三倍。今天我们就聊聊怎么定制一个靠谱的日志输出格式。

4.1 Pattern 布局的核心要素

Logback 和 Log4j2 都支持通过 Pattern 来定制日志输出格式。我个人习惯用 Logback,但核心概念是通用的。一个完整的 Pattern 布局,至少应该包含下面这几个要素:

要素 占位符 说明 我踩过的坑
时间戳 %d{yyyy-MM-dd HH:mm:ss.SSS} 精确到毫秒,用于时间线还原 少写了毫秒,排查慢查询时根本对不上
日志级别 %-5level 左对齐,固定5字符宽度 不固定宽度的话,排版会乱
线程名 %thread 区分并发请求的关键 默认线程名没业务含义,后面会讲怎么改
类名 %logger{36} 缩短包名,保留36字符 太长的话一行就占了大半
行号 %line 精确到代码行,快速定位 生产环境慎用,有性能开销
消息体 %msg%n 日志内容 + 换行 别忘了 %n,否则日志全粘一起

我常用的一个 Pattern 是这样的:

<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36}:%line - %msg%n</pattern>

输出效果:

2025-03-21 14:32:18.456 [http-nio-8080-exec-3] INFO  com.example.OrderService:127 - 订单创建成功,订单号: ORD20250321001

嗯,这个格式我用了好几年,基本没改过。你想想看,一行日志里,时间、谁打的、什么级别、哪个类的哪一行、说了什么,全有了。

4.2 时间戳的精度与格式选择

时间戳是日志里最重要的字段,没有之一。为什么?因为你要还原事件发生的先后顺序。

我曾经遇到过一个场景:两台机器的系统时间差了3秒,结果日志里A机器的"请求到达"时间比B机器的"响应返回"还晚,排查了半天才发现是时间不同步。从那以后,我要求所有服务器必须启用 NTP 同步,并且日志时间戳统一使用 UTC。

时间戳的格式选择,我建议遵循几个原则:

  • 必须包含毫秒:SSS 不能省。高并发场景下,同一秒内可能有上千条日志,没毫秒根本分不清先后。
  • 使用 ISO 8601 格式:yyyy-MM-dd'T'HH:mm:ss.SSSZ 带时区信息,跨团队协作时不会产生歧义。
  • 避免使用默认格式:Logback 默认的 %d 输出的是 "2025-03-21 14:32:18,456",逗号分隔毫秒,看着别扭。
我的小技巧:在开发环境用本地时间,方便阅读;在生产环境统一用 UTC,避免夏令时、时区转换带来的混乱。两套配置通过 Spring Profile 切换就行。

4.3 线程名的定制与业务关联

线程名这个东西,默认的 http-nio-8080-exec-3 只能告诉你这是第几个工作线程,但无法关联到具体的业务请求。你想想看,如果同时有100个请求在处理,日志里全是 exec-1 到 exec-100,你根本不知道哪个线程在处理哪个用户的请求。

我建议的做法是:在请求入口处,把线程名改成有业务含义的名称。

// 在 Filter 或 Interceptor 中
String originalName = Thread.currentThread().getName();
String businessName = "order-" + orderId + "-" + UUID.randomUUID().toString().substring(0, 8);
Thread.currentThread().setName(businessName);

try {
    // 处理业务逻辑
} finally {
    // 记得恢复
    Thread.currentThread().setName(originalName);
}

这样日志就变成了:

2025-03-21 14:32:18.456 [order-ORD20250321001-a3f8c2d1] INFO  ...

看到线程名,你就知道这条日志属于哪个订单。排查问题时,直接 grep 这个线程名,就能把整个请求链路的所有日志捞出来。

注意:线程名修改后一定要在 finally 块中恢复。我曾经见过一个同事改了线程名没恢复,导致线程池里的线程名越来越长,最后 OOM 了。嗯,这是个真实案例。

4.4 类名与行号的取舍

类名和行号是定位代码位置的关键。但这里有个矛盾:行号是通过动态生成字节码来实现的,有性能开销。

我做过一个压测对比:

配置 QPS CPU 额外开销 适用场景
带行号 %line 基准值 - 15% 约 8-12% 开发、测试、预发环境
不带行号 基准值 0% 生产环境(高并发)
仅类名 %logger 基准值 - 3% 约 2% 生产环境(中等并发)

我的建议是:

  • 开发环境:带上行号,方便快速定位。
  • 生产环境:去掉行号,用类名 + 方法名代替。或者只在 WARN/ERROR 级别带行号,INFO 级别不带。

Logback 支持按级别设置不同的 Pattern:

<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
        <level>WARN</level>
    </filter>
    <encoder>
        <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36}:%line - %msg%n</pattern>
    </encoder>
</appender>

<appender name="FILE_INFO" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <filter class="ch.qos.logback.classic.filter.LevelFilter">
        <level>INFO</level>
        <onMatch>ACCEPT</onMatch>
        <onMismatch>DENY</onMismatch>
    </filter>
    <encoder>
        <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
</appender>

这样 WARN 和 ERROR 日志带行号,方便排查;INFO 日志不带行号,减少性能损耗。

4.5 日志格式的整体设计原则

说了这么多,最后总结一下我设计日志格式的几个原则:

  1. 可读性优先:格式对齐,固定宽度,不要一行日志长得像天书。
  2. 信息完整:时间、线程、级别、位置、消息,一个都不能少。
  3. 性能可接受:生产环境去掉行号,或者按级别区分。
  4. 统一规范:整个团队、所有服务使用相同的格式,方便统一采集和分析。

核心观点:日志格式不是写给自己看的,是写给未来的自己和同事看的。花10分钟把格式定好,能省下未来10小时的排查时间。

下面这张图是我对日志格式设计思路的总结,你可以参考一下:

日志格式设计核心要素 日志格式 Pattern 时间戳 线程名 日志级别 类名 行号 设计要点 • 时间戳:必须包含毫秒,生产环境建议使用 UTC • 线程名:默认名称无业务含义,建议在入口处修改为有意义的名称 • 日志级别:固定宽度左对齐,方便阅读 • 类名与行号:开发环境带行号,生产环境按级别区分或去掉行号

嗯,日志格式这块就聊这么多。记住一句话:好的日志格式,是排查问题的第一道防线。花点心思把它配好,后面你会感谢自己的。