15 · 可观测性

⏱ 64 分钟 ｜ 🔭 这一章只管一件事：服务健不健康。「模型准不准」是另一个板块的活

🎯 一句话

出事时你能不能在五分钟内说清「谁、什么时候、调了哪个模型、花了多少、慢在哪一段」—— 这个能力叫可观测性，而它必须在出事之前就装好。

事后再补是补不上的：日志没记的东西，事后没有任何办法把它变出来。

🔭 一、⭐⭐ 先划清一条界

这条界必须先划，否则你会同时做错两件事。

⭐ 为什么必须分开：两套指标的处置动作完全不同。 服务不健康是今晚就要处理的事（回滚、扩容、限流、切备用模型）； 模型退化是一次要花几天的调查（看数据、重训、跑 AB）。 混在一起的代价是双向的：你会在凌晨三点被一个「答得不太好」叫醒， 而一次真正的 5xx 尖峰会淹没在评分噪声里没人管。

⚠️ 交界处怎么判：比如「模型没按格式返回 JSON」算哪边？⭐ 看处置动作 —— 如果你的代码因此抛异常、用户看到报错，它就是本章「错误率按类型分」里的一类，今晚要处理；如果格式是对的、只是内容不够好，那是那边的活。

🧩 二、结构化日志：为什么不能只 print

print 在开发时很好用，上线后有三个致命缺陷：没有级别、时间、来源（只能「全看」或「全不看」）；多进程一起写，顺序错乱、还要靠肉眼分辨哪条属于哪个请求；以及最要命的那条 —— ⭐⭐ 拼进一句话里的东西查不出来：写下 print(f"用户 {u} 花了 {c} 分") 之后，「昨天 u_42 一共花了多少」就变成了一次正则考古。

⭐ 形状：一行一条 JSON，事件名是固定字符串，会变的东西全部进字段。 事件名固定，才聚合得起来（「llm_call 今天有 12000 条，其中 37 条带 error_kind」）； 把变量拼进消息里，等于让每条日志都独一无二，任何聚合都做不了。

一次模型调用该带的字段，每一个都对应一个你迟早要问的问题：

import contextvars, json, logging, sys, time

request_id = contextvars.ContextVar("request_id", default="-")   # ⭐ 每个请求一份，不用手动往下传


class JsonFormatter(logging.Formatter):
    def format(self, record):
        d = {"ts": round(record.created, 3), "level": record.levelname,
             "event": record.getMessage(),        # ⭐ 事件名是【固定字符串】，才聚合得起来
             "request_id": request_id.get()}
        d.update(getattr(record, "fields", {}))   # 业务字段单独放，不拼进消息里
        if record.exc_info:
            d["error"] = self.formatException(record.exc_info).splitlines()[-1]
        return json.dumps(d, ensure_ascii=False)


def get_logger(name="app"):
    log = logging.getLogger(name)
    if not log.handlers:
        h = logging.StreamHandler(sys.stdout)     # ⭐ 打到 stdout，别自己写文件、自己轮转
        h.setFormatter(JsonFormatter())
        log.addHandler(h)
        log.setLevel(logging.INFO)
    return log


if __name__ == "__main__":
    log = get_logger()
    request_id.set("req-8f3a")
    t0 = time.perf_counter()
    time.sleep(0.05)
    log.info("llm_call", extra={"fields": {
        "user_id": "u_42", "feature": "summary", "model": "small",
        "tokens_in": 1200, "tokens_out": 380, "cost_cents": 0.056,
        "ttft_ms": 310, "latency_ms": round((time.perf_counter() - t0) * 1000)}})
    try:
        raise TimeoutError("upstream read timeout")
    except TimeoutError:
        log.exception("llm_error", extra={"fields": {"kind": "upstream_timeout"}})

实跑输出两行 JSON，event 都是固定串、可变的全在字段里；出错那行连异常类型也进了字段：

