08 · 可观测性与性能排查#

简历原话：可观测性与性能排查：基于 OpenTelemetry 实现跨 Redis Stream 的全链路追踪；发现同 worker 内多会话 span 同时变长，定位到同步回查 Qdrant 阻塞事件循环，改走线程池后其他会话停顿 P99 860ms→5ms；回查慢源于高峰时与向量检索争用磁盘，向量 int8 量化后常驻内存，回查 P99 1.3s→49ms。

30 秒口述版#

ShoppingX 的任务是 API 收请求、写进 Redis Stream，再由 worker 消费执行，一个 worker 进程用一个事件循环同时跑几十个会话。早期 trace 只覆盖 worker 里的那一段，排队和执行连不起来。我用 OpenTelemetry 把 W3C traceparent 写进 Stream 消息，worker 取出后接着同一条 trace 往下挂，API、排队、Agent 主循环、每次模型和工具调用就在一棵树上了。接上之后看到一个现象：同一个 worker 里互不相关的几个会话，span 在同一时间窗口一起变长。多个会话同时变慢，说明它们共用的东西被占住了，这个东西就是事件循环。最后查到是按商品 ID 回查 Qdrant 的同步调用把循环卡住了，改成丢线程池执行后，其他会话的停顿 P99 从 860ms 降到 5ms。回查本身为什么慢？高峰期它和向量检索抢磁盘，我给向量做了 int8 标量量化、常驻内存，回查 P99 从 1.3s 降到 49ms。

背景与问题#

系统形态：API 进程只负责鉴权、准入和入队，把任务写进 Redis Stream；worker 进程用消费者组拉任务，每个 worker 一个 asyncio 事件循环，靠并发槽同时跑几十个会话（每个会话是一轮 Agent 主循环：planner → 检索 → 比价精挑 → 收尾）。模型调用、Redis、MySQL 都是异步 IO，理论上一个循环扛几十个会话没问题。

问题 1：链路是断的。

原来的 trace 从 worker 开始执行那一刻才开始，API 那边的入队、排队等待都不在 trace 里。消息里只带一个 request_id，两个进程的日志要靠它手动拼。
用户反馈「点了发送好久没动静」，我们分不清是卡在准入闸、在队列里排队、在等模型限流，还是某个工具慢。

问题 2：高峰期会话会「集体顿一下」。

链路接上后，在 Langfuse 瀑布图里看到奇怪的现象：同一个 worker 上三四个毫不相关的会话，模型流式输出的 span、写 Redis 的 span 在同一个时间窗口里一起被拉长了将近 1 秒。
这些 span 本身各干各的：有的在等模型吐 token，有的在写事件，没有一个跟数据库或检索有关。前端表现是流式文字突然停住一下，再一口气吐出来。
单看任何一个会话都找不到原因，因为慢的根源不在它自己身上。

问题 3：回查本身在高峰期也很慢。

把阻塞修掉后，别的会话不受影响了，但发起回查的那个会话自己还是要等。高峰期回查 P99 有 1.3s，而空闲时同一个请求只要 4ms 左右。

做法与取舍#

1. 跨 Redis Stream 的 trace 传递#

做法：
- API 收到任务时开一个「入队」span，把当前 span 的上下文按 W3C Trace Context 格式序列化成 traceparent（00-<32位 trace_id>-<16位 span_id>-<flags>），作为一个字段和任务一起 XADD 进 Stream。
- worker 拉到消息后解析这个字段，开本轮的根 span 时把它当父 span，于是 API 段和 worker 段是同一个 trace_id。本轮下面所有模型调用、工具调用的 span 由 AgentScope 的 tracing 中间件自动挂上来；同轮并发的多个工具调用走 asyncio Task，OTel 上下文本身存在 ContextVar 里，建 Task 时会被拷贝，所以子 span 天然挂在正确的父节点下。
- 排队时长 = 入队 span 结束到 worker 根 span 开始之间的空档，另外在根 span 上记一个排队等待属性，方便按它筛。
- 日志每行带 trace_id / request_id / thread_id，指标里补了队列积压、任务被接管次数、限流等待时长，积压超过 90% 触发告警（带滞回，防抖动）。
为什么手动解析 traceparent，没用 OTel 自带的 propagator 提取：propagator 提取出来的是 OTel Context，要 attach 到当前上下文，采样器按父 span 的 flags 决定要不要采样。API 侧如果没开观测，发来的 flags 是 00，worker 会把整轮 span 全丢掉，症状是「worker 开着观测却一条 trace 都没有」。手动解析后自己判断：上游采样了就挂父 span；上游没采样就只沿用 trace_id、不挂一个不存在的父节点。
观测关着也生成 traceparent：随机生成 trace_id、flags 记 00。这样即使不上报 span，两个进程的日志也能按同一个 trace_id 关联起来。
否掉的方案：
- 在 Stream 外另存一张 request_id → trace_id 映射表：多一次读写、多一个一致性问题，而 traceparent 本来就是为跨进程传递设计的标准格式。
- 让 worker 自己开新 trace、事后用 request_id 做关联：Langfuse 里看不到一棵完整的树，排队时长还是得手算。
原则：观测不能拖垮主链路。缺配置、客户端初始化失败、span 上报报错一律降级成「没有观测」，只记日志，不抛异常。

