日志不是越多越好：logback 实践与线上问题定位

系列目录

转 Java 前，我已有 Node.js、C# 等后端经验，也预判到 Java 项目会遇到排查和运行维护问题，因此提前补过日志配置相关知识。2015 年转型复盘时，我记下过 Java 的日志不需要自行处理，也可以动态调整输出。当时只知道这些能力可以使用，还没有把它们落实为跨服务关联和统一的记录约定。

上一篇的 GC 排查也暴露了这个缺口。监控和 GC 日志能够确定方向，但“哪条请求路径慢、哪个任务在整点运行”仍要人工比对时间戳。下面记录一次问题如何验证了这个判断，以及之后补上的 logback、MDC 和日志规范。

一次无法关联的转存失败

GC 排查后一周多，客服转来几条用户反馈：把分享的文件转存到自己云盘时偶发失败，重试后又能成功。监控没有明显告警，RT 曲线只有轻微毛刺，需要查看日志。

转存链路包括 API 服务、元数据服务和存储服务。API 服务接收请求，元数据服务检查目标目录并写入元数据，存储服务拷贝数据块。三个服务都有日志，但记录方式不一致：

API 服务的 logback pattern 由我配置；元数据服务由另一位同事接手时配置，时间格式不同；存储调用代码还保留 System.out.println，输出混在 catalina.out，和业务日志分在两个文件。
关键路径上有大量 DEBUG；下游超时被记录为 INFO；ERROR 中还混入目标目录已存在等正常业务校验失败。按 ERROR 检索会得到很多无关记录。
三个服务没有共同的关联字段，只能按时间戳对应，且时间只精确到秒。高峰期一秒会产生几十到上百条日志。

当天下午，三个人分别在机器终端中按“时间窗 + 用户 ID”grep，将日志行贴到群里，再按秒对齐三个服务的记录。一个小时后只能判断存储服务可能较慢。存储服务在同一秒内有几十条日志，失败请求对应的具体调用无法确定，也无法据此确认原因。我们先为存储调用增加超时和重试，减少偶发失败的影响，日志改造留到后续处理。

这次问题说明，日志文件存在不等于请求可以被可靠检索和关联。此前的预判需要落到一项具体要求：同一次请求在各服务中的日志必须有共同标识。

logback 的配置对象

后续补 logback 配置时，我把要理解的范围收在三部分：

logger 按名称形成层级，有效日志级别决定事件是否继续传递给 appender，root logger 是层级根。2015 年记录的“可以动态调整”属于这一层。某个包可在线从 INFO 临时调整为 DEBUG，不需要重启应用。DEBUG 会增加该包的日志量，排查结束后需要恢复原级别。
appender 指定日志写入的位置。控制台、文件和远程端点都可以作为 appender，一个 logger 可以关联多个 appender。
encoder / pattern 决定每行日志的编码和格式。跨服务检索要求各服务约定字段含义、字段格式，并在 pattern 中输出排查所需字段。

改造后的核心配置如下，内容经过脱敏简化，使用 logback 1.x：

<configuration>
  <!-- 全组统一的格式：时间 级别 [线程] tid user logger 消息 -->
  <property name="PATTERN"
      value="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%thread] tid=%X{tid} user=%X{user} %logger{36} - %msg%n"/>

  <!-- 滚动文件：按天滚动 + 单文件上限，最多保留 7 天 -->
  <appender name="FILE" class="ch.qos.logback.rolling.RollingFileAppender">
    <file>logs/app.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
      <fileNamePattern>logs/app.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
      <maxFileSize>512MB</maxFileSize>
      <maxHistory>7</maxHistory>
    </rollingPolicy>
    <encoder>
      <pattern>${PATTERN}</pattern>
    </encoder>
  </appender>

  <!-- 异步输出：业务线程只负责把日志事件扔进队列 -->
  <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
    <queueSize>8192</queueSize>
    <discardingThreshold>0</discardingThreshold>
    <appender-ref ref="FILE"/>
  </appender>

  <root level="INFO">
    <appender-ref ref="ASYNC"/>
  </root>
</configuration>

按天滚动便于按日期检索。maxFileSize 限制单个滚动文件的大小，maxHistory 清理超过保留天数的历史文件。这两个配置不构成所有日志文件的总磁盘配额，特别是一天内产生多个滚动文件时。收到磁盘告警后，我补上了日志也可能占满磁盘这一项检查。AsyncAppender 有自己的队列和丢弃、阻塞条件，后文说明。pattern 中的 %X{tid}、%X{user} 用于输出 MDC 字段。

MDC 如何关联请求

统一 pattern 只能使字段可读。要识别同一次请求，需要 traceId。logback 的 MDC（Mapped Diagnostic Context）为当前线程保存上下文 Map，实现依赖 ThreadLocal。通过 put 写入的键值可以由 pattern 中的 %X{键} 输出。

入口生成或接续 traceId，并随请求透传。JDK 7 下的写法如下：

// Servlet Filter：入口生成或接续 traceId，结束时必须清理
public class TraceFilter implements Filter {
    public void doFilter(ServletRequest req, ServletResponse res, FilterChain chain)
            throws IOException, ServletException {
        try {
            String tid = ((HttpServletRequest) req).getHeader("X-Trace-Id");
            if (tid == null || tid.length() == 0) {
                tid = UUID.randomUUID().toString().substring(0, 8);
            }
            MDC.put("tid", tid);
            chain.doFilter(req, res);
        } finally {
            MDC.clear();  // 线程是池化复用的，不清会串号
        }
    }
    public void init(FilterConfig cfg) { }
    public void destroy() { }
}

实现时需要检查三个条件：

