“用户说下单慢”：从一句废话到根因的定位漏斗——traceId、ELK、链路追踪与排查方法论总纲

“余老师，在吗？有客户反馈，说咱们下单特别慢。”

这是客服小姐姐发来的原话。没有截图，没有时间，没有账号，没有“慢”的定义——是慢了 2 秒还是 20 秒？是点“提交”慢，还是选商品慢？我看着这句话，感觉像医生收到一位患者的留言：“大夫，我不舒服。”

做了八年后端，我越来越确信一件事：生产问题里，80% 的时间不是花在“修”上，而是花在“找”上。命令谁都会敲，难的是拿到一句模糊的话之后，知道先敲哪一条、下一步敲哪一条。这篇是整个“生产问题排查手记”的总纲：前面那些文章讲的是各个具体故障（CPU 飙高、Full GC、慢 SQL、连接池、MQ 堆积、Nginx 502、磁盘水位线、定时任务重复……），这一篇讲的是——怎样在它们之前，就把故障圈到那一个点上。

一、先别打开任何工具：排查前先问的 5 个问题

面对一句模糊的反馈，我的第一个动作是不看监控，先问人（或者查工单）。5 个问题，缺一不可，我贴在了工位的显示器边上：

这 5 个问题背后是一个道理：把“主观感受”翻译成“客观坐标”——时间坐标（几点几分）、空间坐标（哪个机构、哪个接口）、变化坐标（前后有什么变更）。有了坐标，才轮得到工具出场。

二、排查全景：定位漏斗

我把整个排查过程画成一个漏斗，每一层用一种工具，把“可疑范围”缩小一个数量级。这张图也是整个合集的目录：

这个漏斗最重要的是顺序。我见过太多人（包括年轻时的我）上来就登服务器 jstack、top，结果对着一个正常的实例研究了半小时，因为出问题的是另一个机构、另一个接口、另一台实例。工具越往下越精确，也越贵，越依赖“你已经知道看哪里”。

而把第 3 层和第 4 层串起来的那根线，就是本文的主角：traceId。

三、traceId 贯穿：一根线穿起所有服务

1）基本原理

一次“下单”请求，会依次穿过：Nginx → 网关 → 订单服务 → (Dubbo) 库存服务 / 优惠服务 → (RocketMQ) 消息消费者 → (线程池) 异步落库、发短信。每个服务各写各的日志，光看一台机器的日志，就像看电影只看了 1/5。traceId 就是给这一次请求发的“身份证”，每个服务打日志时都带上它，事后就能把所有日志拼回一个完整故事。

实现分三段：生成 → 携带 → 输出。

• 生成：在入口（网关或第一个服务）生成，如果请求头里已经有（比如前端或上游传来），则沿用；
• 携带：在同一个进程内，放进 ThreadLocal，也就是 Logback/Log4j 的 MDC（Mapped Diagnostic Context）；跨进程则通过 HTTP Header、Dubbo Attachment、MQ 消息属性传递；
• 输出：在日志格式里加上 %X{traceId}，每一行日志自动带上。

2）网关生成 + 返回给前端

入口处的 Filter（以 Servlet Filter 为例，网关用 Spring Cloud Gateway 的全局过滤器思路一样）：

@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
public class TraceIdFilter extends OncePerRequestFilter {
    public static final String HEADER = "X-Trace-Id";
    public static final String MDC_KEY = "traceId";

    @Override
    protected void doFilterInternal(HttpServletRequest req, HttpServletResponse resp, FilterChain chain)
            throws ServletException, IOException {
        String traceId = req.getHeader(HEADER);
        if (traceId == null || traceId.isEmpty()) {
            traceId = UUID.randomUUID().toString().replace("-", "");
        }
        MDC.put(MDC_KEY, traceId);
        resp.setHeader(HEADER, traceId);          // 关键：把 traceId 回给前端，客户报障时能提供
        try {
            chain.doFilter(req, resp);
        } finally {
            MDC.remove(MDC_KEY);                  // 线程会被复用，必须清理，否则串号
        }
    }
}

