title: 平均 RT 200ms 但用户抱怨卡可观测性三支柱怎么把隐藏的 2 秒揪出来date: 2026-08-31tags: [可观测性, 链路追踪, 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定义指标名关键在serviceLevelObjectivesSLO它把耗时切成 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 userId8821 cost1803ms [INFO] 2026-08-30 14:22:01 OrderService.create orderId9921 cost1902ms两段日志时间接近但你看不出它们是不是同一次请求。后来我们统一用 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); // 异常也记进 spantrace 里能看到红点 throw e; } finally { span.end(); // 必须 end否则 span 不关闭、链路断在半路 }逐行解释- 第 2 行spanBuilder(queryUserTags)创建一个名为查询用户标签的 spansetSpanKind(CLIENT)标记它是一次客户端调用比如调 Redis/下游。- 第 3 行makeCurrent()把 span 设为当前上下文内部的子调用会自动挂到它下面形成父子关系。- 第 7 行recordException(e)把异常绑到 span在 Jaeger 里这个 span 会标红一眼看出哪里炸了。- 第 10 行span.end()千万别漏漏了 span 永远不结束链路图就断在这我们排查时因此浪费过一上午。三支柱怎么配合支柱回答的问题典型工具数据量保留时长指标系统整体健康吗Prometheus Grafana小聚合数月日志具体哪行出错ELK / Loki大明细数天~数周链路一次请求经过哪Jaeger / OTel中数天三者的连接点是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 可观测性旧文使用不同事故场景未复用旧文。