第 08 章（节选）　分布式链路与实战案例

本篇来自《Go 程序员的 Java 修炼之路》第 08 章「第 08 章　排错方法论：从异常栈到根因（一套能复用的 SOP）」。返回：第 08 章索引

08.6 分布式链路追踪：从”哪个服务”到”哪个请求”

前面的工具全部是单机视角。但你现在面对的是一个请求跨 8 个服务、日志散在 8 台机器（或者 80 个 Pod）上的系统。

问题 2： 用户投诉”我的订单支付失败了”。你有 8 个服务的日志。你怎么找这个请求？

如果没有 traceId，答案是：先猜是订单服务，去那台机器上按时间和 userId 筛，找到一条请求日志，从里面扒出一个下游的订单号，再去支付服务按这个订单号筛，再扒出流水号…… 每一步都要猜，每一步都可能跟错。

有了 traceId，答案是：grep 一次，8 个服务上关于这个请求的所有日志全出来了。

TraceId / SpanId 的传播机制

两个概念：

TraceId：一次完整请求（可能跨多个服务）的唯一标识，全程不变
SpanId：一次调用（一个服务内部的一段工作）的标识。Span 之间有父子关系，形成一棵树

TraceId: abc123def456
│
├─ Span A (order-service /pay)                 spanId=A1, parentId=null
│   ├─ Span B (payment-service /charge)        spanId=B2, parentId=A1
│   │   └─ Span C (bank-gateway /transfer)     spanId=C3, parentId=B2
│   └─ Span D (mysql SELECT orders)            spanId=D4, parentId=A1
└─ 总耗时 1283ms，其中 B2 花了 1201ms（94%）

有了这棵树，“慢在哪”这个问题直接有了答案，不用你去猜。

传播机制 —— 靠什么把 TraceId 传下去：

场景	传播方式
HTTP 调用	请求头（W3C 标准是 `traceparent`，老系统是 `X-B3-TraceId` / 自定义 `X-Trace-Id`）
gRPC	metadata（等价于 HTTP header）
MQ（Kafka/RocketMQ）	消息头（headers / properties），不是消息体
线程池 / `@Async`	ThreadLocal 传递（需要显式处理，见下）
定时任务	自己生成一个新 TraceId（这批任务属于同一个 trace，或者各自独立）

MQ 是最容易漏的一环：很多团队把 traceId 塞进消息体（JSON 的一个字段），这样虽然能用，但中间件（比如消息轨迹查询）看不到它。正确做法是放消息头。

工具选型

工具	定位	接入方式	现状
OpenTelemetry	标准（协议 + SDK + Collector）	SDK 或 Java Agent	事实标准，合并了 OpenTracing 和 OpenCensus（2019）
SkyWalking	APM（国内主流）	Java Agent，零代码侵入	自带存储、UI、告警，开箱即用
Zipkin	轻量链路追踪	Brave / Spring Cloud Sleuth	老牌，简单
Jaeger	CNCF 毕业项目	OTLP 接收	云原生场景常见
Pinpoint	APM（韩国开源）	Java Agent	调用链粒度极细（到方法级）

现在的实践建议：

用 OpenTelemetry 做埋点和数据模型（它是标准，不会被厂商锁定）
后端可选（SkyWalking / Jaeger / 商业 APM 如听云、博睿、DataDog），因为 OTel 的 Collector 可以把 OTLP 数据转发到任何后端
Java 项目优先用 Agent 模式（-javaagent:opentelemetry-javaagent.jar 或 SkyWalking agent），零代码接入

注意一件事：Spring Cloud Sleuth 已经停止维护（Spring Boot 3.x 起被 Micrometer Tracing 取代，底层走 OTel）。如果你接手的老项目用了 Sleuth，迁移时需要注意 traceId/spanId 的 MDC key 从 traceId/spanId 变成了 trace_id/span_id（W3C 标准命名）。

可观测性三支柱

Metrics、Logging、Tracing 是三件事，不是一件事的三种叫法。