两个细节值得强调：一是把 traceId 放进响应头返回给前端，并让前端在报错弹窗里展示“错误编号”。有了它，“用户说慢”就能变成“用户给了个编号”，排查效率直接翻倍；二是 finally 里一定要 MDC.remove，Tomcat 的线程是复用的，不清理的话下一个请求会带着上一个请求的 traceId，日志会串号，排查时你会以为自己在看鬼片。

日志格式（logback）里加上：

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

如果你已经接入了 SkyWalking，它的 logback 工具包提供了 TraceIdPatternLogbackLayout，在 Pattern 里用 %tid 就能直接打出 SkyWalking 的 traceId（官方文档给的示例是 %d{yyyy-MM-dd HH:mm:ss.SSS} [%tid] [%thread] %-5level %logger{36} -%msg%n，探针未激活时输出 TID: N/A）。这样日志里的 traceId 与链路追踪里的 traceId 是同一个，Kibana 里拿到的 ID 可以直接去 SkyWalking 里搜——这是把“日志”和“链路”打通最省事的办法。

3）跨进程传递：Dubbo 与 RocketMQ

MDC 只在本线程有效。请求一旦跨进程，就必须显式把 traceId 带过去。

Dubbo：用 Filter SPI，在消费者端把 traceId 放进 attachment，在提供者端取出来放进 MDC：

// 消费者端
@Activate(group = CommonConstants.CONSUMER)
public class TraceConsumerFilter implements Filter {
    @Override
    public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
        String traceId = MDC.get("traceId");
        if (traceId != null) {
            RpcContext.getContext().setAttachment("traceId", traceId);
        }
        return invoker.invoke(invocation);
    }
}

// 提供者端
@Activate(group = CommonConstants.PROVIDER)
public class TraceProviderFilter implements Filter {
    @Override
    public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
        String traceId = invocation.getAttachment("traceId");
        if (traceId != null) MDC.put("traceId", traceId);
        try {
            return invoker.invoke(invocation);
        } finally {
            MDC.remove("traceId");
        }
    }
}

注册 SPI：在 src/main/resources/META-INF/dubbo/ 目录下创建以 Filter 接口全限定名命名的文件（Apache Dubbo 是 org.apache.dubbo.rpc.Filter，老的阿里 Dubbo 2.5/2.6 是 com.alibaba.dubbo.rpc.Filter），内容形如 traceConsumer=com.demo.trace.TraceConsumerFilter。社区里有不少基于这个思路的实现，包括我最初抄的那份。

坑：如果消费者端用了 Hystrix 线程池隔离，RPC 调用实际发生在 Hystrix 的线程里，MDC 是拿不到的，traceId 就丢了。这也是社区里的经典问题——解决方法是在进入线程池前把 traceId 存进去（后文线程池一节）。

RocketMQ：生产者往消息属性里放，消费者取出来放进 MDC：

// 生产者
Message msg = new Message("ORDER_CREATED", "tag", body);
msg.putUserProperty("traceId", MDC.get("traceId"));
producer.send(msg);

// 消费者
public ConsumeConcurrentlyStatus consumeMessage(List<MessageExt> msgs, ConsumeConcurrentlyContext ctx) {
    for (MessageExt m : msgs) {
        String traceId = m.getUserProperty("traceId");
        MDC.put("traceId", traceId != null ? traceId : UUID.randomUUID().toString().replace("-", ""));
        try {
            handle(m);
        } finally {
            MDC.remove("traceId");
        }
    }
    return ConsumeConcurrentlyStatus.CONSUME_SUCCESS;
}

消息队列是异步的，一次“下单”产生的消息，可能几秒后才被消费，中间还可能重试——traceId 让你能把“下单接口日志”和“消费者日志”拼在同一条时间线上，排查“消息丢了还是消费慢了”（之前那篇 MQ 堆积的文章里有这个场景）非常好用。

4）最经典的坑：线程池里 MDC 丢了

Logback 官方手册里说得很明白：子线程不会自动继承父线程的 MDC，尤其是使用 java.util.concurrent.Executors 线程池时，因为线程是提前创建、复用的，根本不存在“父子关系”。官方建议的做法：提交任务前用 MDC.getCopyOfContextMap() 拷贝，在工作线程里第一步 MDC.setContextMap() 恢复。

所以现象是这样的：主流程日志有 traceId，一进 @Async 或自己的线程池，日志里 traceId 就变成了空，甚至是上一个任务遗留的 traceId。我给出通用解法——包装 Runnable：

