客户端测的时间与服务端测的时间

一句话总结

对外发出的调用要从两边测量。客户端跨度与服务端跨度的差值，就是“在服务端之外花掉的时间”，如果不把这段时间纳入跨度边界，用户感受到的慢就不会出现在跟踪里。

为什么需要它

故障会议上最常见的僵局就是这个。下游团队说“我们的 p99 是 20ms”，上游团队说“我们测出来是 300ms”。双方看的都是自己的仪表板，也都没错。只是测量的区间不同。

服务端测的是请求 handler 打开着的时间。在这之前，有获取连接、序列化请求、发送字节、在对方的线程池里等待排队的时间；在这之后，有接收响应并反序列化的时间。这段只有在客户端才能看到的区间，往往是用户实际等待时间的大部分。

更糟的是连接池等待。连接池空了的话，调用还没发出就要等待，而很多埋点是在从池里拿到连接之后才开始跨度。这样，这段等待就不在任何一个跨度里。跟踪里只有一排 30ms 的调用，根跨度却是 2 秒。人盯着“空白区间”，找不到原因。

工作原理

OpenTelemetry 对发出的调用使用 SpanKind.CLIENT，对接收一方使用 SpanKind.SERVER。这两个在一条跟踪中以父子关系相连，是从不同视角测量同一个逻辑工作的一对。把两个跨度的时间差减出来，就是本实验的出发点。

边界划在哪里，是设计的关键。规则可以写成一条——从调用方开始等待响应的瞬间，到响应拿到手的瞬间，就是 CLIENT 跨度。为获取连接而等待的时间、重试之间休息的时间，都必须在其中，才会等于用户经历的时间。对于重试，让每次尝试各有一个子跨度、外层跨度覆盖整体的形态，读起来最清晰。

被中断的调用，配对会错位。客户端在 120ms 时放弃，服务端却把 400ms 干完。这样，同一条跟踪里会同时留下一个 120ms 的 CLIENT 跨度和一个 400ms 的 SERVER 跨度。认不出这种形态，就会把“服务端跨度比父级还长”误认为埋点 bug。实际上它是资源在泄漏的信号——服务端还在继续生成没有人会读的响应。

取消必须与错误区别开来记录。用户关闭标签页导致连接断开，不是服务的失败。把状态升为 ERROR，错误率就会随着用户的行为起伏，用这个指标设的告警会在凌晨把人叫醒。OpenTelemetry 的跨度状态约定 把状态分为 Unset、Ok、Error 三种，是否升为错误由埋点的一方决定。取消的话，保持状态不变，用属性和事件来记录，更容易处理。

属性设计是基数问题。写发出调用的目标时，如果把地址原样放进去，订单 ID 和 Pod 后缀就会混进值里。Semantic Conventions 的 RPC 约定 把 rpc.service 和 rpc.method 分开设置，原因就在这里——哪个服务的哪个操作，值的种类少，这样才能聚合。ID 不作为属性值，而是在需要时下沉到事件或日志中。

在转储文件上计算关键路径或重复调用的方法，由本学习路径中的其他实验讲解，发出的请求头里放什么，由认证课程中的上下文边界实验讲解。这里做的是两者之间的事——为了让那些计算成立，在发出一侧，跨度要从哪里划到哪里、要附上什么。

最后，一个请求多次调用同一个目标这件事，必须有客户端跨度才看得见。只给服务端埋点，下游只是散落着六个跨度，这些调用出自一个请求这一事实，在上游跟踪里并不会显现。把目标和操作作为低基数属性附上，统计同一对目标和操作发出了多少次，就变成一行查询。

在现场相遇的样子

调查支付延迟时见过这样的跟踪。根是 1.8 秒，把子跨度全加起来也只有 0.4 秒。剩下的 1.4 秒不在任何一个跨度里。原因是连接池大小是 2，而一个请求要调用下游八次。因为埋点是在拿到连接之后才开始跨度，等待时间整个消失了。把跨度开始的位置挪到获取连接池之前，这个只有三行的改动让那 1.4 秒出现在了画面上，这时讨论才从“为什么慢”转到“是扩大池，还是减少调用”。

在另一个服务里，反过来是超时在掩盖问题。客户端超时是 200ms，所以仪表板上的 p99 总是贴在 200ms 上。把服务端一侧的跨度一起看，同一条跟踪里留着一个 1.2 秒的 SERVER 跨度。客户端放弃了，服务端还在继续工作，这些堆积的工作让后续的请求更慢。一条统计配对错位的跨度对的查询，成了打断这个循环的依据。

下一项实验要做什么

同一个调用，在客户端和服务端两边测量，求出差值，再把这个差值拆成排队时间和其余部分。把连接池等待放在跨度之外和放进跨度之内两种情况并排做出来，看看同一件事会显得多么不同。在两个转储文件里找出因超时而中断的调用的配对，并确定把取消的调用与错误区别开来记录的规则。接着把目标标识属性设计成低基数，亲手数一数值的种类，仅凭客户端跨度就把一个请求六次调用同一个目标的情况显现出来。最后把这套规则写成文件，原样应用到第二个客户端上。