支柱	回答什么问题	数据形态	成本	工具
Metrics	”有没有问题？有多严重？“	聚合的数值时间序列	低（预聚合，可长期存）	Prometheus + Grafana
Logging	”具体发生了什么？“	离散的文本事件	高（全量存储很贵）	ELK / Loki
Tracing	”这个请求在哪个环节出问题？“	有结构的调用树	中（通常要采样）	SkyWalking / Jaeger

正确的配合流程（这是排查的标准动作）：

1. Metrics 发现问题  → Grafana 报警：订单服务 P99 从 50ms 涨到 3s
2. Tracing 定位范围  → 挑几个慢请求的 trace 看，发现 94% 时间在 payment-service 的 DB 查询
3. Logging 看细节    → 用这个 traceId 捞出全部日志，看到具体的 SQL 和参数
4. 单机工具下钻      → Arthas trace / jstack，确认根因

反过来做（直接去看日志）是最低效的，因为你不知道该看哪一行的日志。

这就是为什么 Tracing 必须采样：全量存储调用链的代价太高（一次请求 8 个服务 × 每层几个 span）。常见策略：

# 常见采样策略
- 头部采样（Head sampling）：请求入口就决定，比如 1% 采样
- 尾部采样（Tail sampling）：★ 请求结束后决定，出错的和慢的 100% 保留，正常请求 1% 采样

尾部采样是正确答案：你关心的恰恰是那些出错和慢的请求，而头部采样会随机丢掉它们。OpenTelemetry Collector 的 tail_sampling processor 就是干这个的。

【思考】为什么 TraceId 在线程池里会丢？怎么解决？

这一题的价值不在答案本身，在于它是一个通用问题的一个实例。想清楚这个通用问题是什么。

参考答案

直接答案：因为 MDC 是 ThreadLocal<Map<String,String>> 实现的，而线程池里的线程不是提交任务的那个线程。

为什么会丢：

// 请求进来，在 Tomcat 的工作线程（http-nio-8080-exec-1）上执行
MDC.put("traceId", "abc123");
 
// 提交异步任务
executor.submit(() -> {
    log.info("异步扣减库存");   // 这行在 pool-1-thread-3 上执行
    // pool-1-thread-3 的 ThreadLocalMap 里没有 traceId → 日志里 %X{traceId} 是空的
});

ThreadLocal 的语义是”当前线程的私有变量”。子线程不会继承父线程的 ThreadLocal（除非用 InheritableThreadLocal）。所以任务一旦被提交到线程池，上下文就断了。

为什么不能用 InheritableThreadLocal 简单解决：

InheritableThreadLocal 会在线程创建时把父线程的值复制给子线程。听起来对，但在线程池里是错的：

// 线程池的线程是复用的，只在第一次创建时继承
ExecutorService pool = Executors.newFixedThreadPool(4);
 
// 请求 1：traceId=aaa，提交了任务 → pool 创建了 thread-1，thread-1 继承到 aaa ✓
// 请求 2：traceId=bbb，提交了任务 → 复用 thread-1，thread-1 里的值**还是 aaa** ✗

结果是数据错乱（请求 2 的日志被打上了请求 1 的 traceId），比丢失更糟糕 —— 丢失你只是一片空白，错乱你会被误导到完全错误的方向。

而且还有第二个问题：InheritableThreadLocal + 线程池 = 值永不更新 = 这个引用一直被线程持有 = 内存泄漏。

解决方案一（Spring 项目首选）：TaskDecorator。

@Configuration
public class MdcExecutorConfig {
 
    @Bean("mdcTaskExecutor")
    public Executor mdcTaskExecutor() {
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
        executor.setCorePoolSize(8);
        executor.setMaxPoolSize(16);
        executor.setQueueCapacity(2000);
        executor.setThreadNamePrefix("biz-");
 
        // ★ 关键：任务装饰器 —— 在提交时抓取上下文，在执行时回放，执行后清理
        executor.setTaskDecorator(runnable -> {
            Map<String, String> captured = MDC.getCopyOfContextMap();  // 提交方线程：抓取
            return () -> {
                if (captured != null) {
                    MDC.setContextMap(captured);   // 执行方线程：回放
                }
                try {
                    runnable.run();
                } finally {
                    MDC.clear();                   // ★ 必须清理，否则线程复用时会串号
                }
            };
        });
        executor.initialize();
        return executor;
    }
}

