使用篇丨链路追踪（Tracing）其实很简单：请求轨迹回溯与多维链路筛选

作者：涯海

在日常生活中，我们可能都经历过以下场景：去医院看病就诊，但预约页面迟迟无法打开；新款手机发布日促销秒杀，下单页面一直卡住转菊花；游戏大版本更新，在线人数过多，导致人物一直在“漂移”。这些问题令产品体验变得非常差，有耐心的同学还会吐槽几句，没耐心的同学早已转身离开。试想一下，作为该系统开发/运维人员，又该如何避免此类问题发生，或者快速定位止损？

关键路径与多条链路对比

本章我们将以业务 Owner（小帅）的视角，逐步了解分布式链路追踪的各种基础用法：小到单次用户请求的异常根因诊断，大到全局系统的强弱依赖梳理，分布式链路追踪都能给予确定性答案。

小帅作为一家电商公司订单中心的业务 Owner，核心 KPI 就是保障创建订单 createOrder 接口的可用性，如响应时延低于 3s，成功率大于 99.9%。一旦该接口可用性出现问题，会直接影响用户下单行为，造成业务资损，进而影响小帅的绩效和年终奖。

但创建订单接口直接或间接依赖多个其他系统服务，如资金、地址、优惠、安全等。一旦某个下游系统服务可用性出现问题，也会造成创建订单失败或超时。为此，小帅特别头痛，每当创建订单接口不可用时，小帅都非常心急，却不知该如何定位根因，只能拉上所有下游接口负责人一起评估，不仅费时费力，低效排查也造成业务损失进一步扩大，经常被老板痛骂。

当小美了解这个情况后，推荐接入分布式链路追踪系统，并通过一系列故障应急案例，指导如何利用 Tracing 定位问题，梳理风险，提前预警，切实提高了订单中心的可用性。小帅经常会遇到各种用户反馈的创建订单超时问题，以往对此类问题颇有些束手无策。不过，接入分布式链路追踪系统后，通过调用链准确回溯超时请求的调用轨迹，小帅就可以轻松定位耗时最长的接口信息，如下图所示，A 接口超时的主要原因是调用 D 接口导致的。

1.png

但如果是下面这种情况，A 调用 B，B 又调用 C。那么，导致 A 接口超时的根因到底是 B 接口，还是 C 接口呢？

2.png

为了区分真正影响用户体验的 Span 耗时，我们先来了解一下关键路径的概念。

关键路径

如果一次 Span 调用有 t 段耗时在关键路径上，那么去掉这 t 段耗时，整条链路的总体耗时也会相应的缩短 t 段时间。 仍以上面那条链路为例，灰色部分表示关键路径，缩短任意关键路径上的耗时都可以减少整体耗时。此时，我们可以判断 A 接口超时的主要原因是 C 接口导致的。

3.png

再来看另一种情况，如果 A 接口同一时间并行调用 B、C、D、E 接口，那么耗时最长的 D 接口就成为关键路径，如下图所示。

4.png

但是，如果我们将 D 接口耗时减少 t1+t2 两段时间，整体耗时却只减少了 t1 段时间，因为，当 D 接口耗时小于 B 接口时，D 接口就不再是关键路径，而是由 B 接口取代。这就好像主要矛盾被大幅缓解后，次要矛盾就变成了主要矛盾。

5.png

综上所述，我们在做耗时性能分析时，应该首先识别出关键路径，然后再做针对性的优化。对于非关键路径上的耗时优化不会对最终的用户体验产生价值。

多条链路对比

单条调用链路只能用来分析各个接口的绝对耗时，而无法得知每个接口的耗时变化情况。但是，绝对耗时长不代表这个接口就一定有问题，比如数据存储接口耗时通常要比单纯的计算接口耗时要长，这种长耗时是合理的，无需特别关注。

因此，在诊断性能退化问题时，我们更应该关注相对耗时的变化。比如获取同一个接口在耗时异常时段与正常时段的多条链路进行比对，从而发现导致性能退化的原因。下图展示了 A 接口的两条不同链路，我们可以清楚的看到，虽然第一条链路的 B 接口耗时要比 C 接口耗时长，但是导致 A 接口整体耗时从 2.6s 涨到 3.6s 的原因，其实是 C 接口的相对耗时变长了 1s，而 B 接口的相对耗时几乎不变。因此，当 A 接口的响应时延超过 3s，不满足可用性要求时，我们应该优先分析 C 接口相对耗时增长的原因，而不是 B 接口。