public class MdcRunnable implements Runnable {
    private final Runnable delegate;
    private final Map<String, String> context = MDC.getCopyOfContextMap();   // 在提交线程里拷贝

    public MdcRunnable(Runnable delegate) { this.delegate = delegate; }

    @Override
    public void run() {
        Map<String, String> previous = MDC.getCopyOfContextMap();
        if (context != null) MDC.setContextMap(context); else MDC.clear();
        try {
            delegate.run();
        } finally {
            if (previous != null) MDC.setContextMap(previous); else MDC.clear();   // 还原，避免污染线程池
        }
    }
}

// Spring @Async：用 TaskDecorator 统一包装，一劳永逸
@Bean
public ThreadPoolTaskExecutor bizExecutor() {
    ThreadPoolTaskExecutor ex = new ThreadPoolTaskExecutor();
    ex.setCorePoolSize(8);
    ex.setMaxPoolSize(16);
    ex.setQueueCapacity(200);
    ex.setThreadNamePrefix("biz-");
    ex.setTaskDecorator(r -> new MdcRunnable(r));
    ex.initialize();
    return ex;
}

用自己 new 的 ThreadPoolExecutor、CompletableFuture.supplyAsync(..., executor)、并行流，都会遇到同一个问题，要么统一包装，要么在业务里手动传。我们的规范是：项目里不允许直接 new 线程池，必须使用公共模块提供的、已带 MDC 传递的线程池工厂。（如果用 SkyWalking，它的 agent 会对常见线程池做增强，跨线程链路上下文会自动传递，但日志里的 MDC 仍需要自己管，别把两件事混为一谈。）

下面这张图把 traceId 的“携带”路径与断点画了出来：

四、日志规范：让 Kibana 能“问出答案”

有了 traceId，还需要日志“写得对”，否则 Kibana 里搜出来一堆 error 你也不知道哪个是哪个。我们的日志规范只有几条，但每条都是血泪换来的：

1. 每行日志必带 traceId，同时带上业务键：机构 ID（orgId）、税号（taxNo）、订单号（orderNo）。客户报障时几乎不可能给你 traceId，但一定能给你公司名/税号。有了业务键，就可以“业务键 → 慢请求 → traceId → 全链路”。业务键写进 MDC（比如登录拦截器里 MDC.put("orgId", ...)），而不是每条日志手拼。
2. 结构化 JSON 日志：不要再靠正则去切 [a][b][c] 的文本。使用 logstash-logback-encoder 输出 JSON，字段 @timestamp、level、service、traceId、orgId、logger、message、cost_ms、stack_trace。Filebeat 采集后不用 grok，直接进 ES，字段类型清晰，可以对 cost_ms 做范围查询与聚合。
3. 关键节点打耗时：对外部调用（HTTP、Dubbo、SQL 批量、缓存）打一行“开始/结束/耗时”，并用统一字段名（如 cost_ms）；慢调用（超过阈值）用 WARN 级别。
4. 入口和出口日志：Controller 层用切面统一打“接口、参数摘要、耗时、结果码”。参数脱敏（手机号、身份证、银行卡、token），日志不是垃圾桶。
5. 异常必须打堆栈，且只打一次：log.error("下单失败 orderNo={}", orderNo, e)，不要 e.getMessage() 拼字符串把堆栈丢了，也不要每层都 catch 后再 error 一遍，一个异常刷出五份堆栈，搜索时会被误导。
6. 日志级别与索引：按天建索引配 ILM 保留（可参考本合集里 ES 磁盘水位线那篇的教训，别让日志把磁盘吃满）。

<!-- logback-spring.xml：JSON 输出，MDC 里的 traceId、orgId 自动成为字段 -->
<appender name="JSON" class="ch.qos.logback.core.rolling.RollingFileAppender">
  <file>/data/logs/order-svc/app.json.log</file>
  <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
    <fileNamePattern>/data/logs/order-svc/app.%d{yyyy-MM-dd}.%i.json.log</fileNamePattern>
    <maxFileSize>200MB</maxFileSize><maxHistory>7</maxHistory><totalSizeCap>10GB</totalSizeCap>
  </rollingPolicy>
  <encoder class="net.logstash.logback.encoder.LogstashEncoder">
    <customFields>{"service":"order-svc"}</customFields>
  </encoder>