注意 MDC.clear() 那一行。 它的作用跟 InheritableThreadLocal 的坑是对称的：如果你只 set 不 clear，这个线程下次被复用时会带着上次的 traceId —— 又是数据错乱。

解决方案二（阿里 TTL，跨框架通用）：TransmittableThreadLocal。

// 1. 用 TTL 替代普通 ThreadLocal
private static final TransmittableThreadLocal<String> TRACE_ID = new TransmittableThreadLocal<>();
 
// 2. 包装线程池（关键步骤，漏了就不生效）
ExecutorService pool = TtlExecutors.getTtlExecutorService(Executors.newFixedThreadPool(8));
 
// 3. 提交任务时自动传递，执行后自动清理
TRACE_ID.set("abc123");
pool.submit(() -> log.info("traceId={}", TRACE_ID.get()));  // abc123 ✓

TTL 的原理是包装 Runnable/Callable，在 run() 前后做”抓取-回放-恢复”三段式（它叫 TtlRunnable）。它比 TaskDecorator 通用的地方在于：TTL 能传递任意 TTL 变量，且支持线程池的包装、ForkJoinPool、CompletableFuture 的包装，不依赖 Spring。

<dependency>
    <groupId>com.alibaba</groupId>
    <artifactId>transmittable-thread-local</artifactId>
    <version>2.14.5</version>
</dependency>

解决方案三（新项目推荐）：用 OpenTelemetry 的 Context 传播。

// OTel 的 Context 也是 ThreadLocal 的，但它提供了显式的传播机制
Context current = Context.current();          // 提交方：抓取当前 Context（内含 Span）
executor.submit(Context.taskWrapping(current, () -> {
    // 执行方：Context 已恢复，这里创建的 Span 会自动挂在上一个 Span 下面
    Span span = tracer.spanBuilder("async-deduct").startSpan();
    try (Scope scope = span.makeCurrent()) {
        inventoryService.deduct();
    } finally {
        span.end();
    }
}));

这是最”正确”的方案，因为 OTel 把”上下文传播”当成一等公民设计，它的 Context 里装的不仅是 traceId，还有 Baggage（任意业务标签）、Span 引用等。缺点是你需要真的在用 OTel。

方案选型建议：

场景	推荐方案
Spring Boot 项目，只需要传 MDC	`TaskDecorator`（零依赖）
大量异步 / 自定义线程池 / 非 Spring 项目	TTL
已经接入 OpenTelemetry	OTel 的 `Context.taskWrapping`
老项目里有 `InheritableThreadLocal`	立刻改掉，这是个定时炸弹

更深一层：这是一个”异步 + 上下文传递”的通用问题，MDC 只是它的一个实例。

把这个问题抽象出来：当一个执行单元（线程/goroutine/协程）把工作交给另一个执行单元时，“当前上下文”该怎么办？

丢弃（普通 ThreadLocal）：最简单，但上下文断了
继承（InheritableThreadLocal）：只在创建时传递一次，在池化场景下语义错误
显式传递（TaskDecorator / TTL / OTel Context）：正确，但需要框架或约定支持
参数化（把上下文当函数参数一路传下去）：最正确，但侵入性最强

Go 在这个问题上的答案是唯一的：context.Context 作为参数显式传递。

// Go 的做法：context 是第一个参数，编译器强制你显式传
func pay(ctx context.Context, orderID int64) error {
    // ctx 里带着 traceID、deadline、cancel func
    span := trace.SpanFromContext(ctx)
    return inventory.Deduct(ctx, orderID)   // 必须显式往下传
}
 
// 异步：也是显式传
go func() { defer wg.Done(); deduct(ctx, id) }()

这是我认为 Go 明显更优的一个设计点，值得 Java 学习。

context.Context 的三个好处，恰好对应上面 ThreadLocal 的三个坑：

