《AI Agent 工程实战》14.1 延迟剖析：模型/检索/工具各占多少

14.1 延迟剖析：模型/检索/工具各占多少

第 13 章的可观测性把「一次 run 慢不慢」变成了可观测的指标，但指标只告诉你慢了，没告诉你慢在哪。一个 Agent 请求要经过模型调用、语料检索、工具执行、结果序列化好几个阶段，它们的量级差异极大——如果不分阶段计时，你很容易把优化力气花错地方：盯着 CPU 火焰图看半天，而真正吃掉 90% 时间的其实是那几次网络上的模型调用。

本节把 ResearchCopilot 推进到「分阶段可计时」：给一次 run 的模型调用、检索、工具执行、序列化分别埋点，真跑打出各阶段的耗时与占比表，并用一组对照实验量出「同步阻塞拖垮异步服务」到底有多严重。

14.1.1 Agent 的延迟结构跟 Web 服务不是一回事

传统 Web 服务的延迟几乎全在 CPU 与数据库上，优化手段是加缓存、加索引、换更快的机器。Agent 服务的延迟分布完全不同：

最反直觉的一点是模型调用通常独占大头。它既不是 CPU、也不是磁盘，而是「等供应商的服务器」。这意味着加机器、加 CPU 对端到端延迟几乎没用——瓶颈不在你这边。

但「通常是模型」不等于「永远是模型」。三种情况下大头会易主：检索没加索引（全表扫描把几十 ms 拖成几秒）、工具里有同步阻塞 IO（把整个事件循环堵死，见 14.1.7）、上下文被序列化得越来越长（每轮都要重新编码整段历史）。所以先量、再猜，是这一节存在的全部理由。

14.1.2 给每个阶段计时

计时本身很简单：一个 perf_counter 包住每个 await，记下耗时。难点在于埋点的位置——必须包住「等待」本身，而不是「发起等待」的代码。

import time
from dataclasses import dataclass

@dataclass
class Phase:
    name: str
    seconds: float

async def timed(name: str, awaitable):
    t0 = time.perf_counter()
    await awaitable
    return Phase(name, time.perf_counter() - t0)

timed 接收一个已创建的协程对象（asyncio.sleep(...) 的返回值），在 await 前后取时间差。把「计时」和「具体逻辑」解耦，是为了同一套计时器能包住任意阶段——模型、检索、工具都走同一个 timed，输出格式天然统一。

计时有一个容易忽略的坑：并发阶段要按「墙钟」而不是「累加」计。一次检索并发抓 3 篇语料，每篇 0.12s，串行累加会得到 0.36s，但真实的墙钟只有 0.12s。8.1 已经论证过「并行总耗时 = 最慢的那个」，所以计时要包住整个 TaskGroup 的边界，而不是每个子任务各自计时再求和。

14.1.3 端到端 P95 由谁决定

单次耗时是均值，真正决定用户体验的是 P95——最慢的那 5% 请求。P95 由谁决定，取决于哪个阶段方差最大：

• 模型调用方差中等（排队抖动），但基数大，所以它对 P95 的绝对贡献通常最大。
• 检索方差可以极大：命中缓存的走了 5ms，未命中的全量扫描走 2s——P95 往往被检索的慢尾拖高。
• 工具执行方差最大：一个外部 API 偶发超时，能把单次 run 直接顶到超时上限。
• 序列化几乎无方差，但它随历史长度线性增长，长对话里会稳定吃掉几十 ms。

判据是：先看 P95 的绝对值和均值差多少。如果 P95 是均值的两三倍，说明有个阶段的慢尾在作祟，要去查检索和工具；如果 P95 和均值贴得很近，说明延迟稳定，优化只能靠「压整体」——换更快的模型档位、减少轮数。

14.1.4 真跑：一次 run 的分阶段占比

构造一次带四个阶段的 run：模型调用 0.35s、检索并发抓 3 篇各 0.12s、工具执行 0.08s、把 200 条消息序列化成 JSON。跑 5 次取中位数：

import asyncio, json, statistics, time

HISTORY = [{"role": "user" if i % 2 else "assistant",
            "content": "检索到第 %d 段语料，包含与问题相关的若干事实与引用。" % i}
           for i in range(200)]

async def run_once():
    out = []
    out.append(await timed("model_call", asyncio.sleep(0.35)))     # 模型
    t0 = time.perf_counter()
    async def fetch(_i):
        await asyncio.sleep(0.12)                                  # 单篇语料
    async with asyncio.TaskGroup() as tg:
        for i in range(3):
            tg.create_task(fetch(i))
    out.append(Phase("retrieval", time.perf_counter() - t0))       # 检索（整组）
    out.append(await timed("tool_exec", asyncio.sleep(0.08)))      # 工具
    t0 = time.perf_counter()
    _ = json.dumps(HISTORY)
    out.append(Phase("serialization", time.perf_counter() - t0))   # 序列化
    return out

真跑输出（Python 3.14.6，5 次中位数）：