6.png

我们再来看一个缓存未命中的例子，如下图所示。第一条链路调用了5次数据库，每一次调用的耗时都不算很长，但是 A 接口整体耗时却达到了 3.6s。当我们比对之前未超时的链路时，发现 A 接口并没有调用数据库，而是请求了5次缓存，整体耗时只有 1.8s。此时，我们可以判断 A 接口超时的原因是调用依赖行为发生了变化，原本应该请求缓存的调用变成了请求数据库，很可能是缓存被打满，或者是该次请求的参数命中了冷数据，最终导致了接口超时。

7.png

通过上面两个案例，我们认识到分析性能问题时，不仅需要知道绝对耗时的多少，更要关注相对耗时的变化。当然，有经验的同学如果对自身业务的正常链路形态了若指掌，就可以直接观察异常链路得出结论。

关联信息回溯

通过前面的学习，小帅已经成功掌握了调用链的轨迹回溯能力，可以熟练运用调用链分析性能瓶颈点，快速定位异常的接口。但是，他又遇到了新的困惑，就是找到了异常接口之后，下一步该怎么办？比如 C 接口的耗时从 0.1s 增长到了 2.1s，导致了上游的 A 接口超时。但是仅仅知道这个信息还不够，C 接口耗时增长背后的原因是什么？如何解决这个问题，让它恢复到原来的性能基线？

很多线上问题，很难只通过接口粒度的链路信息定位根因，需要结合更加丰富的关联数据，指导下一步的行动。接下来，我们通过几个案例，介绍几类最典型的链路关联数据，以及相应的用法。

本地方法栈

小帅负责的订单系统，每天上午十点都会有一波周期性的业务峰值流量，偶尔出现一些超时请求，但下游调用耗时都很短，无法判断超时的具体原因，导致这个问题一直悬而未决，为此小帅十分头痛，只好求助小美。正常请求与超时请求的调用链路对比如下图所示。

8.png

由于超时请求链路的相对耗时增长主要是 A 接口本身，因此，小美建议小帅启用慢调用方法栈自动剖析功能，自动抓取超时请求的完整本地方法栈，如下图所示。

9.png

通过本地方法栈，小帅得知超时请求是卡在 log4j 日志框架 callAppenders 方法上，原来 log4j 在高并发场景的同步输出会触发 “热锁”现象，小帅将 log4j 的日志输出由同步模式改为异步模式后，就解决了业务峰值超时的问题。

如果小帅使用的分布式链路追踪系统，并没有提供慢调用方法栈自动剖析功能，也可以通过 Arthas 等在线诊断工具手动抓取方法栈，定位到异常方法后，再考虑将其添加至本地方法插桩埋点中，进行常态化追踪。

自动关联数据

基于分布式链路追踪的框架拦截点，可以自动关联多种类型的数据，比如接口请求的出/入参数，调用过程中抛出的异常堆栈，数据库请求的执行 SQL 等等。此类信息不影响调用链的形态，却会极大的丰富链路的信息，更明确的阐述为什么会出现这样或那样状况的原因。

比如小帅接到上游业务方反馈，某个新渠道的商品下单总是超时，经过排查后发现该渠道订单依赖的数据库调用非常的慢，通过分析 SQL 明细才知道这个数据库调用是获取渠道优惠信息，但没有做渠道过滤，而是全量查询了所有优惠规则，优化 SQL 查询语句后超时问题就解决了。

10.png

自动关联数据通常由分布式链路追踪产品默认提供，用户根据自身的需要选择是否开启即可，无需额外的操作成本。一般情况下，SQL明细和异常堆栈关联建议常态化开启，而记录请求出/入参数需要消耗较大的系统开销，建议默认关闭，仅在需要的时候临时开启。

主动关联数据

小帅的老板希望能够定期分析来自不同渠道、不同品类、不同用户类型的订单情况，并且将订单接口异常排查的能力向一线运营小二开放赋能，提高用户支持效率。正在小帅一筹莫展之际，小美建议小帅将业务信息关联至调用链上，提供业务标签统计、业务日志轨迹排查等能力。

