给 AI 应用做可观测：日志、链路追踪、成本归因

AI 应用出问题时，我最怕听到的一句话是"你重启一下试试"。

因为模型这层天然是黑盒：同样的输入，输出可能因为采样参数、模型版本、上下文顺序而完全不一样。普通后端那套"看日志、查链路"的手段用到 AI 应用上会立刻失灵——你看到的信息全是"调用成功，耗时 2.3 秒"，然后就没了。

这篇是我最后收敛出来的三件事。

一、日志：别记 prompt，记"这次调用的指纹"

我一开始老老实实把完整的 prompt 和 completion 都打进日志。结果两个问题。

第一个是体积。一条日志几十 KB，一天下来几个 GB，检索成本和存储成本都吃不消。

第二个更要命：记下来的日志对排查几乎没用。Prompt 上千行，你翻到里面也看不出问题在哪。

现在的做法是记"指纹"——能定位问题，但不泄露内容：

import hashlib, json, time

def log_llm_call(req_id, *, model, messages, response, usage, latency_ms):
    prompt_text = json.dumps(messages, ensure_ascii=False)
    fingerprint = hashlib.sha256(prompt_text.encode()).hexdigest()[:16]

    logger.info("llm_call", extra={
        "req_id": req_id,
        "model": model,
        "prompt_fp": fingerprint,
        "prompt_chars": len(prompt_text),
        "prompt_tokens": usage.prompt_tokens,
        "completion_tokens": usage.completion_tokens,
        "finish_reason": response.finish_reason,
        "latency_ms": latency_ms,
        "retrieval_hits": len(response.contexts or []),
    })

几个字段值得解释一下。

prompt_fp 是关键。它把"这次调用的输入"变成一个稳定的短字符串。用户报告"它答错了"，你拿到他的输入算一次指纹，就能在日志里精确定位到那一次调用——不用把 prompt 内容存下来。同一个指纹说明输入完全一致，那么输出差异必然来自模型版本或采样参数。

finish_reason 经常被忽略但极其有用。它是 stop 还是 length，决定了"答案被截断了"这类问题。AI 应用里"说一半就没了"是高频故障，根因往往就是 finish_reason=length，日志里不记这个就只能靠猜。

retrieval_hits 是检索命中数。检索为空时模型会开始编造，这个字段为 0 加上 finish_reason=stop，基本能确定是幻觉起点。

我还加了一个不记内容但一定要记的字段：

"cache_hit": response.usage.cache_read_tokens > 0,

因为提示缓存的命中与否，直接决定了这次调用的成本差好几倍。

二、链路追踪：把一次请求切成有意义的段

普通的 tracing 想法很简单，一个 HTTP 请求一个 span。AI 应用不行，一次请求里面藏着十几次模型调用。

我的切分方式是按语义切，不是按调用切：

http.request
├── retrieval.embed          ← 检索向量化
│   └── llm.embed            ← 嵌入模型调用
├── retrieval.search         ← 向量库查询
├── retrieval.rerank         ← 重排
├── llm.generate             ← 主生成
└── llm.postprocess          ← 后处理

每个段记录四个数：耗时、输入量、输出量、是否命中缓存。

这个切法的好处是能算出每一段占了多少成本。我拿自己的数据算过：

看完这张表才明白，重排占了 9% 的时间但一点 token 都没花，而主生成占了 76%。优化方向立刻清楚：先砍主生成的 prompt 长度，重排那 210ms 可以异步化。

如果按"每次模型调用一个 span"来切，你看到的是十几条时长差不多的 span，什么结论都得不出。

三、成本归因：token 是唯一需要归因的"钱"

传统上归因成本是按请求数、CPU 时间、存储量。AI 应用里这些都不是主要成本，token 才是。

我的归因模型是四层，从粗到细：

L1 和 L2 是静态的，跟着代码走。L3 需要从请求上下文里带出来。L4 是模型调用时的实测值。

具体的实现方式是在调用链路上挂一个上下文对象：

class CostContext:
    def __init__(self, request):
        self.app = "knowledge-qa"
        self.feature = request.headers.get("X-Feature", "default")
        self.tenant = request.headers.get("X-Tenant", "unknown")
        self.usage = {"prompt_tokens": 0, "completion_tokens": 0, "calls": 0}

    def merge(self, usage):
        self.usage["prompt_tokens"] += usage.prompt_tokens
        self.usage["completion_tokens"] += usage.completion_tokens
        self.usage["calls"] += 1

merge 这一步不能省。真实的调用链是"改写 → 嵌入 → 生成 → 重写"，可能调了三次模型。如果只记最后一次，你的成本归因会少算一半以上。

反直觉的一点：最贵的往往不是模型输出

我一开始盯着 completion token 做优化，因为输出看起来更"贵"。

把数据拉出来之后发现不是这样：

输入 token 数量比输出还多，而且单价更低，总占比压倒性领先。真正的问题在检索端——每次塞进去 5 个 chunk，每个 600 token，而且大部分内容跟问题无关。

优化方向从"让模型少说话"变成了"少塞文档进去"。后者效果好了十倍，而且用户完全感知不到。

落地时的几个取舍

采样率要分情况。 全量采集日志和链路开销不小——一次请求产生十几条 span，采样 100% 时存储和 CPU 压力都不小。我的规则是：成功请求采样 1%，失败和慢请求采样 100%，超过 P95 阈值就全留。

成本指标不要放链路里，要放指标系统。 span 是有成本的（存储 + 索引），token 累计值应该打成 metric，按天按租户聚合。一个租户一天一个数据点，比一天一百万条 span 有用得多。

别指望链路追踪能回答"为什么模型答错了"。 这超出了可观测的范畴。链路能告诉你"检索返回了什么、prompt 长什么样、用了哪个模型版本"，但模型内部推理过程看不到。想复现问题，最有效的手段是把失败样本存下来，配上当时的输入输出，在本地重放。

我最后保留的三样东西

如果只能留三样：

1. 带指纹和 usage 的结构化日志 —— 排查问题的地基
2. 按语义分段的链路 —— 告诉你时间花在哪
3. 按租户的 token 日计 —— 回答"钱花到哪了"

前两样让你能修 bug，第三样让你能跟人谈预算。缺第三样的话，AI 应用的花销永远是个黑箱，到月底只能看着账单发愁。

日志和链路的后端选择有很多，各家的采样和保留策略差别很大；上面讲的是切分和归因的思路，具体产品以官方文档为准。