一次 run 的分阶段耗时（5 次中位数，Python 3.14.6）
阶段                  耗时(ms)      占比
model_call           352.1   63.3%
retrieval            122.2   21.9%
tool_exec             82.1   14.8%
serialization          0.2    0.0%
合计                   556.5  100.0%

读这张表：模型调用占 63.3%，一家独大。检索和工具加起来 36.7%，序列化几乎为零（200 条消息才 0.2ms）。

注意检索那 122.2ms——它和单篇的 0.12s 几乎相等，说明3 篇语料是真的并发跑的（串行会是 0.36s）。这正是 14.1.2 说的「按墙钟计」：如果按累加，这里会虚报成 360ms，把检索的占比从 21.9% 夸大到 40%。

这张表还告诉你优化的优先级：要压端到端，先动模型那一栏——换更小/更快的档位、减少轮数、命中缓存。检索和工具即使优化到零，也只省 36.7%。反过来，如果这张表里检索占了 70%，那问题多半是索引没建对，而不是模型选错了。占比表就是优化靶点的地图。

14.1.5 把计时接进 run 循环

上面是孤立地量了一次 run。要让它进 ResearchCopilot，得把计时器挂到真正的循环上。做法是：在循环的每个 await 点包一层 timed，把 Phase 累积到一个列表里，循环结束时一次性带出。

async def profiled_run(model, exec_tool, schemas, user_input, max_steps=8):
    phases: list[Phase] = []
    messages = [Message(role="user", content=user_input)]
    for _ in range(max_steps):
        resp = await timed("model_call", model.complete(messages, schemas()))
        messages.append(resp.message)
        if not resp.message.tool_calls:
            break
        for tc in resp.message.tool_calls:
            out = await timed("tool_exec", exec_tool(tc))
            messages.append(Message(role="tool", content=out, tool_call_id=tc.id))
    return messages, phases

这段和 8.1 的并发循环只差两处：模型调用和工具调用各包了一层 timed。之所以强调「循环结束时一次性带出」，是因为 Phase 列表属于单次 run 的状态——不能放进全局变量，否则并发跑多个 run 时会互相串数据（8.1 的安全边界表里「共享可变状态不能并发」正是这条）。

真实系统里，这些 Phase 通常直接变成 13.1 的 OTel span 属性：每个 timed 对应一个子 span，Phase.seconds 就是 span 的 duration。这样延迟剖析和分布式追踪共用一套埋点，不必各写一份——这也是把「计时」抽象成通用 timed 而非散落各处的 perf_counter 的收益。

14.1.6 真跑：分位数看慢尾

均值会掩盖慢尾，所以真实系统看的是每个阶段的分位数。把上面的 run 改成带抖动（模型 0.35s±0.12、检索 0.12s±0.09、工具 0.08s±0.05），跑 30 次，取 P50 与 P95：

def pct(xs, q):
    xs = sorted(xs)
    return xs[min(len(xs) - 1, int(len(xs) * q))]

真跑输出（Python 3.14.6，30 次）：

30 次 run 的分位数（ms）
阶段                 P50     P95   P95/P50
model_call       397.0   514.9     1.30x
retrieval        141.8   298.9     2.11x
tool_exec         92.5   166.5     1.80x

这张表比均值表有用得多。检索的 P95/P50 是 2.11x，最差——说明它的慢尾最严重：均值只有 142ms，但最慢的 5% 到了 299ms。模型虽然绝对值最大（P95 515ms），但它比值只有 1.30x，稳定。这条信息直接改变优化策略：模型那栏要压整体（换档位），检索那栏要压尾部（加索引、缓存热门查询）。两种问题，两种药。

只看均值就会漏掉这一切——均值表里检索是 122ms，看起来无关紧要；分位数表才暴露它「偶尔慢一倍」的事实。P95 由方差最大的阶段决定，这句话在这里得到了具体数字的印证。

14.1.7 同步阻塞拖垮异步服务

Agent 服务是异步的（fastapi + asyncio），但很多老库是同步的：requests、同步版 psycopg、sqlite3。在 async def 路由里直接调它们，会踩到异步编程最经典的坑：同步 IO 会把整个事件循环堵死。

事件循环是单线程的：它靠协程在 await 处让出控制权来「假装并发」。同步 IO 里没有 await，所以它执行期间所有其它协程都停摆。用一个对照实验量一下：5 个并发请求，每个 IO 耗时 200ms。

def sync_query(delay_ms):            # 模拟 requests.get / psycopg 同步查询
    time.sleep(delay_ms / 1000)
    return "rows"

async def async_query(delay_ms):     # 模拟 httpx.AsyncClient / psycopg async
    await asyncio.sleep(delay_ms / 1000)
    return "rows"

async def handler_blocking(delay_ms):
    return sync_query(delay_ms)      # 在 async 路由里直接调同步 IO

async def handler_async(delay_ms):
    return await async_query(delay_ms)

async def drive(handler, n, delay_ms):
    t0 = time.perf_counter()
    await asyncio.gather(*[handler(delay_ms) for _ in range(n)])
    return time.perf_counter() - t0

真跑（并发 5、单个 IO 200ms）：