{"ts": 1786112431.032, "level": "INFO", "event": "llm_call", "request_id": "req-8f3a", "user_id": "u_42", "feature": "summary", "model": "small", "tokens_in": 1200, "tokens_out": 380, "cost_cents": 0.056, "ttft_ms": 310, "latency_ms": 50}
{"ts": 1786112431.032, "level": "ERROR", "event": "llm_error", "request_id": "req-8f3a", "kind": "upstream_timeout", "error": "TimeoutError: upstream read timeout"}

⭐ 打到 stdout，别自己写文件、别自己做轮转 —— 容器里的标准分工是「进程只管往 stdout 写，收集和留存交给平台」。这也正是第 14 章那行 PYTHONUNBUFFERED=1 的用途：不关缓冲，你在平台上看到的会是一段一段延迟到达的历史。

⚠️ 别把 DEBUG 级别的一切都记上：日志量本身是钱，更要命的是一条重要的日志淹在一万条噪声里等于没记。

🧵 三、请求追踪：一个 id 串起整条链路

形状是：入口处接住或生成一个 id，之后所有日志自动带上它，出错时也把它返回给用户（第 3 章那个 trace_id 就是它）。

⭐ 关键词是「自动」。靠每个函数多传一个参数，传到第三层一定有人忘，而且检索、缓存、记账这些被复用的函数会被迫改签名。Python 里干这件事的东西叫 contextvars：它是「跟着当前这条执行流走」的变量。

import asyncio, concurrent.futures as cf, contextvars

request_id = contextvars.ContextVar("request_id", default="-")


def where(tag):
    return "%-22s request_id=%s" % (tag, request_id.get())


async def child():
    await asyncio.sleep(0)
    return where("create_task")


async def main():
    request_id.set("req-8f3a")
    print(where("同一个协程"))
    print(await asyncio.create_task(child()))      # ⭐ 自动继承：建 task 时拷了一份上下文

    loop = asyncio.get_running_loop()
    with cf.ThreadPoolExecutor(1) as pool:
        # ⚠️ 扔进线程池就断了：那个线程有它自己的一份上下文，拿到的是默认值
        print(await loop.run_in_executor(pool, where, "run_in_executor"))
        ctx = contextvars.copy_context()           # ⭐ 把当前上下文整个带过去
        print(await loop.run_in_executor(pool, lambda: ctx.run(where, "copy_context")))


asyncio.run(main())

实跑输出，第三行就是那个坑：

同一个协程                  request_id=req-8f3a
create_task            request_id=req-8f3a
run_in_executor        request_id=-
copy_context           request_id=req-8f3a

⚠️ run_in_executor 那一行拿到的是默认值 -，而它不报任何错。 第 3 章说过「拿不准就把路由写成普通 def 交给线程池」—— 那条建议在这里有个副作用：扔进线程池的那段代码，日志里的 request_id 会悄悄断掉。 修法就是 copy_context()。

⭐ 三条规则：

1. 入口优先接住上游传来的 X-Request-ID，没有再自己生成 —— 第 14 章 Nginx 里那行 proxy_set_header X-Request-ID $request_id 就是为此存在的。不接住的话，代理的访问日志和你的应用日志各记一个 id，对不上等于两份都残废。
2. 异步边界要显式带过去（create_task 自动继承，线程池不会）。
3. ⭐⭐ 进了队列就必须写进 payload。 第 11 章那个 job 是另一个进程、可能另一台机器、可能几分钟之后才跑，contextvars 一点忙帮不上。做法是 jobs 表加一列 request_id，worker 取出后重新 set —— 这样「点按钮 → 入队 → worker 处理 → 写回结果」四段才连得成一条链路。这是最常见的断链点。

⚠️ 别把 request_id 当用户 id 或会话 id 用：一个用户一天有几千个。要串起一整段对话，另记一个 conversation_id。

🛑 读到这里可以停 —— 前半章讲完了（约 25 分钟）。 后半章还有：该看的四个指标 · 成本看板：至少拆三个维度 · ⚠️ 别把 prompt 和回复原样打进日志 · 告警：什么该告，什么不该 · 换个栈怎么对应 回来的时候不用重读，直接从下一节接着看就行。

📊 四、该看的四个指标

