下单接口实际耗时 1.1 秒,追踪里这条 span 只有 320 毫秒。慢调用榜单里它一直排不进去,APM 上的 P99 是 400 毫秒,用户侧监控是 1.2 秒。碰到这种情况,我一般先确认改动有没有真的生效。

原因不复杂,span 在方法返回 CompletableFuture 时就被关闭,后面的回调在另一个线程继续跑。异步段没有挂到父 span 上,耗时自然不计入。线程池里的回调又新建了独立 trace,看单条链路完全对不上。

碰到「异步 span 提前结束」这类问题,我习惯先把当前配置原样备份一份,改坏了立刻换回来,不用现场推。改完顺手把文档补一句,省得下次自己重新推一遍。

Span span = tracer.nextSpan().name("order.async").start();
try (Scope ws = tracer.withSpanInScope(span)) {
  return queryAsync().whenComplete((r, e) -> span.finish());
}

监控和日志的时间要对上,时区不一致会多绕很大一圈。

具体做法是,把 span 的结束点移到 whenComplete 里 别在方法返回时关闭;回调里用 Scope 恢复父上下文 保证子 span 挂对位置;线程池统一用包装过的 executor 传递上下文;造一个 800 毫秒的异步查询 核对 span 时长。

最后用这个标准收尾,追踪里的 span 时长和用户侧监控的 1.1 秒对得上,慢调用榜单能查到这条。

作者 9823189