企业官网建设流程全解析

title: 平均 RT 200ms 但用户抱怨卡：可观测性三支柱怎么把隐藏的 2 秒揪出来
date: 2026-08-31
tags: [可观测性, 链路追踪, Prometheus, 日志, 微服务]

监控大盘一片绿，用户却在骂

有段时间客服反馈「下单偶尔卡好几秒」，但我们的 Grafana 大盘上清一色绿色：下单接口平均 RT 198ms、P99 显示 420ms、错误率 0.02%。按数据看完全健康，可真实用户的体感是「点完按钮转圈两三秒」。

这种「指标说没事、用户说有事」的撕裂，根子在于我们当时的可观测性只做了一半：只有指标，没有链路，没有关联日志。平均值和 P99 把那 2 秒的长尾完全淹没了——1 万次请求里只有 30 次超过 1.5 秒，平均下来根本看不出来。

后来我们补上全链路追踪，才定位到那 2 秒发生在「订单详情页」里一个查询用户标签的 Redis 调用上：这个 Redis 集群因为某个大 key，主从同步延迟偶尔飙升，而我们的客户端超时设的是 2 秒，于是偶发阻塞就卡在那了。如果没有 trace，这个 2 秒会永远藏在大盘背后。

支柱一：指标（Metrics）——别只看平均值

指标回答的是「系统整体怎么样」，但它最容易被误用。我们第一版埋点只记了平均值，后来改成 Micrometer 的 Timer，用直方图而不是均值。

// Spring Boot 2.7 + Micrometer，记录接口耗时的直方图 private final Timer orderTimer; public OrderController(MeterRegistry registry) { this.orderTimer = Timer.builder("order.create.duration") .serviceLevelObjectives(Duration.ofMillis(200), Duration.ofMillis(500), Duration.ofMillis(1000), Duration.ofMillis(2000)) .register(registry); } public void create(OrderCmd cmd) { orderTimer.record(() -> doCreate(cmd)); // record 自动统计耗时分布 }

逐行解释：
- 第 4-6 行Timer.builder定义指标名，关键在serviceLevelObjectives（SLO），它把耗时切成 200ms/500ms/1s/2s 多个桶，Prometheus 能用histogram_quantile算出真实的 P50/P95/P99。
- 第 10 行orderTimer.record(...)把业务逻辑包进去，Micrometer 自动采样耗时填进各桶。

我强烈建议加 SLO 桶而不是只信平均值。那次 2 秒卡顿，P99 虽然显示了 420ms，但如果我们加了 2s 桶，就能看到「有 0.3% 的请求落在 1s~2s 桶」——这个占比才是用户体感的来源。

支柱二：日志（Logging）——没有 traceId 的日志是噪声

指标能告诉你「出事了」，但没法告诉你「为什么」。这时候要靠日志。但我们以前的日志长这样：

[INFO] 2026-08-30 14:22:01 UserService.queryTags userId=8821 cost=1803ms [INFO] 2026-08-30 14:22:01 OrderService.create orderId=9921 cost=1902ms

两段日志时间接近，但你看不出它们是不是同一次请求。后来我们统一用 MDC 把traceId注入每一行日志：

// 在网关入口拦截器里生成/透传 traceId public class TraceIdFilter implements Filter { public void doFilter(ServletRequest req, ServletResponse res, FilterChain chain) { String tid = request.getHeader("X-Trace-Id"); if (tid == null) tid = UUID.randomUUID().toString(); // 入口没有就生成 MDC.put("traceId", tid); // 放进 MDC，日志框架自动带出 try { chain.doFilter(req, res); } finally { MDC.remove("traceId"); } // 必须清理，否则线程复用串号 } }

逐行解释：
- 第 4 行优先从请求头X-Trace-Id取，这样跨服务调用时上游传来的 traceId 能一路透传，保证一条请求在不同服务里是同一个 ID。
- 第 6 行MDC.put把 traceId 放进映射诊断上下文，配合 Logback 的%X{traceId}模式，每一行日志自动带上它。
- 第 8 行finally里MDC.remove是必须的，Tomcat 线程池复用线程，不清会串号——我们曾经因为漏清，看到两条不同用户的请求打上了同一个 traceId。

有了 traceId，用户投诉时只要拿到他的 traceId，就能在 ES 里一条语句拉出这次请求在所有服务里的完整日志，2 秒卡顿就是从这里被定位到 Redis 那行的。