⭐⭐ TTFT 和总时长必须分开看。 一次回答很长导致总时长 30 秒是正常的；TTFT 从 300 毫秒涨到 3 秒是故障。只盯总时长的话，这个故障会被长回答的正常波动完全盖住。

⭐ 错误率必须分类型，因为五种错的处置动作完全不同：上游 429 要退避和限流（第 12 章）、上游超时要调超时和重试、输出校验失败要改 prompt 或换模型、自己的 5xx 要去看代码。合成一个数，等于把五个不同的病合并成「体温有点高」。

⚠️ 平均值会骗你

import math, random, statistics

random.seed(7)
# ⚠️ 这是【构造的】分布，不是实测数据：90% 正常、9% 慢、1% 卡到超时。它只用来说明算术。
lat = ([random.uniform(600, 1400) for _ in range(900)]
       + [random.uniform(2000, 6000) for _ in range(90)]
       + [30000.0] * 10)


def pct(xs, p):
    s = sorted(xs)
    k = max(1, math.ceil(len(s) * p / 100))   # ⭐ 最近秩法：第 ceil(n*p/100) 个
    return s[k - 1]


avg = statistics.fmean(lat)
print("平均 %.0f ms" % avg)
print("p50 %.0f   p95 %.0f   p99 %.0f   最大 %.0f ms"
      % (pct(lat, 50), pct(lat, 95), pct(lat, 99), max(lat)))
print("比平均值还慢的请求只占 %.1f%%" % (100 * sum(x > avg for x in lat) / len(lat)))

# ⚠️ 百分位不能平均：两台机器各自的 p95 取平均 ≠ 合起来的 p95
a, b = lat[:500], lat[500:]
print("两半各自 p95 = %.0f / %.0f，取平均 %.0f；合起来真实 p95 = %.0f"
      % (pct(a, 95), pct(b, 95), (pct(a, 95) + pct(b, 95)) / 2, pct(lat, 95)))

实跑输出：

平均 1540 ms
p50 1012   p95 3958   p99 5986   最大 30000 ms
比平均值还慢的请求只占 10.0%
两半各自 p95 = 1361 / 5298，取平均 3330；合起来真实 p95 = 3958

三条结论，每条都能从这几个数直接读出来：

• ⭐ 平均值 1540 ms 描述的是一个不存在的请求：只有 10.0% 的请求比它慢，而它比中位数（1012 ms）高出五成。长尾把它整个抬起来了 —— 它既不是典型体验，也不是最坏体验。
• ⚠️ p99 也会漏。 这批数据里 1% 的请求卡在 30000 ms（超时），而 p99 = 5986 ms 恰好站在那批超时的边缘，一个都没看见。要看见就得看 p99.9，或干脆单独统计超时次数。
• ⚠️⚠️ 百分位不能取平均。 两台机器各自 p95 是 1361 / 5298，平均得 3330，合起来的真实 p95 是 3958。多实例的分位数必须把原始数据合起来再算（监控系统里对应「存直方图，别存算好的分位数再平均」）。

⭐ LLM 应用比普通 Web 应用更不能看平均：输出长度方差大、上游排队、偶发重试、缓存命不命中 —— 四个因素叠在一起，长尾特别重。

💸 五、成本看板：至少拆三个维度

第 4 章的 record()、第 12 章第六节那张 calls 表，已经让每次调用记下 user_id / feature / model / cents，看板就是同一张表的三条 GROUP BY：

• 按天的总花费 —— 看趋势和台阶（台阶通常意味着某次发版）
• 按 feature 拆 —— 哪个功能在烧钱，值不值这个钱
• 按 user 排前 20 —— 是不是一个人的锅

⚠️ 别等账单。 供应商账单 T+1 才到，而你自己记的账是秒级的。第 12 章那场烧掉 $7270 的事故里，账单当晚根本没有数据，而这张表在事故开始十几分钟内就已经不正常了。