MDC.clear() 必须在 finally 中执行。Jetty 工作线程会复用。上一个请求遗留 tid 时，下一个请求的日志会带上错误 tid，检索结果也会错误。
MDC 不会自动跨线程。它基于 ThreadLocal。请求提交到业务线程池，也就是第 2 篇的两个池子后，执行线程的 MDC 为空。当时通过复制上下文，在执行前设置、执行后清理：

// 提交任务时把 MDC 拷过去，执行前 set、执行完 clear
final Map<String, String> ctx = MDC.getCopyOfContextMap();
pool.execute(new Runnable() {
    @Override
    public void run() {
        if (ctx != null) {
            MDC.setContextMap(ctx);
        }
        try {
            doWork();
        } finally {
            MDC.clear();
        }
    }
});

MDC 不会跨进程传播。调用下游服务时，需要把 tid 放进请求头，例如 X-Trace-Id，下游 Filter 读取后写入自己的 MDC。Kafka 异步链路也需要在消息头或消息体中携带 tid，消费端读取后写入 MDC。

请求在各服务间传播 tid 后，日志关系如下：

定位方式随之变化：从入口错误日志取得 tid 后，检索四个环节中带该 tid 的日志，结合时间戳和 cost 字段判断耗时集中在哪个环节。跨机器比较时间戳还要求机器时钟足够同步。这是请求日志关联的适用条件。

AsyncAppender 的队列条件

文件日志涉及 IO。同步 appender 会在业务线程中写入，写入延迟可能反映到请求 RT。AsyncAppender 将日志事件交给内存队列，由后台线程写入目标 appender；队列未满时，业务线程通常不必等待写入完成。

使用前需要确认队列容量和队列满后的行为。AsyncAppender 的默认配置为：

queueSize 默认只有 256；
队列剩余容量低于 discardingThreshold，默认取队列容量的五分之一，即 queueSize/5 时，TRACE / DEBUG / INFO 级别日志直接丢弃，只保留 WARN 和 ERROR；
队列彻底满时，默认 neverBlock=false，业务线程会阻塞在入队操作上，请求处理延迟会增加。

因此，默认阈值下，队列剩余空间不足时 INFO 日志可能先于 WARN 和 ERROR 被丢弃。当时将 queueSize 调整为 8192，discardingThreshold 设为 0，避免按级别提前丢弃日志。代价是队列写满时业务线程可能等待入队。我们将队列占用纳入监控；占用持续较高时，需要检查日志产生速率和下游写入能力。

这一取舍与第 2 篇的线程池拒绝策略目标不同。线程池拒绝使调用方感知并处理过载；日志队列阻塞优先保留日志事件。两种策略对请求延迟和日志完整性的影响不同。

日志代码还有两项约定。使用 {} 参数化日志，不使用字符串拼接，例如 logger.debug("cost={}", cost)。日志级别未启用时，参数化消息不会进行字符串格式化。参数本身需要昂贵计算时，仍要先用 isDebugEnabled() 判断。

云盘的日志规范

学习和验证上述机制后，我们将做法整理为四项规范：

格式统一。 pattern 为：时间级别 [线程] tid user logger 消息。避免使用 System.out.println 和 e.printStackTrace()。记录异常时使用 logger.error("上下文", e) 输出异常和堆栈。只记录 e.getMessage() 会丢失堆栈和异常类型，无法替代异常日志。

必打字段。 可关联到请求的业务日志携带 tid；入口日志携带 user 和接口名；入口进出、下游调用和 DB 操作等关键路径携带毫秒级耗时 cost=。cost 可以缩小慢调用的排查范围，但仍需结合调用上下文判断原因。

级别约定。 ERROR 用于需要人工关注的异常，并按具体场景配置告警；目标目录已存在等预期业务校验失败不记录为 ERROR。WARN 记录已处理但需要观察的情况，例如重试或降级。INFO 只记录关键节点，DEBUG 用于排查，生产环境默认不启用。

关键路径埋点。 入口、下游调用和存储操作记录开始和结束；结束日志区分成功、失败并携带 cost。埋点覆盖定位需要的边界即可。过多日志会增加检索噪音和写入开销。

规范落地两周后，出现过一次同类型的偶发失败告警。这次从入口日志取得 tid，检索 API、元数据、存储和异步通知四个环节的记录后，在十分钟内定位到存储服务拷贝数据块的调用偶发耗时较长，重试后成功。日志只能说明该调用耗时较长，底层慢 IO 的原因仍需要其他证据确认。

当时的范围和限制

检索能力依赖公司日志平台。 日志写入约定目录，由平台 agent 采集，再在网页中按关键字和时间窗检索。按 tid 一次检索依赖该平台能力；没有平台时，单机 grep 也可以检索，多台机器需要分别收集日志。

ELK 当时评估过，未自建。 2016 年 ELK 已经流行。自建可以提供更自由的检索和聚合分析，也需要维护集群。当时的日志平台能够满足需求，维护人力只有一两个人，因此没有自建。

tid 方案有明确范围。 它关联日志，无法提供调用树或耗时瀑布等结构化信息。Google 的 Dapper 论文 2010 年已经公开。我读过后认为全链路追踪系统的维护成本不适合当时的团队，先采用 MDC 加透传的方式。这是基于当时人员和维护成本的判断。

下一篇转向 IO，说明 IM 消息文件的实现中“每 3 万次请求 1~2 次失败”的数字如何计算。

参考资料

logback 官方文档（Appender、Rolling Policy、MDC、AsyncAppender 章节）
云盘服务端从nodejs 专项 java 相关复盘（“日志管理”一节的观察，本篇是它的后续实践）