2. 从「多会话同时变慢」定位到事件循环阻塞#

推理：一个会话慢，原因可能在它自己；多个不相关的会话在同一时刻一起慢，一定是它们共享的东西被占住了。同一个 worker 进程里它们共享的只有 CPU 和事件循环，而 CPU 使用率不高，嫌疑就落在事件循环上：某段代码在循环线程上同步执行，期间所有协程都得排队。
补指标验证：给 worker 加了一个事件循环延迟探针：一个后台协程每 100ms 睡一次，醒来时看实际睡了多久，多出来的就是循环被占住的时间，按直方图上报。高峰时延迟探针的尖峰和那些「集体变长」的时间窗口一一对上。
找阻塞者：探针发现延迟超过 100ms 时，采样打印当时循环线程的调用栈。栈顶反复出现的是按商品 ID 回查 Qdrant 的 scroll 调用。
为什么会有同步调用：候选商品登记表只活一轮。用户下一轮说「买第 2 个」「把刚才那几件对比一下」时，比价、收尾、下单、对比这些工具要按 ID 从 Qdrant 把商品捞回来。检索路径早就丢线程池跑了，而这条回查路径用的是同一个同步 Qdrant 客户端，却直接在 async 工具里调用，平时 4ms 看不出问题，一到高峰就卡住整个循环。

3. 改走线程池#

做法：回查调用丢到 asyncio 默认线程池里执行，事件循环只 await 一个 Future，等待期间照常调度别的会话。回查外面仍包着原来的断路器和超时，失败时只记日志，退回「登记表里已有的那些」，不让收尾链路报错。
为什么选线程池，不换异步客户端：
- Qdrant 有官方的异步客户端，但换它要改整个召回层：检索、回查、搜同款、断路器包装全得跟着改，还要两套客户端并存一段时间。检索路径早就是「同步客户端 + 线程池」，回查照同一个模式改，改动最小、行为一致。
- 这里的阻塞是等网络和等 Qdrant 服务端，线程在等待时会释放 GIL，线程池足够用，不存在 CPU 密集任务被 GIL 卡住的问题。
否掉的方案：
- 给回查加进程内缓存：跨轮引用的商品 ID 很分散，同一批 ID 很少被第二次回查，命中率低；而且缓存只是让它不常发生，一旦未命中照样卡循环。
- 调大 worker 数、减少每个 worker 的会话数：只是把被连累的会话变少，阻塞本身还在。
防止再犯：延迟探针和调用栈采样常驻线上，循环延迟 P99 进了告警规则。之后谁在 async 路径里又写了同步 IO，第一时间能看到。

4. 回查慢的根因：和向量检索抢磁盘#

现象：修完阻塞后别的会话不受影响了，但回查自己在高峰期 P99 还是 1.3s。回查只是按 payload 索引 scroll 几十条记录，不做向量计算，空闲时 4ms。
排查：压测时 vmstat 看到 iowait 约 51%、读盘约 200MB/s，用户态 CPU 只有 10% 左右，瓶颈在磁盘不在 CPU。召回库是 138 万商品 × 1024 维 float32，原始向量约 5.4GB，当时向量和 HNSW 图都放在磁盘上（全放内存会顶爆容器上限）。每次向量检索都要从磁盘读大量原始向量来打分，page cache 装不下，高峰期磁盘 IO 队列被检索占满，回查的读请求只能排在后面。
做法：开 int8 标量量化，并让量化后的向量常驻内存；原始 float32 向量仍放磁盘，只在最后对少量候选做精确重打分（oversampling 后 rescore）。量化向量约为原来的 1/4，1.3GB 左右，放得进内存。检索的主要打分全在内存里完成，不再大量读盘，磁盘让出来后回查自然就快了。
为什么是 int8 标量量化：
- 二值量化（1 bit）压缩率更高，但 1024 维的 BGE-M3 向量不是为二值化训练的，召回损失会明显更大。
- 乘积量化（PQ）压缩率高，但打分更慢、召回损失也更大，Qdrant 官方也把它定位成内存特别紧时才用。
- int8 在 Qdrant 里切换不需要重新 embedding，可以在线改集合配置，后台重建量化索引即可。
代价：Qdrant 进程内存从约 356MB 涨到约 2.0GB；召回有损失，用 200 条带线上同款过滤条件的固定查询对比量化前的 top-20，recall@20 平均 96.8%，靠 rescore 把排序精度拉回来。量化索引构建约 20 分钟。
否掉的方案：
- 把回查搬出 Qdrant、商品详情另存到 MySQL：回查确实不再和检索抢盘，但要双写两份商品数据，还有一致性问题；而且检索本身仍然慢，只是把问题藏起来了。
- 换更快的盘 / 加 Qdrant 副本：部署在单台 VPS 上，成本高，也没解决「每次检索都要读几 GB 向量」这个根本问题。