⭐ 但要分清分工：真正把损失摁住的是第 12 章的全局日预算熔断（它在风暴开始约 12 分钟后就拉闸），本章负责的是让人看见 —— 看板告诉你钱花在谁身上、告警告诉你熔断触发了。看得见但没有闸，你得到的只是一条「你已经烧掉很多钱了」的通知。

🔒 六、⚠️ 别把 prompt 和回复原样打进日志

三个理由，任意一个都够：

• 隐私 —— 用户会往输入框里贴身份证号、病历、内部代码。
• 体积 —— 一次长上下文 3 万 token，日志量能超过业务数据本身。
• 合规 —— 日志的留存期通常更长、访问权限通常更松；用户要求删除数据时，你多半会忘了日志里还有一份副本。

⭐ 默认该记的是指纹，不是内容：

import hashlib, re

EMAIL = re.compile(r"[\w.+-]+@[\w-]+\.[\w.]+")
PHONE = re.compile(r"(?<!\d)1[3-9]\d{9}(?!\d)")


def fingerprint(text, keep=30):
    """给日志留一个【能对上、能搜、但还原不出来】的指纹。"""
    masked = PHONE.sub("<phone>", EMAIL.sub("<email>", text))   # ⭐ 先脱敏再截断
    return {"sha12": hashlib.sha256(text.encode("utf-8")).hexdigest()[:12],
            "chars": len(text),                                  # 长度留着，排查截断要用
            "head": masked[:keep]}


if __name__ == "__main__":
    p = "帮我总结这封邮件：联系人 li.ming@example.com，电话 13800138000，内容如下……"
    print(fingerprint(p))
    print(fingerprint(p)["sha12"] == fingerprint(p)["sha12"], "← 同一段输入指纹相同，能对上")

实跑输出：{'sha12': '38da98143f24', 'chars': 54, 'head': '帮我总结这封邮件：联系人 <email>，电话 <phone'}。

三个字段各有分工：哈希让你能回答「是不是同一段输入在反复失败」而不必存内容；长度让你能排查截断和超上下文；脱敏后的开头够你认出这是哪一类请求。

⚠️ 先脱敏再截断，顺序不能反 —— 反过来的话，一个刚好被截成两半的手机号会照样留在日志里，而且它已经不匹配正则了，任何事后清洗都抓不到它。

⭐ 确实需要完整内容时（排查具体的坏 case、攒评测集），走一条单独的通道：专门的表或对象存储，短留存期、独立权限、默认关闭、按比例采样。⚠️ 采样要按整条请求采，要么全记要么全不记 —— 随机丢一半会给你一条断掉的链路，比什么都没有更误导人。

🚨 七、告警：什么该告，什么不该

⭐ 判据只有一条：收到它，你今晚会做一个动作吗？ 不会 → 它不是告警，是看板上的一个数字。

⚠️ 告警真正的敌人是噪声：一个每天响五次的告警，一个月后就没有人看了 —— 于是它响的第六次（真的那次）也没人看。这件事为什么必然发生、怎么救，《模型上线之后》08 章整章在讲，配这一章读。

⭐ 没触发过的告警等于没有告警。 配完当场手动触发一次，确认你的手机真的响了 —— 通道配错、密钥过期、免打扰时段，这三样每一个都能让你在真出事那天什么都收不到。

🔁 八、换个栈怎么对应

⭐ 这张表里只有第二行真的不一样：Go 强制你把 context 写进每个函数签名 —— 啰嗦， 但永远不会出现「第三层忘了传」。Python / Node 的隐式上下文写起来舒服， 代价就是本章那个 run_in_executor 的坑：它断了，但不报错。

🔗 这一章连到哪里

✅ 检查点