显式：函数签名上写着 ctx context.Context，你一眼看出这个函数参与上下文传播。Java 的 ThreadLocal 是隐式的 —— 你根本不知道哪个方法读了它
不会错乱：因为每次调用都传一个新的 ctx，不存在”线程复用导致值过期”的问题
不会泄漏：ctx 是一个普通参数，函数返回后自动被 GC。没有”线程持有引用”这种生命周期问题

Java 在往这个方向走：Java 21 的 ScopedValue（预览特性，配合结构化并发）本质上就是”有作用域的、不可变的、显式传递的 ThreadLocal”。第 04 章的 ThreadLocal 泄漏那道题里提过它。

但这里我要给一个更平衡的判断：context.Context 的代价是侵入性 —— 每个函数签名都要加一个参数，每个调用点都要传一次。Go 社区接受了这笔代价（甚至成了强制规范），Java 社区没有（所以有了 ThreadLocal 和它的一堆补丁）。

这跟第 00 章讲的”Go 错误是值 vs Java 错误是控制流”是同一个模式：Go 选择显式和啰嗦，Java 选择隐式和简洁。两种选择各有账单，只是账单寄到的时间不同。

08.7 实战：三个完整的排查案例

三个案例分别对应三类最难的问题：性能、内存、偶发。每个都按”现象 → 假设 → 验证 → 根因 → 修复 → 教训”推进。

案例一（性能）：接口 P99 从 50ms 涨到 3s

现象

监控告警：订单服务 /order/create 的 P99 从 50ms 涨到 3000ms，持续 20 分钟。诡异的是：

CPU 32%（不高，说明不是在算）
内存平稳，GC 正常（说明不是 GC 问题）
没有任何 ERROR 日志（说明不是某个下游报错）
QPS 没涨（说明不是流量突增）

假设（按验证成本从低到高排序）

外部依赖慢（验证成本：1 分钟，看下游监控）
锁竞争（验证成本：1 分钟，thread -b）
GC 停顿（验证成本：30 秒，jstat，已初步排除）
数据库慢查询（验证成本：2 分钟，看慢 SQL 日志）

先排除最容易的：查了支付、库存、用户三个下游的监控，全部正常（RT < 20ms）。假设 1 排除。

验证：Arthas 三连

# 第一步：总览
dashboard
#  线程区：200 个 http-nio 线程，其中 197 个 BLOCKED
#  内存区：堆 45%，GC 正常
#  → CPU 不高但 197 个线程 BLOCKED = 典型的"排队等锁"，不是"算得慢"

# 第二步：谁在阻塞别人
thread -b
# "xxl-job-scheduler-1" Id=89 RUNNABLE
#     at java.net.SocketInputStream.socketRead0(Native Method)
#     at com.mysql.cj.jdbc.ClientPreparedStatement.execute(ClientPreparedStatement.java:~1000)
#     at com.example.order.StatsJob.rebuildDailyStats(StatsJob.java:64)
#     at com.example.order.InventoryService.deduct(InventoryService.java:88)
#     - locked <0x00000000d7b3c210> (a com.example.order.InventoryService)
#
#     Number of blocked threads: 197

关键发现：阻塞源头是一个 xxl-job-scheduler 线程（定时任务线程），不是 HTTP 请求线程。它持有 InventoryService 的锁，卡在一个 JDBC 查询上。

# 第三步：看这个定时任务在跑什么
trace com.example.order.StatsJob rebuildDailyStats '#cost > 100' -n 1
#     `---[2987.4ms] com.example.order.StatsJob:rebuildDailyStats()
#         `---[2985.9ms] com.example.order.StatsMapper:selectDailyStats()
#              `---[2985.8ms] com.mysql.cj.jdbc.ClientPreparedStatement:execute()
 
# 拿到 SQL（用 watch 抓参数）
watch com.example.order.StatsMapper selectDailyStats '{params[0]}' -x 2
#   @ParamMap[{startDate=2026-08-01, endDate=2026-09-01, status=null}]

根因