流程图 / 架构图#

图 1：trace 怎么跨过 Redis Stream#

sequenceDiagram
    participant C as 前端
    participant A as API 进程
    participant S as Redis Stream
    participant W as worker 进程
    participant L as Langfuse / OTel 后端
    C->>A: POST 提交任务
    A->>A: 开「入队」span，生成 traceparent
    A->>S: XADD 任务 + traceparent 字段
    A-->>L: 上报入队 span
    A-->>C: 返回 thread_id
    Note over S: 排队等待<br/>= 入队 span 结束到根 span 开始的空档
    W->>S: XREADGROUP 拉到任务
    W->>W: 解析 traceparent
    alt 上游已采样
        W->>W: 根 span 挂在入队 span 下，同一 trace_id
    else 上游未采样或观测关闭
        W->>W: 只沿用 trace_id，不挂父 span
    end
    W->>W: 模型调用 / 工具调用 span 自动挂到根 span 下
    W-->>L: 上报整轮 span
    Note over A,W: 两个进程的日志每行都带同一个 trace_id

图 2：一个同步调用怎么拖慢整个 worker#

flowchart LR
    subgraph W["worker 进程：一个事件循环"]
        EL["事件循环线程"]
        S1["会话 A：等模型流式输出"]
        S2["会话 B：写事件到 Redis"]
        S3["会话 C：收尾工具按 ID 回查商品"]
        TP["线程池"]
    end
    Q[("Qdrant")]
    S1 --> EL
    S2 --> EL
    S3 -->|"改前：在循环线程上同步 scroll"| EL
    EL -->|"阻塞期间 A、B 都无法被调度"| Q
    S3 -.->|"改后：丢线程池，循环只 await"| TP
    TP -.-> Q

图 3：回查为什么慢、量化后怎么变#

flowchart TB
    subgraph Before["量化前：向量与 HNSW 全在磁盘"]
        R1["并发向量检索"] -->|"读大量 float32 原始向量打分"| D1[("磁盘 5.4GB 向量")]
        F1["按 ID 回查"] -->|"排在检索的读请求后面"| D1
        D1 --> X1["iowait 约 51%，回查 P99 1.3s"]
    end
    subgraph After["量化后：int8 向量常驻内存"]
        R2["并发向量检索"] -->|"主打分走内存"| M2[("内存 int8 向量 约 1.3GB")]
        R2 -->|"只对少量候选 rescore"| D2[("磁盘 float32 原始向量")]
        F2["按 ID 回查"] --> D2
        D2 --> X2["iowait 约 0%，回查 P99 49ms"]
    end
    Before --> After

图 4：排查思路#

flowchart TD
    A["用户反馈：流式输出偶尔停住一下"] --> B["接通跨队列 trace，看瀑布图"]
    B --> C{"慢的是单个会话还是多个？"}
    C -->|"同 worker 多个无关会话同时变长"| D["怀疑共享资源：CPU 或事件循环"]
    D --> E{"CPU 高吗？"}
    E -->|"不高"| F["加事件循环延迟探针"]
    F --> G["延迟尖峰与变长窗口对齐"]
    G --> H["超阈值时采样调用栈"]
    H --> I["栈顶是同步 Qdrant 回查"]
    I --> J["改走线程池：他人停顿 P99 860ms→5ms"]
    J --> K{"回查本身还慢？"}
    K -->|"P99 1.3s，vmstat iowait 高"| L["与向量检索抢磁盘"]
    L --> M["int8 量化常驻内存：回查 P99 1.3s→49ms"]