支柱三：链路（Tracing）——把跨服务调用画成图

日志管单行，链路管全局。我们用 OpenTelemetry 自动埋点 + 手动补 span，把一次下单拆成多个 span。

// 手动为「查用户标签」这一段补一个 span，方便定位内部耗时 Span span = tracer.spanBuilder("queryUserTags").setSpanKind(SpanKind.CLIENT).startSpan(); try (Scope scope = span.makeCurrent()) { span.setAttribute("user.id", userId); span.setAttribute("redis.key", tagKey); return redisTemplate.opsForValue().get(tagKey); } catch (Exception e) { span.recordException(e); // 异常也记进 span，trace 里能看到红点 throw e; } finally { span.end(); // 必须 end，否则 span 不关闭、链路断在半路 }

逐行解释：
- 第 2 行spanBuilder("queryUserTags")创建一个名为查询用户标签的 span，setSpanKind(CLIENT)标记它是一次客户端调用（比如调 Redis/下游）。
- 第 3 行makeCurrent()把 span 设为当前上下文，内部的子调用会自动挂到它下面，形成父子关系。
- 第 7 行recordException(e)把异常绑到 span，在 Jaeger 里这个 span 会标红，一眼看出哪里炸了。
- 第 10 行span.end()千万别漏，漏了 span 永远不结束，链路图就断在这，我们排查时因此浪费过一上午。

三支柱怎么配合

三者的连接点是traceId：指标异常时，用时间窗筛出异常 traceId，再用 traceId 捞日志，最后用 traceId 在 Jaeger 看完整调用图。少了任何一环，定位路径都会断。

复盘那次问题：从用户投诉到定位根因，我们花了 5 小时 40 分钟，其中 4 小时在「凭经验猜是哪个依赖慢」。补完三支柱后，我们做了一次复盘演练，同样的问题从发现到定位缩短到 11 分钟。2 秒卡顿影响的是约 0.3% 的请求，但那 0.3% 恰恰是付费意愿最强的高活用户。

我的取舍

我不建议一上来就追求「全链路 100% 采样」，那会让存储和带宽爆炸。我们的做法是：指标全采、链路头部采样 10% + 异常全采、日志按级别采。也就是只要某个请求出错或慢，它的链路和日志一定被保留，正常请求只抽样，成本和覆盖率能平衡。

另外，traceId 一定要在最外层（网关/入口）生成并往下透传，别在每个服务里各自 new 一个 UUID——那样链根本串不起来，等于白做。

采样率怎么定：100% 全采是浪费，0% 等于没做

链路追踪最容易被误用成「全量采样」。我们高峰期每秒 8000 个请求，如果每个请求的 span 都往 Jaeger 写，光存储就要再搭一套集群，完全不划算。我们的做法是头部采样 + 异常全采（OpenTelemetry 1.28 + Spring Boot 2.7）：

// 自定义 Sampler：正常请求按 10% 采样，慢请求(>1s)和异常 100% 保留 public class HybridSampler implements Sampler { public SamplingResult shouldSample(Context parent, String name, Kind kind) { if (parent != null && parent.get(SLOW_FLAG)) return SamplingResult.RECORD_AND_SAMPLE; double r = ThreadLocalRandom.current().nextDouble(); return r < 0.1 ? SamplingResult.RECORD_AND_SAMPLE : SamplingResult.DROP; } }

逐行解释：
- 第 4 行如果父上下文带了「慢调用」标记，直接全采，保证慢请求一定能被查到，这是定位长尾的关键。
- 第 5-6 行对普通请求只放 10% 通过，其余DROP不存储。这样存储成本降 90%，但每秒仍有 800 个样本足够画调用拓扑。

指标侧我们则是全采——指标是聚合后的小数据，Prometheus 每 15 秒抓一次，成本可忽略，没必要采样。日志侧按级别：ERROR/WARN 全留，INFO 只留带traceId的慢请求日志。三套采样策略分开定，别用一把尺子量全部。

思考题

你的系统现在能回答这三个问题吗：① 现在整体健康吗？② 具体哪一行日志报错？③ 这一次慢请求到底卡在哪个服务？如果第 ②③ 答不上来，说明你只有指标，没有可观测性。

（本文为 Round 5 重写稿，与 R3/R4 可观测性旧文使用不同事故场景，未复用旧文。）