一个低频的每日统计定时任务，在 synchronized 方法 InventoryService.deduct() 里执行了一条慢 SQL：

SELECT sku_id, SUM(amount) FROM order_item
WHERE create_time BETWEEN '2026-08-01' AND '2026-09-01'
GROUP BY sku_id;
-- order_item 表 200 万行，create_time 上没索引 → 全表扫描 3 秒

因果链：定时任务持有 InventoryService 的锁 → 锁内执行全表扫描 3 秒 → 所有 /order/create 请求都在 deduct() 门口排队 → P99 = 3 秒。

注意这里的”低频”很关键：这个任务一天只跑一次，跑的时候恰好被你撞上。如果它跑得快一点（比如 200ms），你永远发现不了这个隐患。它是被”数据量涨到 200 万行”这件事引爆的。

修复（三层）

// ❌ 修复前：synchronized 方法里做数据库 IO
public synchronized void deduct(String sku, int n) {
    // ... 检查库存、扣减（毫秒级）
    statsMapper.selectDailyStats(start, end);   // ← 3 秒的全表扫描，锁被一路持有
}
 
// ✅ 修复一：SQL 加索引（治本）
// ALTER TABLE order_item ADD INDEX idx_create_time (create_time);
// 全表扫描 3s → 索引扫描 12ms
 
// ✅ 修复二：把统计逻辑移出锁（治标也治本）
public void deduct(String sku, int n) {
    synchronized (this) {
        // 锁内只做内存/DB 的检查和扣减，微秒到毫秒级
    }
    // 统计逻辑挪到锁外，且用独立的线程池执行
}
 
// ✅ 修复三：给定时任务加锁超时（防御性）
// 即使将来又出现慢 SQL，也不会无限期占锁
ReentrantLock lock = new ReentrantLock();
if (lock.tryLock(500, TimeUnit.MILLISECONDS)) {   // 拿不到锁就快速失败
    try { rebuildDailyStats(); }
    finally { lock.unlock(); }
} else {
    log.warn("stats job skipped, lock busy");
    // 让监控看到：这个任务被跳过了
}

教训

synchronized 里绝对不能做 IO（数据库、HTTP、Redis、MQ、文件）。锁的持有时间要按微秒算，不是毫秒，更不是秒。这是 Java 并发的第一条铁律
低频任务是被忽视的性能炸弹。它平时不出现，一旦数据量涨上去就会以”持锁”的方式放大影响
CPU 不高 + 线程 BLOCKED = 排队，不是算得慢。这个组合应该立刻想到锁，而不是去查算法
定时任务的线程名要和业务线程名区分开（xxl-job-scheduler vs http-nio-8080-exec）。第 04 章说过”给线程池起好名字价值连城”，这个案例就是兑现 —— 如果那个线程叫 pool-3-thread-1，你根本看不出它是个定时任务
没有任何 ERROR 日志，不代表没有故障。 监控系统必须覆盖 P99，而不只是错误率

案例二（内存）：服务每天重启一次才不 OOM

现象

运维的”解决方案”：每天凌晨 3 点定时重启一次订单服务，因为不重启就会在下午左右 OOM。前任留下的运维文档里写着”服务有内存泄漏，暂时靠重启规避”。

监控特征：老年代占用从重启后的 30% 一路爬到 95%（大约 16 小时），然后 Full GC 越来越频繁，最后 OOM。

验证

# 第一步：确认是泄漏而不是配置太小
jstat -gcutil 12345 5000
#    O        YGC   YGCT   FGC   FGCT
#    34.21    1203  10.2    2    0.51   ← 重启后 1 小时
#    58.44    3411  28.7    5    1.34   ← 6 小时后
#    87.92    6218  52.1   11    3.08   ← 12 小时后
#    95.13    8402  71.9   19    6.72   ← 16 小时后，每次 FGC 后 O 都降不回去
#  → 判定：真泄漏（FGC 后不回落是唯一判据）