小帅听取了小美的建议后，首先将渠道、品类、用户类型等业务标签添加到分布式链路追踪的 Attributes 对象中，这样就可以分别统计不同标签的流量趋势，时延分布和错误率变化；其次，小帅将业务日志也关联到分布式链路追踪的 Event 对象中，这样就可以查看一次订单请求在不同系统中的业务轨迹与信息，即使是不懂技术的运营同学也能够清晰的判断问题原因，更有效的支持客户，如下图所示。

11.png

由于业务逻辑千变万化，无法穷举，所以业务数据需要用户主动进行关联，分布式链路追踪系统仅能简化关联过程，无法实现完全自动化。此外，自定义标签和业务日志是最常用的两种主动关联数据类型，可以有效地将调用链的确定性关联能力扩展至业务领域，解决业务问题。

综合分析

通过本小节的学习，相信大家已经非常熟悉分布式链路追踪的请求轨迹回溯能力，我们再来整体回顾一下：首先调用链提供了接口维度的轨迹追踪，而本地方法栈可以详细描述某个接口内部的代码执行情况，自动关联数据和主动关联数据在不改变链路形态的前提下，极大的丰富了链路信息，有效指导我们下一步的行动。在一些比较复杂的问题场景，需要结合以上信息进行多角度的综合判断，如下图所示。

12.png

上一小节我们介绍了如何通过调用链和关联信息进行问题诊断，但是，细心的读者可能会有一个疑问，整个系统有那么多的调用链，我怎么知道哪条链路才是真正描述我在排查的这个问题？如果找到了不相符的链路岂不是会南辕北辙？

没错！在使用调用链分析问题之前，还有一个很重要的步骤，就是从海量链路数据中，通过各种条件筛选出真实反应当前问题的调用链，这个动作就叫做链路筛选。那什么叫多维呢？多维是指通过 TraceId、链路特征或自定义标签等多种维度进行链路筛选。每一种筛选条件都是由日常开发/运维的场景演变而来，最为契合当下的使用方式，提高了链路筛选的效率和精准度。

多维度链路筛选

（一）基于链路标识 TraceId 的筛选

提到链路筛选，大家很自然的就会想到使用全局链路唯一标识 TraceId 进行过滤，这是最精准、最有效的一种办法。但是，TraceId 从哪里来？我该如何获取呢？

如何获取 TraceId？

虽然TraceId 贯穿于整个 IT 系统，只不过大部分时候，它只是默默配合上下文承担着链路传播的职责，没有显式的暴露出来。常见的 TraceId 获取方式有以下几种:

  • 前端请求 Header 或响应体 Response：大部分用户请求都是在端上设备发起的，因此 TraceId 生成的最佳地点也是在端上设备，通过请求 Header 透传给后端服务。因此，我们在通过浏览器开发者模式调试时，就可以获取当前测试请求 Header 中的 TraceId 进行筛选。如果端上设备没有接入分布式链路追踪埋点，也可以将后端服务生成的 TraceId 添加到 Response 响应体中返回给前端。这种方式非常适合前后端联调场景，可以快速找到每一次点击对应的 TraceId，进而分析行为背后的链路轨迹与状态。
  • 网关日志：网关是所有用户请求发往后端服务的代理中转站，可以视为后端服务的入口。在网关的 access.log 访问日志中添加 TraceId，可以帮助我们快速分析每一次异常访问的轨迹与原因。比如一个超时或错误请求，到底是网关自身的原因，还是后端某个服务的原因，可以通过调用链中每个 Span 的状态得到确定性的结论。
  • 应用日志：应用日志可以说是我们最熟悉的一种日志，我们会将各种业务或系统的行为、中间状态和结果，在开发编码的过程中顺手记录到应用日志中，使用起来非常方便。同时，它也是可读性最强的一类日志，即使是非开发运维人员也能大致理解应用日志所表达的含义。因此，我们可以将 TraceId 也记录到应用日志中进行关联，一旦出现某种业务异常，我们可以先通过当前应用的日志定位到报错信息，再通过关联的 TraceId 去追溯该应用上下游依赖的其他信息，最终定位到导致问题出现的根因节点。
  • 组件日志：在分布式系统中，大部分应用都会依赖一些外部组件，比如数据库、消息、配置中心等等。这些外部组件也会经常发生这样或那样的异常，最终影响应用服务的整体可用性。但是，外部组件通常是共用的，有专门的团队进行维护，不受应用 Owner 的控制。因此，一旦出现问题，也很难形成有效的排查回路。此时，我们可以将 TraceId 透传给外部组件，并要求他们在自己的组件日志中进行关联，同时开放组件日志查询权限。举个例子，我们可以通过 SQL Hint 传播链 TraceId，并将其记录到数据库服务端的 Binlog 中，一旦出现慢 SQL 就可以追溯数据库服务端的具体表现，比如一次请求记录数过多，查询语句没有建索引等等。

