LLM Ops 评测与可观测实战（5）：LLM 调用链追踪：从请求到 token 的全链路观测

CodexDave

260人浏览 · 2026-10-10 09:48:46

CodexDave · 2026-10-10 09:48:46 发布

问题背景

上一篇把坏变更拦在了发布门口，但门禁只能保证"上线前已知的好"，挡不住"上线后才暴露的怪"。场景回到那个客服 RAG 机器人：产品经理甩来一条用户反馈——“我问退款进度，它答非所问”，附带一个会话 ID。接下来的三十分钟里你要回答：这条请求当时检索到了哪三份文档？rerank 把它们排成了什么顺序？两次模型调用各自的输入输出是什么？工具查订单接口返回了什么？答案如果都在日志里，排查是一分钟的事；如果只在同事的回忆里，就是一天的事。调用链追踪（tracing）就是把一次请求穿过的所有环节记成一棵树：每个环节一个 span，带起止时间、父子关系、结构化属性，事后按 trace ID 一键还原现场。本篇讲追踪的数据模型与属性规范、流式输出的特殊记账，以及一个最费钱的工程决策——trace 采样：全采存不下，随机采又恰好丢掉最有价值的那部分。

核心原理

**span 模型：时间树 + 属性袋。**每个 span 携带 trace ID、span ID、父 ID、起止时间戳，以及一组键值属性。LLM span 的属性集比传统 RPC 丰富得多：模型名与版本参数（temperature、top_p）、完整 prompt 与补全文本（脱敏后）、输入/输出 token 消耗、缓存命中情况、停止原因（正常结束还是截断）；检索 span 带查询串、命中片段 ID 与分数；工具 span 带调用参数与返回码。跨进程用 W3C trace context 传播 trace ID，网关、编排服务、向量库、模型网关打到同一条链上。OpenTelemetry 已为生成式调用制定了语义约定（GenAI semantic conventions），属性命名尽量对齐它，别自造方言——方言的代价是每个看板、每个分析脚本都要重写一遍。

**LLM 应用追踪区别于传统追踪的三个点。**第一，payload 是主角：传统 APM 记时间就够，LLM trace 不看输入输出内容等于没追，"慢"往往是小概率事件，"错"才是常态问题；这带来隐私与存储的双重压力，脱敏和分级存储是前置功课。第二，流式输出要记两笔账：首 token 时延（TTFT）决定体感，整链完成时延决定成本，二者要分别在 span 上打点，只看端到端会把"模型开始吐字前的等待"和"吐字过程"混成一团。第三，非确定性使得"复现"依赖完整现场：prompt 版本号、few-shot 快照、检索文档 ID 列表必须进 span 属性，否则拿着输入也拼不回当时的输入。

**采样：价值密度极不均匀，随机抽样是懒惰的公平。**一次 LLM 请求动辄几 KB 的 prompt 与补全文本，全量留存等于把用户对话整体镜像一份进自己的数据库。但 trace 的价值服从"错误与慢查询优先"：一个 2.6 秒带工具重试的失败请求，信息量顶得上一百条 1.4 秒的成功请求。实践中的混合策略是：错误与超阈值的 trace 强制全采、其余按路由/租户分层随机采样兜住统计口径、再对头部采样命中的 trace 做父子完整性修复（尾部采样需要在采集端做缓冲与决策，这是架构上最贵的一块）。

实验一：把一条请求的 span 树立起来

本机以确定性模拟演示（固定种子），生产环境按 OpenTelemetry SDK 真实打点。

import random

rng = random.Random(42)

def lat(mu, sig):
    return max(1.0, rng.gauss(mu, sig))

spans = []

def add(name, parent, start, dur):
    spans.append({"name": name, "parent": parent, "start": start, "dur": dur})
    return len(spans) - 1