数字怎么来的#

测试环境：线上同一台 VPS（部署 demo 的那台），在后端容器里直连内网 Qdrant，库里是全量 138 万商品。不调真模型，只打 Qdrant 和事件循环。

负载：模拟高峰的向量检索，6 组并发、每组 5 条同时突发，检索带线上同款过滤条件（平台 + 价格不超过预算 + 一半请求加评分不低于 4）；查询向量从库里随机抽。每种配置连续跑 90 秒。

同时跑两个探针：

回查探针：每隔固定间隔按一批随机商品 ID 做一次回查，记录耗时，统计 P50 / P95 / P99。
事件循环延迟探针：和回查探针在同一个进程、同一个事件循环里，每 10ms 睡一次，醒来时记录实际多睡的时间，这就是「其他会话会感受到的停顿」。

三组对照（除被测变量外条件完全相同）：

配置	回查 P99	事件循环停顿 P99 / 最大	检索 P99	90 秒完成检索数	iowait / 用户态 CPU
量化前 · 同步回查	1319ms	860ms / 1314ms	2297ms	1395	51% / 10%
量化前 · 线程池回查	1340ms	5ms / 96ms	2336ms	1395	51% / 10%
int8 量化后	49ms	21ms / 88ms	90ms	8712	0% / 35%

怎么读这张表：

860ms→5ms 是第一行对第二行：只把回查从同步改成线程池，其他条件不变。回查本身还是 1.3s（1319ms 和 1340ms 基本一样），但这段时间事件循环不再被占，别的协程感受到的停顿 P99 从 860ms 降到 5ms。这说明线程池只解决「连累别人」，不解决「自己慢」。
1.3s→49ms 是第一行对第三行：量化后磁盘不再被检索占满，回查 P99 从 1319ms 降到 49ms。顺带检索 P99 从 2.3s 降到 90ms，90 秒内完成的检索数从 1395 涨到 8712。
第三行的循环停顿 P99 21ms 是同步回查的配置：回查只剩几十毫秒，同步调用的代价也跟着变小；线上两个改动同时生效，停顿维持在个位数毫秒。
空闲基线：没有并发检索时回查 P50 4ms、P99 7ms，用来说明回查本身很便宜，慢全来自高峰争用。

判断是磁盘瓶颈的依据：压测期间 vmstat 每秒采样，量化前 iowait 约 51%、读盘约 200MB/s、用户态 CPU 只有 10% 左右；量化后 iowait 降到 0，用户态 CPU 升到 35%（检索吞吐涨了 6 倍，CPU 在干活了）。

召回损失怎么测：200 条固定的带过滤条件查询，以量化前 HNSW 的 top-20 为参照，算量化后 top-20 的重合率，平均 recall@20 为 96.8%。

为什么用 P99 而不是平均：用户感知的是「偶尔卡一下」，平均值会被大量几毫秒的正常样本冲淡，P99 和最大值才反映出卡顿。

追问 Q&A#

Q1：traceparent 具体放在消息的哪里？worker 怎么接上？

它是 Stream 消息里和任务其他字段并列的一个普通字段，格式是 W3C 标准的 00-trace_id-span_id-flags。 worker 拉到消息后用正则校验格式，拒掉全零 id 这种非法值，然后开本轮根 span 时把远端的 trace_id 和 span_id 作为父上下文传进去。老消息没有这个字段，或者格式不对，就当没有，自己起一条新 trace，不报错。

Q2：为什么不直接用 OTel 的 propagator inject / extract？

inject 那一侧我其实可以用，问题在 extract 之后的采样判断。 extract 出来的 Context attach 上去以后，默认的 ParentBased 采样器看父 span 的 flags：API 侧没开观测时 flags 是 00，worker 这一整轮就全被丢掉了。我们的场景是 API 和 worker 可能分别开关观测，所以自己解析，自己决定：上游采样了就挂父 span，没采样只沿用 trace_id 做日志关联。

Q3：一轮 Agent 里同轮并发好几个工具调用，span 父子关系不会乱吗？

不会。OTel 的当前 span 存在 ContextVar 里，asyncio 创建 Task 时会拷贝一份当前上下文。同轮多个工具调用是框架 gather 出来的多个 Task，每个 Task 建出来时都带着「当前是这一轮的模型调用 span」，所以子 span 都挂在同一个父节点下，互不串。

Q4：你怎么从 trace 里看出是事件循环的问题？trace 上不会直接写「循环被阻塞」。