如何在日志中关联 TraceId？

既然 TraceId 关联有这么多的好处，那么我们如何在日志输出时添加 TraceId 呢？主要有两种方式：

  • 基于 SDK 手动埋点：链路透传的每个节点都可以获取当前调用生命周期内的上下文信息。最基础的关联方式就是通过 SDK 来手动获取 TraceId，将其作为参数添加至业务日志的输出中。
  • 基于日志模板自动埋点：如果一个存量应用有大量日志需要关联 TraceId，一行行的修改代码添加 TraceId 的改造成本属实有点高，也很难被执行下去。因此，比较成熟的 Tracing 实现框架会提供一种基于日志模板的自动埋点方式，无需修改业务代码就可以在业务日志中批量注入 TraceId，使用起来极为方便。
基于 SDK 手动实现日志与 TraceId 关联示例

以 Jaeger Java SDK 为例，手动埋点主要分为以下几步：

  1. 打开应用代码工程的 pom.xml 文件，添加对 Jaeger 客户端的依赖（正常情况下该依赖已经被添加，可以跳过）。
<dependency>    
    <groupId>io.jaegertracing</groupId>     
    <artifactId>jaeger-client</artifactId>     
    <version>0.31.0</version> 
</dependency>
  1. 在日志输出代码前面，先获取当前调用生命周期的 Span 对象，再从上下文中获取 TraceId 标识。
String traceId = GlobalTracer.get().activeSpan().context().toTraceId();
  1. 将 TraceId 添加到业务日志中一并输出。
log.error("fail to create order, traceId: {}", traceId);
  1. 最终的日志效果如下所示，这样我们就可以根据业务关键词先过滤日志，再通过关联的 TraceId 查询上下游全链路轨迹的信息。
fail to create order, traceId: ee14662c52387763
基于日志模板实现日志与 TraceId 自动关联示例

基于 SDK 手动埋点需要一行行的修改代码，无疑是非常繁琐的，如果需要在日志中批量添加 TraceId，可以采用日志模板注入的方式。

目前大部分的日志框架都支持 Slf4j 日志门面，它提供了一种 MDC（Mapped Dignostic Contexts）机制，可以在多线程场景下线程安全的实现用户自定义标签的动态注入。

MDC 的使用方法很简单，只需要两步。

第一步，我们先通过 MDC 的 put 方法将自定义标签添加到诊断上下文中：

@Test 
public void testMDC() {     
  MDC.put("userName", "xiaoming");     
  MDC.put("traceId", GlobalTracer.get().activeSpan().context().toTraceId());     
  log.info("Just test the MDC!"); 
}

第二步，在日志配置文件的 Pattern 描述中添加标签变量 %X{userName} 和 %X{traceId}。

<appender name="console" class="ch.qos.logback.core.ConsoleAppender">     
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">         
        <level>INFO</level>     
    </filter>     
    <encoder>         
        <pattern>%d{HH:mm:ss} [%thread] %-5level [userName=%X{userName}] [traceId=%X{traceId}] %msg%n</pattern>         
        <charset>utf-8</charset>     
    </encoder> 
</appender>

这样，我们就完成了 MDC 变量注入的过程，最终日志输出效果如下所示：

15:17:47 [http-nio-80-exec-1] INFO [userName=xiaoming] [traceId=ee14662c52387763] Just test the MDC!

看到这里，细心的读者可能会疑问，MDC 注入不是也需要修改代码么？答案是确实需要，不过好在 Tracing 框架已经提供了简易的关联方式，无需逐行修改日志代码，极大的减少了改造量。比如 Jaeger SDK 提供了 MDCScopeManager 对象，只需要在创建 Tracer 对象时顺便关联上 MDCScopeManager 就可以实现 traceId、spanId 和 sampled 自动注入到 MDC 上下文中，如下所示：

MDCScopeManager scopeManager = new MDCScopeManager.Builder().build(); 
JaegerTracer tracer = new JaegerTracer.Builder("serviceName").withScopeManager(scopeManager).build();