# 第二步：看谁在堆积（不加 :live，避免触发 Full GC）
jmap -histo 12345 | head -15
#  num     #instances         #bytes  class name
#    1:       2841093       90914976  [C
#    2:       2840127       68163048  java.lang.String
#    3:       1204338       38538816  java.util.HashMap$Node
#    4:        601218        24048720  com.example.order.OrderDTO   ← ★ 业务对象 60 万个
#    5:        601218        14453232  com.example.order.OrderItem
#  → 60 万个 OrderDTO，每个 40 字节，外加它的 OrderItem —— 而且类名明确

业务类进前 5，实锤。不需要 dump 就知道是谁了。但要知道谁在持有它们，还得 dump：

# 第三步：摘流量后堆转储（警告：会 STW）
jcmd 12345 GC.heap_dump -gz=1 /data/dump/heap.hprof
# 8G 堆 → 压缩后 2.4G，传输快很多

MAT 分析三步：

Step 1: 打开 Leak Suspects（MAT 首页自动生成）
  → Problem Suspect 1: "com.example.order.OrderCache" 占用 1.8GB (62%)

Step 2: Dominator Tree（按 retained heap 排序）
  → com.example.order.OrderCache @ 0x7f8c1234      1,821,456,320 B (62.31%)
      └→ java.util.HashMap$Node[]                   1,821,102,080 B
           └→ 601218 个 Node → value: OrderDTO

Step 3: 对 OrderCache 右键 → Path to GC Roots → exclude weak/soft references
  → com.example.order.OrderCache.INSTANCE            (static field)
      ← 静态字段！生命周期 = 进程生命周期

根因

翻出代码：

// ❌ 前任写的"临时"缓存：静态 Map，只 put 不 remove，无容量上限无过期
public class OrderCache {
    public static final Map<Long, OrderDTO> CACHE = new ConcurrentHashMap<>();
 
    public static OrderDTO get(Long id) {
        return CACHE.computeIfAbsent(id, id2 -> orderMapper.selectById(id2));
    }
    // 没有任何 remove，没有任何过期策略，没有任何容量限制
}

注释里写着 // TODO: 临时方案，后面换 Redis。这个”后面”永远没来，而这个临时方案跑了两年 —— 直到订单量涨到每天 60 万，它撑不过一天。

修复

// ✅ 方案一（推荐）：换成 Caffeine，有容量上限 + 过期策略
@Configuration
public class CacheConfig {
    @Bean
    public Cache<Long, OrderDTO> orderCache() {
        return Caffeine.newBuilder()
                .maximumSize(10_000)                    // ★ 容量上限：这是防泄漏的核心
                .expireAfterWrite(Duration.ofMinutes(10))  // ★ 过期时间
                .recordStats()                           // 开启统计，能监控命中率
                .build();
    }
}
 
// 使用：get 语义不变，但有了驱逐保证
OrderDTO order = orderCache.get(id, k -> orderMapper.selectById(k));

// ✅ 方案二：如果数据量真的需要很大，用 Redis（分布式缓存），本地只留热点
// 但注意：引入 Redis 会带来缓存穿透/击穿/雪崩三个新问题，见第 18 章

验证修复有效（这一步不能省）：

# 上线后观察 24 小时
jstat -gcutil 12345 5000
#  O 列应该在 30%~65% 之间锯齿波动（每次 FGC 后回落到基线），不再单调上升

教训

静态集合是内存泄漏的头号嫌疑犯。 因为静态字段是 GC Root，它的生命周期等于 ClassLoader 的生命周期（基本等于进程）。看到 static Map / static List 且有 put/add 但没 remove，直接怀疑
本地缓存必须有容量上限和过期策略，没有例外。 哪怕你”知道”数据量很小 —— 数据量的增长永远超出你的预期
jmap -histo 在很多时候就够了，不一定要 dump。 业务类名出现在前 20 名，你基本已经知道是谁了。dump 是 8G 的、会 STW 的、要传半天的大文件，能不做就不做
jstat 的 O 列是判定泄漏的唯一标准：Full GC 后回落到基线 = 只是压力大；不回落 = 泄漏
“靠重启规避”是最危险的运维方案，因为它把一次性的故障变成了慢性的、被忽视的、最终一定会爆的债。这个团队的警报系统里没有”老年代趋势”这一项，所以泄漏跑了两年没人管
// TODO: 临时方案 是最长命的代码。 每次写这句话的时候提醒自己：它会比你的任期长

