用一个 id 串起五个服务
一句话总结
在一个有五个服务的系统中,回答“一个订单不见了”的办法,不是凭时间去猜,而是用每个请求随身携带的 id 把日志行串起来,而现场真正碰到的问题不是没有 id,而是 id 在中间某一处断掉了。
为什么需要它
按时间归并的方法,只有在请求稀疏时才有效。如果每秒进来几十个请求,02:01:08 前后每个服务都会冒出几十行日志,没有依据来挑出哪一行属于这个订单。何况每个服务的时钟稍有不同,连顺序都会看起来颠倒。
所以要在请求开始时生成一个 id,并把它随所有下游调用一起传递。问题是,大家给这个 id 起了各不相同的名字——X-Request-Id、X-B3-TraceId、X-Correlation-Id。厂商一不同,链条就断了。W3C Trace Context 是把名称和格式统一起来的标准,如今几乎所有的跟踪库都使用这个头部。
工作原理
traceparent 是一个定长的值。
00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01
用连字符分开的四段,依次是 version、trace-id、parent-id、trace-flags。当前版本是 00。trace-id 是 16 个字节(小写十六进制 32 个字符),指向整个跟踪,parent-id 是 8 个字节(16 个字符),指向这一个请求。在其他跟踪系统中,parent-id 被称为 span-id。规范写明,两个值全为 0 就无效,无效的 traceparent 必须被厂商忽略(MUST)。parent-id 中混入大写十六进制的情况也一样。
名称在这里容易混淆。我收到的头部中的 parent-id,是调用我的一方的跨度 id;我发出的头部中的 parent-id,是我自己的跨度 id。所以,如果日志里把传入的头部和传出的头部都留下,用这两个值就能原样还原父子关系。这就是跨度树。
trace-flags 是一个 8 位字段。现在只使用 sampled 标志这一个,但规范明确要求,不要把十六进制当作数字来解读并与该值比较,而要使用掩码——不只是 01 是 sampled,09 也是 sampled(00000001 与 00001000 同时开启的值)。Trace Context Level 2 在第二位上增加了 random-trace-id 标志,所以实际上已经开始流通 03 和 02。用 flags == "01" 统计出的数字,已经是错的了。
tracestate 是各厂商的 名称=值 列表,参与跟踪的系统会在左侧添加新的条目。最左端就是当前写入 traceparent 的系统。
日志一侧的约定也与之衔接。OpenTelemetry 日志数据模型在日志记录中设有 TraceId、SpanId、TraceFlags 字段,并写明如果有 SpanId,就应当也有 TraceId(SHOULD)。日志和跟踪用同一个 id 会合,就是在这里。
在现场相遇的样子
断掉。规范写道,中间组件至少要原样传递 traceparent 和 tracestate,不能让跟踪断掉(MUST),但没有做埋点的旧服务、代理、消息队列会直接把头部丢掉。其后的服务因为没有收到头部,会重新开始一个跟踪。屏幕上会出现两条很短的跟踪,而二者之间的关系哪里也找不到。
这时要用的是业务键。如果用订单号、支付单号这类系统本来就带着的值把前后接起来,即使是跟踪中断的区间,也能排成一条线。这并不是完整的解法——业务键在重试时也是同一个值,所以无法指向某一个请求。尽管如此,它足以证明“在哪里断掉的”,而这个证明,就是促使下次部署传递头部的依据。
自身耗时看起来像在说谎。从一个跨度的耗时中减去各子跨度的时间,就得到该服务自己花的时间。但如果某个子跨度没有做埋点而看不见,它的时间就会原样算到父跨度的自身耗时上。“订单服务花了 800ms”这个结论,其实是“订单服务所调用的某个看不见的东西花了 800ms”。自身耗时格外大的跨度,不是元凶,而是下一个要做埋点的位置。
只剩下采样的部分。在大流量下,不会存储所有的跟踪。sampled 被关闭的跟踪,在界面上完全没有,或者只有一部分。如果客户所说的那个订单没有被采样,跟踪工具里什么也没有才是正常的,这时就必须下到日志里去找。
下一项实验要做什么
做出五个服务的日志,把所有 traceparent 拆成四段,把无效的值连同原因隔离起来。找到客户所说订单的 trace-id,把该跟踪的日志行按时间排好,用 parent-id 建立跨度树,求出各跨度的耗时和自身耗时。然后找到头部断掉的服务,用订单号把它前后接起来,用掩码读取 sampled 标志来区分被记录的跟踪和没有被记录的跟踪,最后把调查结果写成报告。评分器会自己重新解析原始文件,并与你的结果进行核对。