通过 MDC 机制，有效推动了实际生产环境中应用日志与 Trace 链路的关联，你也快动手试试吧。

日志关联 TraceId 的限制有哪些？

并不是所有日志都能够与 TraceId 进行关联，最根本的原因就是在日志输出的时机找不到相对应的链路上下文，这是怎么回事呢？

原来，链路上下文仅在调用周期内才存在，一旦调用结束，或者尚未开始，又或者由于异步线程切换导致上下文丢失等场景，都会无法获取链路上下文，也就无法与日志进行关联了。比如，在应用启动阶段，许多对象的初始化动作都不在请求处理主逻辑中，强行关联 TraceId 只会获取到一个空值。

所以，在实际应用中，如果发现无法在应用日志中输出 TraceId，可以逐一检查以下几点：

  1. 确认类似 MDCScopeManager 初始化的变量注入工作是否完成？
  2. 确认日志模板中是否添加 %X{traceId} 变量？
  3. 确认当前日志是否在某个调用的生命周期内部，且确保链路上下文不会因为异步线程切换导致丢失。

综上所述，我们可以在系统报错时，快速找到关联的 TraceId，再进行整条链路的轨迹信息回溯，最终定位根因解决问题。但是，如果我们由于各种限制还没有完成 TraceId 的关联，那么该怎么办呢？接下来我们来介绍两种不需要 TraceId 的筛选方法。

（二）基于链路特征的筛选

链路特征是指调用链本身所具备的一些基础信息，比如接口名称，请求状态，响应耗时，节点IP、所属应用等等。这些基础信息被广泛应用于各类监控、告警系统。一旦应用出现异常，会根据统计数据先判断出大致的问题影响面，比如在哪个应用，哪个接口，是变慢了还是错误率升高了？

然后，再根据这些基础信息组合筛选出满足条件的调用链路，例如：

serviceName=order AND spanName=createOrder AND duration>5s

这样，我们就可以过滤出应用名称为 order，接口名称为 createOrder，请求耗时大于 5秒的一组调用链路，再结合上一小节学习的单链路或多链路轨迹回溯分析，就可以轻松定位问题根因。

（三）基于自定义标签的筛选

在排查某些业务问题时，链路特征无法实现调用链的精准筛选。比如下单接口的来源渠道可以细分为线上门店、线下批发、线下零售、直播渠道、三方推广等等。如果我们需要准确分析某个新渠道的链路问题，需要结合自定义标签来筛选。

小帅所在的公司新拓展了线下零售模式，作为集团战略，需要重点保障线下零售渠道的订单接口可用性。因此，小帅在下单接口的链路上下文中添加了渠道（channel）标签，如下所示：

@GetMapping("/createOrder") 
public ApiResponse createOrder(@RequestParam("orderId") String orderId, @RequestParam("channel") String channel) { 
... 
// 在链路上下文中添加渠道标签 
GlobalTracer.get().activeSpan().setTag("channel", channel); 
... 
}

每当线下零售同学反馈订单接口异常时，小帅就可以根据 channel 标签精准过滤出满足条件的调用链路，快速定位异常根因，如下所示：

serviceName=order AND spanName=createOrder AND duration>5s AND attributes.channel=offline_retail

（四）一个典型的链路诊断示例

本小节我们介绍了三种不同的链路筛选方式，结合上一小节的请求轨迹回溯，我们来看一个典型的链路筛选与诊断过程，主要分为以下几步：

  1. 根据 TraceId、应用名、接口名、耗时、状态码、自定义标签等任意条件组合过滤出目标调用链。
  2. 从满足过滤条件的调用链列表中选中一条链路查询详情。
  3. 结合请求调用轨迹，本地方法栈，主动/自动关联数据（如SQL、业务日志）综合分析调用链。
  4. 如果上述信息仍无法定位根因，需要结合内存快照、Arthas 在线诊断等工具进行二次分析。

13.png

预告

在完整介绍分布式链路追踪的前世今生及基础概念之后，本文了解了请求轨迹回溯、多维链路筛选场景，接下来的章节我们将继续介绍：

  • 链路实时分析、监控与告警
  • 链路拓扑

更多内容，敬请期待！

posted @ 2023-04-03 11:19  阿里云云原生  阅读(211)  评论(0)  编辑  收藏  举报