t = 0.0
root = add("request", -1, 0, 0)
t += lat(6, 2)
i = add("route_classify", root, t, lat(42, 9)); t += spans[i]["dur"] + lat(3, 1)
t += lat(4, 2)
retr = add("retrieval", root, t, 0)
retr_start = t
i = add("embed_query", retr, t, lat(35, 6)); t += spans[i]["dur"] + lat(2, 1)
i = add("vector_search", retr, t, lat(58, 12)); t += spans[i]["dur"] + lat(4, 2)
i = add("rerank", retr, t, lat(190, 40)); t += spans[i]["dur"]
spans[retr]["dur"] = t - retr_start
t += lat(3, 1)
i = add("prompt_assemble", root, t, lat(12, 3)); t += spans[i]["dur"] + lat(5, 2)
i = add("llm_call(function_pick)", root, t, lat(430, 90)); t += spans[i]["dur"] + lat(260, 30)
i = add("tool:order_api", root, t, lat(310, 70)); t += spans[i]["dur"] + lat(8, 3)
i = add("llm_call(answer_gen)", root, t, lat(1180, 220)); t += spans[i]["dur"] + lat(5, 2)
i = add("output_guard", root, t, lat(22, 5)); t += spans[i]["dur"]
end = t + lat(15, 4)
spans[root]["dur"] = end

children = {}
for idx, sp in enumerate(spans):
    if sp["parent"] >= 0:
        children.setdefault(sp["parent"], []).append(idx)

def show(idx, depth=0):
    sp = spans[idx]
    kids = sorted(children.get(idx, []), key=lambda j: spans[j]["start"])
    self_ms = sp["dur"] - sum(spans[j]["dur"] for j in kids)
    print("%s%s  %.0f ms  (自身+未记账空隙 %.0f ms)" % ("  " * depth, sp["name"], sp["dur"], self_ms))
    for j in kids:
        show(j, depth + 1)

print("trace 树(一次请求, 固定种子=42):")
for idx, sp in enumerate(spans):
    if sp["parent"] < 0:
        show(idx)
print()
print("总耗时 %.0f ms; 两次 llm_call 合计 %.0f ms, 占 %.0f%%。"
      % (spans[root]["dur"],
         sum(sp["dur"] for sp in spans if sp["name"].startswith("llm_call")),
         sum(sp["dur"] for sp in spans if sp["name"].startswith("llm_call")) / spans[root]["dur"] * 100))
print("request 层未记账空隙主要来自 function_pick 之后那段 ~260ms:")
print("模型输出解析与工具调用往返没有子 span 记账, 属追踪盲区, 应补一个 tool_dispatch span。")

运行输出：

trace 树(一次请求, 固定种子=42):
request  2654 ms  (自身+未记账空隙 315 ms)
  route_classify  40 ms  (自身+未记账空隙 40 ms)
  retrieval  282 ms  (自身+未记账空隙 4 ms)
    embed_query  34 ms  (自身+未记账空隙 34 ms)
    vector_search  62 ms  (自身+未记账空隙 62 ms)
    rerank  181 ms  (自身+未记账空隙 181 ms)
  prompt_assemble  13 ms  (自身+未记账空隙 13 ms)
  llm_call(function_pick)  489 ms  (自身+未记账空隙 489 ms)
  tool:order_api  258 ms  (自身+未记账空隙 258 ms)
  llm_call(answer_gen)  1234 ms  (自身+未记账空隙 1234 ms)
  output_guard  22 ms  (自身+未记账空隙 22 ms)

总耗时 2654 ms; 两次 llm_call 合计 1723 ms, 占 65%。
request 层未记账空隙主要来自 function_pick 之后那段 ~260ms:
模型输出解析与工具调用往返没有子 span 记账, 属追踪盲区, 应补一个 tool_dispatch span。

树上一处"自身+未记账空隙 315 ms"值得盯住：request 层比子 span 之和时间多了 315 ms，这几乎全在 function_pick 与 order_api 之间——SDK 没有给"解析模型输出的工具调用参数并发起 HTTP"这段编排逻辑打 span，它就变成树上的黑洞。LLM 应用追踪的第一批工单往往不是模型慢，而是这类记账盲区：网关排队、序列化、重试退避，全都藏在父 span 的"自身时间"里。补 span 的原则：凡是跨网络或跨进程的边界，必须有名字。

实验二：分位数统计与 10% 预算下的采样策略

import random

def pct(vals, p):
    v = sorted(vals)
    k = (len(v) - 1) * p / 100.0
    lo = int(k)
    hi = min(lo + 1, len(v) - 1)
    return v[lo] + (v[hi] - v[lo]) * (k - lo)