案例三（偶发）：每天凌晨 2 点左右少量超时

现象

每天凌晨 2:00~~2:05 之间，有 20~~50 个请求超时（超时阈值 2 秒）
白天完全正常，QPS 是凌晨的 50 倍都不出问题
日志里没有任何异常（超时的请求最后都成功了，只是慢）
持续两周，无人能复现

假设

“凌晨 2 点”这个时间点太明显了 —— 一定有个定时任务。但查了 xxl-job 的调度记录，凌晨 2 点确实有一个批处理任务（数据同步），那个任务本身跑得好好的，从没失败过，所以之前没人怀疑它。

验证：JFR 常开录制

这类偶发问题不能靠”等它发生再去采样”（你不知道它什么时候发生，等你收到告警登上去，早就过去了）。所以：

# 在启动参数里加常开录制，滚动保留最近 24 小时
-XX:StartFlightRecording=disk=true,maxage=24h,maxsize=2g,filename=/data/rec.jfr
# 等一个凌晨，第二天来取

JMC 里打开录制文件，看三件事：

1. GC 事件（JVM Internals → GC Pauses）
   → 02:01:47.213  GC Pause (G1 Full Collection)  1,842 ms   ← ★ 1.8 秒的 Full GC
   → 02:01:52.901  GC Pause (G1 Full Collection)  1,655 ms
   → 02:01:58.330  GC Pause (G1 Full Collection)  1,710 ms
   三次，每次 1.6~1.8 秒，间隔 5~6 秒

2. 那 1.8 秒里应用线程在干嘛（Java Application → Java Thread Statistics）
   → 所有 http-nio 线程在这 1.8 秒内 CPU 时间 = 0（全被 STW 挂起）

3. 谁在制造垃圾（Memory → Allocation by Site / TLAB 外分配）
   → com.example.sync.FullSyncJob.run()            分配了 3.2 GB
      └→ ArrayList.grow()                            ← 大 List 扩容

根因

// ❌ 批处理任务：一次性把 50 万条数据全加载进内存
@XxlJob("fullSyncJob")
public void run() {
    List<OrderDTO> all = orderMapper.selectAll();   // 50 万条，一次性装进 ArrayList
    // ArrayList 扩容时要在老数组和新数组之间反复拷贝，产生大量临时对象
    for (OrderDTO order : all) {
        syncToEs(order);      // 每条还要 new 一个 ES 的请求对象
    }
}

因果链：

50 万条 DTO 一次性进堆（约 3.2GB）
  → 年轻代装不下，直接晋升老年代
  → 老年代被顶满，G1 触发 Full GC
  → 1.8 秒 STW，所有业务线程被挂起
  → 恰好在这 1.8 秒内进来的请求，全部超过 2 秒超时阈值
  → 白天没有这个任务，所以永远不复现

为什么”日志里没有任何异常”？ 因为那些请求最终都成功了 —— 它们只是被 STW 挂起了 1.8 秒，恢复后继续执行完。应用层的超时是网关侧的，服务端完全感知不到。

修复

// ✅ 方案一（推荐）：MyBatis 游标（ResultHandler），流式处理，内存占用恒定
@XxlJob("fullSyncJob")
public void run() {
    // 注意三个条件：ResultSetType=FORWARD_ONLY + fetchSize=Integer.MIN_VALUE + ResultHandler
    orderMapper.scanAll(new ResultHandler<OrderDTO>() {
        @Override
        public void handleResult(ResultContext<? extends OrderDTO> ctx) {
            OrderDTO order = ctx.getResultObject();
            syncToEs(order);          // 处理完这条，它就可以被 GC 了
            // 注意：不要在这里面做批量缓存，否则又变成一次性加载
        }
    });
}