</appender>

一行典型输出（已美化）：

{"@timestamp":"2026-09-18T10:42:17.381+08:00","level":"WARN","service":"order-svc",
 "traceId":"7f3c9a1e5b2d4c86a0e1f2d3c4b5a697","orgId":"100234","logger":"c.d.order.client.TaxClient",
 "message":"call tax gateway slow, taxNo=91XXXXXXXXXXXXXXXX cost_ms=8123","cost_ms":8123}

五、Kibana 查询：KQL 速查

Kibana 的 KQL（Kibana Query Language）语法很小：field:value 匹配字段；and / or / not（大小写不敏感）组合并可用括号；* 是通配符；> >= < <= 用于数值/日期范围；field:* 判断字段存在。下面是我最常用的一批，都是官方语法范围内的：

# 1. 按 traceId 拉出一次请求的全部日志（所有服务），按时间排序即是完整时间线
traceId : "7f3c9a1e5b2d4c86a0e1f2d3c4b5a697"

# 2. 某机构在某接口上的慢请求（耗时超过 3 秒）
orgId : "100234" and message : "POST /api/order/create" and cost_ms >= 3000

# 3. 只看订单服务和库存服务的告警与错误
service : ("order-svc" or "stock-svc") and level : ("WARN" or "ERROR")

# 4. 排除健康检查噪音，找出耗时最大的外部调用
cost_ms > 1000 and not message : "/actuator/health" and message : "call*"

# 5. 有异常堆栈的日志（字段存在）
stack_trace : * and service : "order-svc"

# 6. 支持按税号查：客户只报公司名/税号时用它反查 traceId
message : "taxNo=91XXXXXXXXXXXXXXXX" and cost_ms >= 3000

使用技巧：

• 时间范围先框窄（拐点前后 30 分钟），再叠条件，否则又慢又噪；
• 先搜业务键，找到一两条慢日志，取出 traceId，再用第 1 条查全链路；
• 在 Discover 里把 @timestamp、service、level、traceId、cost_ms、message 加成列，一屏就能读完；
• Kibana 里点某条日志旁的“过滤此值”，能快速逐层收窄；
• 字段没建好映射（text vs keyword）时，精确匹配会不准——所以才要结构化日志和固定模板。

六、SkyWalking：看 span 耗时，回答“时间花在哪一段”

日志告诉你“发生了什么”，但当一次请求跨 6 个服务、20 个调用时，靠日志时间戳做减法，会让人抓狂。这时用链路追踪：在 SkyWalking UI 里，用日志里拿到的 traceId 直接搜（前提是日志里打的就是 SkyWalking 的 traceId，即前面说的 %tid），会得到一张瀑布图：

Trace: 7f3c9a1e5b2d4c86a0e1f2d3c4b5a697            total 8.62 s
├─ POST /api/order/create            (order-svc)          8.62 s
│  ├─ Dubbo StockService.lock         (stock-svc)         0.06 s
│  ├─ Dubbo CouponService.calc        (coupon-svc)        0.09 s
│  ├─ Redis GET org:profile:100234    (order-svc)         0.002 s   ← 未命中
│  ├─ MySQL SELECT org_profile ...    (order-svc)         0.02 s
│  ├─ HTTP POST tax-gateway/validate  (order-svc)         8.12 s    ← 大头在这里
│  └─ MySQL INSERT t_order ...        (order-svc)         0.01 s

读图的方法就是：先看总耗时，再找“最长的那根横条”，然后看它是自己的（self time）还是子调用的。这里 8.62 秒里 8.12 秒都是一个外部 HTTP 调用，别的全是毛毛雨。链路追踪的价值就在于，它把“到底是订单服务慢、库存服务慢、还是数据库慢”这个争论了半天的问题，一张图终结。SkyWalking 里还有“慢端点”“慢服务”排行、拓扑图和告警，用于从“指标层”直接发现异常服务，然后点进具体 trace。

需要注意几点：