并发 5 个请求，单个 IO 耗时 200ms
同步阻塞 handler： 1028.9 ms
异步     handler：  201.1 ms
阻塞放大了 5.1 倍

差距是决定性的：异步版 201ms（等于单个请求），同步版 1029ms（约等于 5 个串行）。同步阻塞把「5 个请求重叠等待」退化成了「5 个请求排队等待」——并发完全失效。放大倍数 ≈ 并发数，并发越高退化越狠：50 个并发请求下，同步版要 10 秒，异步版还是 200ms。

这条规律的工程含义很硬：异步服务里，任何一个同步 IO 都会把整台机器的并发能力降到 1。而且它极其隐蔽——单测时只有一个请求，测不出问题；上线后并发一上来，整个服务的 P95 突然集体飙升，看 CPU 却不高（因为都在 time.sleep 里干等）。排查时的信号是：QPS 上不去、延迟随并发线性增长、CPU 却很闲——这三点同时出现，八成是某处藏了个同步 IO。

修法有三条，按优先级排：① 换成异步客户端（requests → httpx.AsyncClient，同步 psycopg → psycopg 异步连接），这是根治；② 不得已时丢到线程池，用 await asyncio.to_thread(sync_query, ...) 把阻塞挪出事件循环；③ 兜底加超时，防止单个阻塞调用把循环占死。第 8 章的并发受限服务之所以能撑住并发，前提正是工具链全程异步——一旦有一个工具偷偷用了同步 IO，前面所有的并发设计都会前功尽弃。

第 ② 条值得展开，因为它常被当成「省事的妥协」，其实代价要算清楚：

async def handler_threadpool(delay_ms):
    return await asyncio.to_thread(sync_query, delay_ms)   # 阻塞挪到工作线程

to_thread 把同步调用扔进一个默认线程池执行，await 它时事件循环继续转，所以不再堵死循环。但它不是免费的：每个并发请求占一个线程，线程池默认上限有限（asyncio 默认 min(32, cpu+4)），并发超过线程数后请求照样排队。换句话说，to_thread 把「循环被堵死」换成了「线程池被打满」——延迟不再随并发线性爆炸，但吞吐仍有天花板。它适合「偶发的一两个同步调用」，不适合「主路径上的高频同步 IO」——后者必须老老实实换成异步客户端。

14.1.8 什么时候不是模型的锅

分阶段占比表跑出来，如果模型那一栏没有独占大头，就得往别处看。三种最常见的「冤枉模型」场景：

这三条的排查动作都一样：把对应阶段的耗时单独打点，跨请求对比分布。14.1.4 那张表看的是均值，真正要盯的是同一阶段的 P95 与 P50 差多少——差值大，说明慢尾在那个阶段，去那里找。

一个容易忽略的点：「模型慢」有时也是你自己的锅。同一个模型，上下文越长、工具 schema 越多，首 token 延迟越高。所以「模型调用 63%」这件事本身不代表只能靠换模型解决——把上下文瘦身（14.2）、减少工具 schema 数量，同样能把这一栏压下去。占比表给的是靶点，不是借口。

14.1.9 验收与真实环境

本节把「慢」拆成了可归因的阶段：

• 分阶段计时：模型 / 检索 / 工具 / 序列化四段，按墙钟而非累加，真跑出模型占 63.3% 的占比表。
• 分位数：检索的 P95/P50 达 2.11x，慢尾最重；模型绝对值大但比值只有 1.30x，更稳。
• 同步阻塞实测：并发 5、IO 200ms 下，同步版 1029ms vs 异步版 201ms，放大 5.1 倍。
• 判据：P95 由方差最大的阶段决定；「QPS 上不去 + 延迟线性涨 + CPU 闲」指向同步阻塞。

验收清单：

• 一次 run 的每个阶段都有独立耗时打点，且并发阶段按墙钟计
• 有一张占比表，能一眼看出当前的大头
• 全链路没有同步 IO（requests / 同步 psycopg 已换成异步客户端或 to_thread）
• 每段的 P95 与 P50 都被记录，能定位慢尾

真实环境 / 真实模型下会怎样：本节所有耗时都是 asyncio.sleep 假装的，比例是我按典型值设定的。真实世界有三个差异。第一，模型调用会主导到 80% 以上——真实一次生成动辄一两秒，而检索命中索引后常常只要几十毫秒，占比只会比 63% 更悬殊。第二，真实延迟的方差大得多：供应商排队、限流、网络抖动，都会让模型那一栏的 P95 远高于均值，所以生产里必须按分位数而不是均值看每个阶段。第三，流式输出会改写体验口径——用户感知的是「首 token 延迟」而不是「整段生成完成」，14.1 表里的 model_call 应该拆成「首 token」与「剩余生成」两段分别计，否则你优化了半天总时长，用户却毫无感觉。真实系统里，这张占比表通常是按天滚动的——今天的大头和上周未必一样，延迟剖析是一件要持续做的事，不是一次性体检。

阅读导航：上一节：13.3 告警与 on-call：从 trace 到告警演练 · 下一节：14.2 成本优化：缓存、路由、小模型降级 + 评测兜底 。