1. 本章和《模型上线之后》各管什么？为什么必须分开？交界处（比如「模型没按格式返回 JSON」）怎么判？
2. 只用 print 的三个缺陷是什么？哪一个让「昨天 u_42 花了多少」问不出口？为什么事件名必须是固定字符串？
3. 一条模型调用日志至少该带哪些字段？为什么 cached 也要记？
4. request_id 为什么要靠 contextvars 而不是每个函数传参？本章那段代码里哪一行断掉了、输出是什么？
5. 进了队列之后 request_id 怎么办？为什么 contextvars 在这里完全帮不上忙？
6. TTFT 和总时长为什么必须分开看？错误率为什么必须按类型分？
7. 那段延迟数据里平均值是多少、比它慢的请求占多少？p99 为什么没看见那批 30000 ms？两台机器的 p95 取平均错在哪？
8. 为什么不能把 prompt 原样进日志？默认该记哪三样？为什么必须先脱敏再截断？
9. 判断「该不该告警」的那一条判据是什么？为什么说没触发过的告警等于没有告警？

🛑 可以停在这里

⚡ 走神救援

🔭 先划界：⭐⭐ 本章管「服务健不健康」，《模型上线之后》管「模型准不准」 —— 分开是因为处置动作不同：前者今晚就要回滚/扩容/限流，后者是要花几天的调查。交界处（比如「模型没按格式返回 JSON」）看处置动作判归属。 结构化日志：print 的三宗罪是没级别/没来源、⭐拼进一句话里的东西查不出来、多进程顺序乱。形状是一行一条 JSON，事件名固定，可变的全进字段 —— 固定才聚合得起来。必带字段：request_id、user_id/tenant_id、model、tokens_in/out + cost_cents、ttft_ms/latency_ms、cached（命不命中缓存成本差几倍）、error_kind。⭐ 一律打 stdout，收集交给平台（第 14 章 PYTHONUNBUFFERED=1 就是为它）；⚠️ 别把 DEBUG 全记上，一条重要日志淹在一万条噪声里等于没记。 🧵 追踪：入口接住或生成一个 id，之后自动带上 —— 手动传参传到第三层必有人忘。Python 用 contextvars。实跑结果里 create_task 自动继承，⚠️ run_in_executor 拿到的是默认值 - 而且不报错，要 copy_context() 修。三条规则：优先接住上游的 X-Request-ID（第 14 章 Nginx 那行；不接住则代理日志和应用日志两份都残废）、异步边界要显式带、⭐⭐ 进了队列必须写进 payload（jobs 表加一列，worker 取出后重新 set）—— 那是另一个进程另一台机器，contextvars 完全帮不上忙，这是最常见的断链点。 📊 四个指标：⭐ TTFT（流式界面里「快不快」几乎只由它决定）、总时长、token 与钱、错误率按类型分。⭐⭐ TTFT 和总时长必须分开：长回答让总时长 30 秒是正常的，TTFT 从 300ms 涨到 3 秒是故障，只看总时长会被盖住。⚠️ 平均值会骗你：实跑那组构造数据平均 1540 ms，却只有 10.0% 的请求比它慢，中位数才 1012 ms；p99 = 5986 恰好卡在那 1% 超时（30000 ms）的边缘一个没看见；⚠️⚠️ 百分位不能平均 —— 两半各自 p95 是 1361 / 5298，取平均 3330，真实是 3958。 💸 成本看板三条 GROUP BY：按天趋势、按 feature、按 user 前 20；⚠️ 别等账单（T+1）—— 第 12 章那场 $7270 的事故里，自己记的账十几分钟内就已经不正常了；⭐ 但分工要分清：拉闸的是第 12 章的日预算熔断（约 12 分钟就触发），本章负责让人看见，看得见而没有闸，只是一条「你已经烧掉很多钱了」的通知。🔒 别把 prompt 原样进日志：隐私、体积、合规（日志留存更长、权限更松）。默认记哈希前 12 位 + 长度 + 脱敏后开头；⚠️ 先脱敏再截断，反了会留下半个手机号而且逃过正则。要完整内容就走单独通道（短留存、独立权限、默认关、按比例采样），⚠️ 采样要整条链路一起采。🚨 告警判据只有一条：收到它你今晚会做一个动作吗？ 不会就是看板不是告警。⚠️ 敌人是噪声（每天响五次的告警一个月后没人看）；⭐ 没触发过的告警等于没有告警，配完当场触发一次，确认手机真的响了。

下一节 👉 15b-怎么测不确定的系统.md