• SkyWalking 通常有采样率设置，你要找的那一条慢请求，可能刚好没被采到。所以日志里的 traceId 要保证覆盖率，链路只做“加强”而不是唯一依赖；
• 异步、MQ 场景，一条 trace 可能拆成几段，用 traceId（或 MQ 的 msgId）串起来；
• span 里不含业务语义，机构 ID、税号这类业务键要靠日志或者给 span 打 tag（自定义 tag）补足。

七、完整时间线：从“下单慢”到根因

说了这么多工具，最后还是要走一遍完整的过程。以下是我把一次真实经历改写成的时间线（机构、税号均为虚构示例，数字仅说明量级）：

整个过程没有一次 jstack，没有一次登服务器，因为漏斗到第 4 层就已经把根因暴露出来了。这就是为什么我一直强调“先问、再看指标、再看日志、再看链路、最后才下服务器”。如果我当时直接登服务器 top，会看到一切正常，然后陷入“我的机器没问题，那就是网络吧”的甩锅循环。

另外，这个案例还有一个深层教训：“变更”永远是第一嫌疑人，在 10:28 我就把“昨天发版”记下了，但没有先入为主。因为如果全局慢，而发版又是刚好在这个时间点，那嫌疑更大，需要先看指标确认范围，再看日志确认证据——“时间吻合”只是线索，不是证据。

八、指标 + 日志 + 链路：三件套怎么配合

它们的关系是“发现 → 圈定 → 还原 → 定位”：指标发现异常并圈定范围（哪个服务、哪个时间）；日志按业务键还原具体请求；链路对着 traceId 定位到具体环节；现场工具（jstack、Arthas、慢 SQL、抓包）解释“为什么这一环慢”。缺任何一环，都会回到“猜”。所以我们的规范是三者用同一个 traceId 打通：日志里有 traceId，链路里是同一个 traceId，Grafana 的告警通知里带上“跳转到 Kibana 的链接”，值班的人一键就能过去。

和本合集里其他文章的关系，也可以用这张“症状索引”记：

• CPU 打满：指标发现 → top -Hp + jstack 现场（正则回溯、死循环）；
• 频繁 Full GC / OOM：指标看堆曲线 → jmap、MAT、GC 日志；
• 接口整体变慢：链路看 span → 慢 SQL / 连接池耗尽 / 外部依赖超时；
• MQ 堆积、消息重复：指标看堆积量 → 日志按 msgId/traceId 追消费者 → 幂等设计；
• Nginx 502/504：网关日志的 upstream 耗时 → 后端线程池与超时配置；
• 写入 403 / 集群变黄：ES 磁盘水位线 → _cat/allocation；
• 定时任务重复/不触发：调度日志 + 执行日志 → 幂等设计；
• Docker/容器问题：docker logs、资源限制、OOMKilled；

它们的共同点是：先有坐标，再有命令。

九、复盘：把“找”的时间压下来

一句话备忘：模糊反馈先问 5 件事（范围、时间、变更、规律、复现）→ 指标圈范围 → 业务键在 Kibana 找慢请求取 traceId → 同一个 traceId 在 SkyWalking 看 span → 最后才登服务器；MDC 跨线程、跨进程都要手动传。

写到这里，这个合集也算收尾了。回头想想，最有价值的排查能力，不是记住多少命令，而是面对“下单好慢”这样的废话，依然能冷静地问出第一个问题。至于客服小姐姐，她后来学会了发消息的标准格式：“机构ID + 时间 + 现象 + 截图上的错误编号”——你看，连客服都被我们训练成了 traceId 的搬运工。

参考资料

• Logback 官方手册：Mapped Diagnostic Context——MDC 的用法，%X 输出，以及子线程/线程池不会自动继承 MDC、需用 getCopyOfContextMap / setContextMap 手动传递。
• Apache SkyWalking 官方文档：logback 工具包——TraceIdPatternLogbackLayout、%tid 与 SW_CTX 输出格式，实现日志里打印链路 traceId。
• Kibana 官方文档：Kibana Query Language (KQL)——字段匹配、and/or/not、通配符、范围比较与字段存在性查询语法。
• 博客园：dubbo traceId 透传实现日志链路追踪（基于 Filter 和 RpcContext）——消费者/提供者 Filter 通过 attachment 传递 traceId 并放入 MDC，以及 SPI 注册文件的写法。