rng = random.Random(77)
N = 5000
traces = []                       # (延迟ms, 是否错误)
for _ in range(N):
    base = max(300, rng.gauss(1600, 350))
    has_retry = rng.random() < 0.04          # 工具超时重试
    if has_retry:
        base += rng.uniform(2000, 9000)
    err = rng.random() < (0.09 if has_retry else 0.005)
    traces.append((base, err))

lat = [d for d, _ in traces]
print("端到端延迟分位: p50=%.0f  p95=%.0f  p99=%.0f  p99.9=%.0f (ms)"
      % (pct(lat, 50), pct(lat, 95), pct(lat, 99), pct(lat, 99.9)))
err_lat = [d for d, e in traces if e]
print("错误 trace 共 %d 条, 其中位延迟 %.0f ms; 全体中位延迟 %.0f ms -> 错误强烈偏向慢尾"
      % (len(err_lat), pct(err_lat, 50), pct(lat, 50)))

budget = int(0.10 * N)
random_keep = traces[:budget]                       # 种子已定, 等价随机抽样 10%
tail_keep = sorted(traces, key=lambda x: -x[0])[:budget]   # 按延迟留最慢 10%

def coverage(kept, label):
    te = sum(1 for _, e in traces if e)
    ke = sum(1 for _, e in kept if e)
    print("%-14s 保留 %d 条: 覆盖错误 %d/%d (%.0f%%)"
          % (label, len(kept), ke, te, ke / te * 100))

coverage(random_keep, "随机头部采样")
coverage(tail_keep, "延迟尾部采样")
print("结论: 两种 10% 策略都漏掉大量错误 -> 生产用'错误强制全采 + 慢尾全采 + 其余随机'的混合策略")

运行输出：

端到端延迟分位: p50=1629  p95=2393  p99=8752  p99.9=10526 (ms)
错误 trace 共 36 条, 其中位延迟 2032 ms; 全体中位延迟 1629 ms -> 错误强烈偏向慢尾
随机头部采样         保留 500 条: 覆盖错误 6/36 (17%)
延迟尾部采样         保留 500 条: 覆盖错误 17/36 (47%)
结论: 两种 10% 策略都漏掉大量错误 -> 生产用'错误强制全采 + 慢尾全采 + 其余随机'的混合策略

p99 是 p50 的五倍多，全部来自带工具重试的慢尾；36 条错误里 17 条躺在最慢的 500 条里——尾部采样天然能摸到大半错误，但仍有近五成错误是"快着出错"（比如模型秒回但内容错），它们会同时骗过头部与尾部采样，只能靠"出错必留"的强制规则或事后回捞（应用侧记录错误标记，采集端收到标记后把缓冲中的该 trace 提升为全采）兜住。统计口径上还要防一个陷阱：被采样偏置过的样本不能再直接算分位数——尾部采样保留了所有慢请求，你的 p99 会永远等于最大值；要么分策略加权还原，要么统计类指标改用未采样的 metrics 通道算。

工程接入清单

按依赖顺序落：先在模型网关与编排框架（LangGraph、LiteLLM 一类）接上自动插桩，拿到最粗的树；再补业务 span（路由分类、护栏检查、工具分发），消灭父层空隙；然后定义属性规范（prompt 版本、检索文档 ID、token 开销、TTFT），对齐 OTel GenAI 语义约定；最后接采样策略与存储分级——payload 文本热存 7 天、结构化元数据长存，排查看板配"按用户反馈 ID 直达 trace"的入口，让客服工单系统带上 trace ID 字段。每一步都要有回退开关：追踪是辅助系统，不能成为故障源，SDK 异常必须静默降级而不是阻塞业务线程。

常见陷阱

其一，prompt 与补全明文裸存：trace 库成了全公司隐私等级最高却防护最弱的库，脱敏必须在客户端出口前完成，服务端"事后洗"永远慢一步。其二，把 span 属性当垃圾桶：每条 trace 塞入全部中间文本，存储爆炸、查询变慢，属性只留"定位与复现所需最小集"，全文进对象存储挂链接。其三，流式只记完成时间：没有 TTFT 打点，用户抱怨"卡"你却在 p99 里找不到证据——把"第一个增量包到达"作为独立事件记录。其四，跨异步队列断链：任务进消息队列后没带 trace context，下游开的树与上游认亲失败，一棵链碎成三截——所有跨进程边界显式透传 trace ID。其五，采样后的分位数直接汇报：见实验二，数字好看得像 bug。