<!-- Mapper 里：关键是 fetchSize="-2147483648"（Integer.MIN_VALUE），它让 MySQL 驱动走流式读取 -->
<select id="scanAll" resultType="com.example.order.OrderDTO"
        fetchSize="-2147483648" resultSetType="FORWARD_ONLY">
    SELECT * FROM order_item WHERE sync_status = 0
</select>

// ✅ 方案二：手动分页（更简单，但没有游标优雅）
int pageSize = 1000;
long lastId = 0;
while (true) {
    List<OrderDTO> batch = orderMapper.selectByPage(lastId, pageSize);
    if (batch.isEmpty()) break;
    batch.forEach(this::syncToEs);
    lastId = batch.get(batch.size() - 1).getId();
}

另外两个防御性改动：

# 1. 限制批处理任务的堆使用：给它一个独立的、小堆的实例（或者用 -XX:MaxRAMPercentage 隔离）
# 2. 加监控：GC 停顿时长应该是 P99 告警的一部分，而不只是看 GC 次数

教训

大结果集必须流式处理。 List<DTO> 一次性加载是 Java 里最常见的内存炸弹。判断标准：如果这个 List 的元素数量会随业务增长而增长，就必须改成流式或分页
GC 停顿会直接体现在接口 P99 上。 你的服务”没有慢 SQL、没有慢下游、CPU 也不高”，但 P99 有毛刺 —— 第一反应应该是 GC
“日志里没有异常”不等于”系统正常”。 JVM 层面的问题（STW、JIT 去优化、锁膨胀）在应用日志里是完全隐形的。你必须监控 JVM 本身的指标（GC 停顿时长、安全点停顿、JIT 编译时间），而不只是应用指标
偶发问题的解法是常开录制，不是守株待兔。 JFR 的常开开销 < 1%，这个代价换”事后能回放”的能力，是笔极划算的交易
批处理任务应该和业务请求隔离（独立的实例 / 独立的线程池 / 独立的堆）。让一个内部任务影响用户可感知的 P99，是架构问题而不只是代码问题

三个案例的共同模式

回头看这三个案例，它们的排查路径其实是同一个形状：

现象分类（性能 / 内存 / 偶发）
   ↓
先排除便宜的（看监控、看日志，5 分钟内排除 3 个假设）
   ↓
用工具拿到"证据"而不是"感觉"（thread -b / jmap -histo / JFR）
   ↓
证据指向一个具体的类 + 行号
   ↓
读那行代码，理解它为什么会有这个行为（而不是"看起来能不能改"）
   ↓
修复 + 验证（验证这一步不能省）

注意倒数第二步：三个案例的根因代码，单看那一行都是”能跑的”。synchronized 里查数据库、静态 Map 缓存、List 装 50 万条 —— 它们在数据量小的时候全都是对的。问题不在代码，在代码和它所处环境的假设不匹配。

这就是为什么”先定位后修复”是硬性原则：你不理解那行代码为什么会在当前条件下出问题，你的修复就只是在挪动问题。

徐术挺-漫思录

探索

05-分布式链路与实战案例

第 08 章（节选）　分布式链路与实战案例

08.6 分布式链路追踪：从”哪个服务”到”哪个请求”

TraceId / SpanId 的传播机制

工具选型

可观测性三支柱

08.7 实战：三个完整的排查案例

案例一（性能）：接口 P99 从 50ms 涨到 3s

案例二（内存）：服务每天重启一次才不 OOM

案例三（偶发）：每天凌晨 2 点左右少量超时

三个案例的共同模式

目录

反向链接

徐术挺-漫思录

探索

05-分布式链路与实战案例

第 08 章（节选） 分布式链路与实战案例

08.6 分布式链路追踪：从”哪个服务”到”哪个请求”

TraceId / SpanId 的传播机制

工具选型

可观测性三支柱

08.7 实战：三个完整的排查案例

案例一（性能）：接口 P99 从 50ms 涨到 3s

案例二（内存）：服务每天重启一次才不 OOM

案例三（偶发）：每天凌晨 2 点左右少量超时

三个案例的共同模式

目录

反向链接

第 08 章（节选）　分布式链路与实战案例