事情本身不复杂,线索都在日志里。一条 trace 里网关 span 显示 1.2 秒,模型调用 span 显示 2.4 秒,子 span 比父 span 还长,看板上延迟指标和用户体感完全对不上。
第一反应是「网关的重试产生了同名 span,被合并计算」,验证下来不成立。
原因不止一个,得分开看。父子 span 用了不同机器的本地时钟。也可能是异步回调里 span 的结束时间在另一个线程打的。
少数情况下是时钟没有做 NTP 同步,偏差到秒级。
上来先看同一 trace 里各 span 的起止时间
python -c "import json;t=json.load(open('trace.json'));print([(s['name'],s['start'],s['end']) for s in t['spans']])"
随后把耗时改成基于单调时钟计算
python -c "import time;print(time.monotonic())"
给重试的 span 加 attempt 标签
python -c "print('span_attr=attempt')"
跨机比对时间偏差
python -c "print('ntp_offset_ms')"
同样的操作我在测试机上先走了一遍,线上只做验证过的部分。
改完先别撤,确认这几项。子 span 的耗时全部落在父 span 区间内,同一 trace 的总耗时与网关日志误差在 5 毫秒内。
容易忽略的是,跨机 trace 不能直接用本地时间相减,得用单调时钟加时钟偏移校正;重试不区分 attempt 的 span 会让延迟看起来翻倍。改动前把原配置备份一份,出问题能马上回滚,这比任何技巧都实用。