trace 上看到的只是现象：同一个 worker 里几个互不相关的会话，span 在同一个时间窗口里一起变长，而且变长的是等模型、写 Redis 这种和彼此毫无关系的操作。一个会话慢可能是它自己的问题，多个无关会话同时慢，说明它们共用的东西被占住了。同进程共用的只有 CPU 和事件循环，CPU 不高，就只剩事件循环。然后我加了事件循环延迟探针去验证，尖峰和变长窗口能对上，再用超阈值时的调用栈采样找到具体是哪一行。

Q5：事件循环延迟探针怎么实现的？会不会本身有开销？

一个后台协程循环 sleep 固定间隔，醒来时用单调时钟算实际过去了多久，减去预期间隔就是循环延迟，写进直方图。开销就是每 100ms 一次调度，可以忽略。超过阈值才去抓循环线程的调用栈，而且按比例采样，不会每次都抓。压测时为了精度把间隔调到 10ms。

Q6：检索早就丢线程池了，为什么回查漏了？

两条路径是不同时期写的。检索从一开始就知道慢，所以包了线程池；回查是后来为「跨轮引用商品」加的，空闲时只要 4ms，写的时候没意识到它也是网络 IO。 Python 里 async 函数里调同步阻塞函数不会报错，也不会有警告，只有高峰才会暴露。所以我在修完之后把循环延迟 P99 加进了告警，靠指标而不是靠人记得。

Q7：线程池默认大小是多少？高峰时线程池会不会被打满，变成新的瓶颈？

asyncio 默认线程池的上限是 min(32, CPU 核数 + 4)。回查、检索都在里面排队，打满了新的调用会在线程池队列里等。但这种等待只影响发起回查的那个会话自己，事件循环照常调度别的会话，这正是我们要的隔离效果。线程池排队时间也在回查 span 里，真成了瓶颈 trace 上能直接看到。根本解决回查慢靠的是后面的量化，不是加线程。

Q8：为什么不换成 Qdrant 的异步客户端？那才是「正解」吧？

异步客户端确实更干净，但要改整个召回层：检索、回查、搜同款、外面包的断路器和超时，还要两套客户端并存一段时间。这个问题的本质是「同步 IO 别在循环线程上跑」，线程池已经解决了，而且和检索路径保持同一个模式，维护成本低。等召回层有别的理由大改时再整体切异步，不为这一个点单独动。

Q9：int8 量化召回掉了 3 个多点，对业务影响多大？最低的单条掉到多少？

平均 recall@20 是 96.8%，这是和量化前的 HNSW 结果比，不是和精确搜索比。个别查询会掉得多，尤其是过滤条件很严、候选本来就少的查询，最差的单条只有四成多。业务上影响不大，原因有两个：一是开了 rescore，用磁盘上的原始向量对量化召回的候选重新打分，排序精度基本拉回来；二是召回之后还有 reranker 精排和按偏好精挑，最终只推荐 3 件，top-20 里偶尔换掉几件对最终清单影响很小。如果要更稳，可以把 oversampling 系数调大，用一点延迟换召回。

Q10：如果商品从 138 万涨到 1500 万，int8 也放不进内存了怎么办？

1500 万 × 1024 维 int8 大约 15GB，单机确实吃力。几个方向：一是 Qdrant 分片，把集合拆到多个节点，每个节点的量化向量常驻各自内存；二是降维，BGE-M3 这类模型可以截断或换用更小维度的 embedding，维度减半内存就减半；三是在内存特别紧时考虑二值量化加大倍数 oversampling，再用原始向量 rescore，但要重新测召回。回查这条路径可以再加一层：按 ID 取商品详情走 Redis 缓存，彻底和检索的 IO 分开。

Q11：量化是在线切换的吗？切换过程中服务受影响吗？

Qdrant 支持在线修改集合的量化配置，不需要重新 embedding，后台重建量化索引，约 20 分钟。重建期间集合状态会变黄，检索照常能用，只是还走旧路径、延迟不变。重建完成状态变绿，新请求自动走量化索引。切之前我先在压测环境跑了三组对照，确认收益和召回损失，再上线。

Q12：你说「高峰」，线上真实高峰多高？压测的负载有代表性吗？

压测用的是 6 组 × 5 条的突发检索，对应的是一个 worker 上同时有几个会话进入检索阶段、每个会话同轮并发发出好几条跨平台检索的情形。我们的单轮普通会话一般同轮发 3~~5 条检索，所以 30 路并发检索大约对应 6~~10 个会话同时检索，这在一个 worker 几十个并发槽里是正常高峰。过滤条件也照线上同款配，不是裸向量检索。