# 日志、追踪与成本：看清一次 AI 请求发生了什么
## 用途、程度与前置
用户说“刚才那次一直转圈”，你需要知道它停在上传、检索、模型还是工具执行阶段。本章适用于已有 API 调用、流式回答、后台任务或多步骤 Agent 的应用。L2 要求是能设计一次请求的可观测字段，复现超时链路，算清费用估计，并设置预算和异常提醒。
前置是 Node 异步函数、异常处理和 HTTP 请求知识。完整示例只用 Node.js 22 标准库模拟两次上游尝试，不访问网络、不读取真实提示词、不产生费用。它展示日志契约；接入 OpenTelemetry SDK 是进一步工程化，而不是运行示例的前提。
## 日志、指标与追踪各自回答什么
日志是一条事件，例如检索结束、上游返回限流。指标是可聚合的数值，例如每分钟错误数量或请求时长分布。追踪把一次用户请求经过的阶段连起来，每段 span 有开始、结束、状态和父子关系。三者一起才能从“错误率变高”下钻到“哪个阶段失败”，再查看具体原因。[OpenTelemetry 信号](https://opentelemetry.io/docs/concepts/signals/)
把前端一次点击想成 trace，把后端请求、检索、模型生成、工具调用想成 span。request_id 是你对外展示的排障编号；trace_id 是追踪系统的关联标识；provider_request_id 是供应商返回的编号。三者可以关联，但职责不同。用户重试可能创建新的请求 id，却仍属于同一个业务任务；真正需要幂等的是业务操作标识，而不是随意复用日志编号。
结构化日志用 JSON 字段表达，不依赖在一长串字符串中解析。建议记录时间、级别、事件名、业务路由、版本、request_id、阶段、耗时、结果类别与上游状态。把“超时”与“用户取消”分开：取消并不一定是故障，却可能表示首字延迟太高。错误堆栈进内部日志，前端只拿安全错误码和关联编号。
原始提示词、完整答案、鉴权头、邮件地址不应成为默认日志。调查确实需要内容时，采用受控采样、字段脱敏、短保留期和授权查询。对数据做普通哈希并不等于彻底匿名化，低熵标识可以被枚举。指标标签也不能使用每个用户 id 或每条 prompt；高基数字段会让监控费用和查询负担急剧增加。
## 延迟与失败要有清晰口径
流式体验至少看三段：排队时间、首个有效内容到达时间、全部响应完成时间。HTTP 头返回很快而正文几十秒没到，用户仍然感觉卡住。空心跳不算首个有效内容。还要区分服务端耗时和浏览器感知耗时，后者包含网络、渲染和页面后台状态。
平均数容易掩盖慢请求，应配合 P50、P95、P99 与样本数量。小样本 P99 很不稳定，别对十条记录给出精细容量结论。错误率分母也要固定：按用户请求统计和按上游尝试统计会得到不同数字。一条请求重试三次才成功，用户成功率为百分之百，上游尝试成功率却更低。
链路跨服务时需要传播上下文，而不是每层重新生成 trace。采样可降低开销，但要说明哪些请求没被采集；不能因为追踪平台查不到就断定请求没发生。把版本、区域和模型路由留在有限枚举字段中，发布后按这些维度对比，通常比先看大段原文更有效。[追踪基础](https://opentelemetry.io/docs/concepts/observability-primer/)
## 成本不是简单的字符数乘单价
先记录事实用量，再计算费用。不同供应商、模型、输入缓存、输出、推理、图像、音频和工具可能有不同计量规则。字符数只能作粗略预算，不能代替真实 token 用量。最终结算以供应商用量和账单口径为准；某些错误、中断或重试也可能已经发生消耗，不应一律记零。
把价目表从代码中抽离，使用版本和生效时间。估计费用等于各类计量数量乘对应单位价格，再考虑供应商规则。不要把“缓存输入数”加到“总输入数”上重复计费；先核对该字段是子集还是独立用量。金额可以用最小货币单位整数或十进制定点库计算，避免浮点误差在大量请求中积累。
限额要同时考虑单次输出上限、每人速率、租户日预算、并发数与工具最大步数。请求前预留预算，完成后按实际用量结算，并处理请求失败时的预留释放。多个实例必须共享原子计数或事务，单进程变量无法保证全局预算。达到阈值后让产品展示明确状态，并允许低成本降级或稍后重试。
## 完整示例：一次请求、两次尝试、一份用量估计
保存以下文件为 observe.mjs，无需安装 npm 包。演示使用“教学计费单位”，不是任何厂商的真实价格。
```javascript
// observe.mjs
import { randomUUID } from "node:crypto";
import { performance } from "node:perf_hooks";
const requestId = randomUUID();
const started = performance.now();
const price = { version: "demo-v1", inputPer1000: 2, outputPer1000: 6 };
const attempts = [];
function log(event, fields = {}) {
// 显式白名单字段，避免把整个 HTTP 请求对象写进日志
console.log(JSON.stringify({
time: new Date().toISOString(), event, request_id: requestId, ...fields
}));
}
async function fakeProvider(attempt) {
if (attempt === 1) {
const err = new Error("模拟限流");
err.code = "RATE_LIMIT";
throw err;
}
return { text: "这是模拟回答", usage: { input: 500, output: 100 } };
}
async function main() {
log("request.started", { route: "answer", prompt_version: "v3" });
let result;
for (let attempt = 1; attempt <= 2; attempt++) {
const begin = performance.now();
try {
result = await fakeProvider(attempt);
attempts.push({ attempt, status: "ok", usage: result.usage });
log("provider.finished", {
attempt, status: "ok", duration_ms: performance.now() - begin
});
break;
} catch (err) {
attempts.push({ attempt, status: err.code, usage: null });
log("provider.failed", { attempt, code: err.code });
if (err.code !== "RATE_LIMIT" || attempt === 2) throw err;
// 演示等待；真实服务优先遵守 Retry-After，并加入抖动与总时限
await new Promise(resolve => setTimeout(resolve, 20));
}
}
const known = attempts.filter(a => a.usage !== null);
const input = known.reduce((n, a) => n + a.usage.input, 0);
const output = known.reduce((n, a) => n + a.usage.output, 0);
const estimatedUnits = input / 1000 * price.inputPer1000
+ output / 1000 * price.outputPer1000;
log("request.finished", {
status: "ok", attempts: attempts.length, input_tokens: input,
output_tokens: output, estimated_units: estimatedUnits,
price_version: price.version,
unknown_usage_attempts: attempts.filter(a => a.usage === null).length,
duration_ms: performance.now() - started
});
}
main().catch(err => {
log("request.failed", { code: err.code ?? "INTERNAL" });
process.exitCode = 1;
});
```
```bash
node observe.mjs
```
预期看到 started、failed、finished、finished 四条 JSON 事件，最后 attempts 为 2，输入 500、输出 100，estimated_units 为 1.6，unknown_usage_attempts 为 1。时间与 UUID 每次变化。示例故意把失败尝试用量记为未知，提醒你之后用供应商记录对账，不把它伪装成免费。
逐段解析：randomUUID 创建服务端可信关联编号；performance.now 测时避免系统时钟校准干扰；log 统一输出格式；fakeProvider 可控制失败，便于验证重试路径；最后汇总只计算已知用量，并把未知项作为独立事实。真实 API 返回字段需要经过适配层转换，不能假设每家都叫 input、output。
## 常见错误与排障
账单高于应用估计时，检查重试是否漏记、流中断是否没收到最终 usage、缓存口径是否算错、批任务是否绕过统一调用层，以及模型路由是否发生变化。不要先从修改单价“校平”差额开始。
日志显示耗时短但用户反馈慢，先核对计时起点，确认是否只测到 response headers；再测上传、首内容、完成和渲染时间。限流重试放大故障时，应限制总尝试和总等待时间，并在高峰时降并发。只追加重试次数通常会制造更多请求。
## 先从用户体验定义要观测的事件
一个请求并不是只有“开始”和“结束”。用户点击发送后，可能先等待上传，再等待队列，再进行检索，然后才发出模型调用。模型开始输出后还可能调用工具、再次生成或因网络中断失败。若所有阶段只记录一个总耗时，你能知道慢，却不知道应该改前端、队列、检索还是模型参数。
先定义业务完成事件。例如聊天任务只有收到完整结束状态才算成功；创建工单需要实际业务记录产生；导出报告需要文件已经可下载。把“模型输出了完成字样”记为成功会使监控数字漂亮，但用户任务可能根本没完成。最终状态应由执行记录决定，模型自然语言只作为展示内容。
前端与后端都应有各自的计时点。浏览器记录点击、请求发出、首个有效内容、渲染完成和用户取消；后端记录接收、排队、依赖调用与业务完成。两侧时钟可能不完全一致，不要直接用浏览器时间减服务器时间得到网络耗时。单侧持续时间使用单调时钟，跨系统关联靠请求标识和追踪上下文。
命名应围绕稳定事件，而不是临时调试文案。request.received、retrieval.completed 和 tool.failed 适合长期查询；“走到这里了三”无法支持聚合。字段值最好是有限且明确的枚举，错误原因分类型保留，必要详细说明放在受控字段。统一 schema 还需要版本管理，否则同名 duration 一会儿是秒一会儿是毫秒会产生难以发现的错误。
## 日志字段如何在并发请求中保持关联
在 Node 中，把 requestId 存在模块级变量会被并发请求覆盖。请求 A 等待网络时，请求 B 修改变量，A 后续日志就可能带上 B 的编号。这种错误在单人调试中不容易出现，一旦并发就让追踪失真。显式传上下文参数最容易理解；层级较深时，也可以使用 AsyncLocalStorage 管理异步调用范围。
AsyncLocalStorage.run(store, callback) 为回调及其派生异步链建立存储；getStore 在对应链上读取，在没有上下文时返回 undefined。它不是全局字典，也不是数据库事务。跨进程、队列或外部服务时仍需显式序列化和验证上下文；某些自定义异步桥接也需要检查传播是否正确。[Node 异步上下文](https://nodejs.org/api/async_context.html)
安全身份不应仅靠可观测字段决定。用户可以发送一个看似合法的 trace id，但它只用于关联，不能据此取得另一个租户的数据。入口可以接受符合协议的追踪上下文，同时生成自有业务请求编号，并限制字段长度。访问授权仍由验证过的会话决定，不能让日志系统反过来成为身份来源。
## 第二个完整示例：两条并发链各自保留上下文
保存为 context-log.mjs，Node.js 22，无第三方包、不调用网络。它故意让两条请求交错执行，验证关联不会串线。
```javascript
// context-log.mjs
import { AsyncLocalStorage } from "node:async_hooks";
import { setTimeout as sleep } from "node:timers/promises";
import assert from "node:assert/strict";
const context = new AsyncLocalStorage();
const events = [];
function record(event) {
const current = context.getStore();
if (!current) throw new Error("缺少请求上下文");
events.push({ requestId: current.requestId, event });
}
async function worker(requestId, delay) {
return context.run({ requestId }, async () => {
record("started");
await sleep(delay);
record("retrieved");
await sleep(1);
record("completed");
});
}
await Promise.all([worker("request-a", 15), worker("request-b", 2)]);
for (const id of ["request-a", "request-b"]) {
assert.deepEqual(events.filter(e => e.requestId === id).map(e => e.event),
["started", "retrieved", "completed"]);
}
console.log(JSON.stringify(events, null, 2));
console.log("两条异步链的上下文验证通过");
```
执行 node context-log.mjs，预期六条事件，每个 requestId 下都有 started、retrieved、completed。全局先后顺序可能不同，但各条业务链内部顺序应成立。随后在 context.run 外直接调用 record，应得到缺少上下文错误，而不是沿用某个已完成请求的身份。
代码用事件数组替代日志后端，是为了让行为可断言，不代表生产应该无限把日志积在内存。真实输出需要背压或缓冲上限，日志接收器失效时也不能无限占用应用内存。关键日志是否允许丢弃、哪些审计记录必须可靠保存，是业务要求，应与普通调试日志区分。
## 从一条链路走向指标和追踪系统
追踪的 span 表示一次有持续时间的操作。模型调用 span 可以包含模型路由、尝试次数和结果状态；工具 span 可以包含工具名和稳定错误码；不要默认包含完整参数或返回正文。把请求 id 与 span 关联后，指标告警可以定位到代表性慢请求，再沿父子关系找出耗时来源。
分布式追踪需要传播父上下文。如果每个服务都创建一个全新 trace，你会得到多段独立记录，看不到同一请求如何经过它们。队列任务还可能晚于原 HTTP 请求执行，应该记录显式关联关系，不要让一个请求 span 一直悬挂几个小时。后台任务的重试也需要区分同一业务任务和不同执行尝试。
采样决定保存哪些追踪。只随机保留一部分能控制开销，但稀有错误可能恰好没被保留；按错误和慢请求结果保留需要相应处理架构和缓冲。无论采用哪种策略，都要让查询者知道数据是否完整。审计记录、费用账目和业务事实不应依赖普通追踪采样，因为被采样掉的请求仍然真实发生过。
指标通常使用计数器、直方图或当前值。请求总数适合持续累计的计数；耗时适合能观察分布的直方图；排队数量适合当前值。计数器因进程重启归零时，监控查询要按系统提供的速率语义处理，不能把两个时刻直接相减后解释成负流量。[OpenTelemetry 指标](https://opentelemetry.io/docs/concepts/signals/metrics/)
## 成本估计需要一次有状态的结算过程
调用前你通常不知道精确输出用量，所以预算控制需要预留，而不是等账单出来才判断能否调用。预留量可基于已知输入、最大输出和工具预算给出保守估计。估计过于乐观会超支，过于保守会过早拒绝请求；应该记录估计与实际差异，再调整策略，而不是承诺永不超额。
调用结束有三种情况：拿到实际用量、明确未执行、执行状态未知。第一种结算并释放差额；第二种在有可靠证据时释放预留；第三种保留待核对状态，之后通过供应商记录或任务查询结算。网络超时不能自动归入免费失败，否则高峰重试会不断释放预算并继续产生真实费用。
账目还需要区分业务任务与尝试。一次用户请求重试三次，可能有三笔上游消耗，但只产生一次用户可见答案。业务报表可以按任务汇总，底层用量必须保留每次尝试，再按统一规则关联。请求取消之后，模型是否真的停止、最终 usage 是否收到，都应影响结算状态。
## 第三个完整示例：预算预留与结算
保存为 budget-ledger.mjs，Node.js 22，仅使用整数教学单位，不代表任何厂商价格。它是单进程内存账本，展示状态转换；分布式环境需要数据库事务或原子操作。
```javascript
// budget-ledger.mjs
import assert from "node:assert/strict";
function createBudget(total) {
let available = total;
const holds = new Map();
return {
reserve(id, amount) {
if (!Number.isSafeInteger(amount) || amount < 0) throw new Error("金额无效");
if (holds.has(id)) throw new Error("预留编号重复");
if (available < amount) return false;
available -= amount;
holds.set(id, { amount, state: "reserved" });
return true;
},
settle(id, actual) {
const hold = holds.get(id);
if (!hold || hold.state !== "reserved") throw new Error("预留不可结算");
if (!Number.isSafeInteger(actual) || actual < 0) throw new Error("实际用量无效");
// 若实际超过预留，余额可为负，必须暴露超额而不是截断账目
available += hold.amount - actual;
hold.state = "settled";
hold.actual = actual;
},
snapshot() {
return { available, pending: [...holds.values()].filter(h => h.state === "reserved").length };
}
};
}
const ledger = createBudget(100);
assert.equal(ledger.reserve("attempt-a", 70), true);
assert.equal(ledger.reserve("attempt-b", 40), false);
ledger.settle("attempt-a", 50);
assert.equal(ledger.reserve("attempt-b", 40), true);
console.log(ledger.snapshot()); // 余额 10，另有一笔 40 单位等待结算
try { ledger.settle("attempt-a", 50); }
catch (error) { console.log(error.message); }
```
执行 node budget-ledger.mjs，预期 available 为十、pending 为一，随后报告预留不可结算。重复结算被拒绝，避免把同一差额返还两次。把第一次实际用量改成一百一十，可观察余额变成负数；系统应停止新增请求并调查估计误差，而不是把实际账目改成预留值。
生产幂等结算通常还需要返回原结算结果，而不是简单拒绝重复；本例用拒绝方式使错误明显。操作编号、租户、价格版本和请求参数应绑定，防止不同任务误用同一笔预留。跨实例时，“先检查余额再扣减”必须在一个原子操作内完成，否则两个并发请求可能同时看到足够余额。
## 用服务目标设计告警，不让告警变成噪声
告警需要说明受影响的业务、观察窗口、样本量与行动。例如“最近十分钟生成完成率持续下降且至少出现一定数量请求”，比“某次请求失败”更适合服务告警。安全越权或高金额异常则可能单次就值得关注。阈值应该来自业务容忍度和历史分布，不能复制别人系统的数字。
同时观察请求量很重要：流量突然归零时错误率可能也为零，但服务未必正常。可以增加端到端合成探测验证入口和关键依赖，但探测数据必须与真实用户统计区分。AI 探测可以使用便宜且可确定判断的小任务，并限制频率；不能让监控本身制造大量模型费用。
告警触发后应有短而具体的排查顺序：确认影响范围，按版本或区域切片，查看慢阶段和错误类型，再决定回滚、降级或限流。操作完成后继续观察相同指标，而不是只看一次请求成功。若每次告警都没有明确动作，应该调整告警设计，而不是让所有人习惯忽略。
## 缓存命中如何影响观测结论
缓存会同时改变耗时和费用，因此对比发布前后表现时需要记录命中情况。新版看起来更快，可能只是这批请求重复更多，而不是代码优化。将冷请求、应用缓存命中、供应商输入缓存等状态分开，才能解释改善来源；不同缓存的计费与失效规则也不能混用。
缓存 key 还必须包含影响结果的版本和权限范围。少了提示词版本可能返回旧答案，少了租户或文档权限信息可能泄漏数据。监控应该关注命中率、错误失效和过期结果比例，而不是只追求命中率越高越好。缓存是产品正确性的一部分，费用下降不能抵消错误数据被持续复用。
## 综合练习：把未知用量留在账本里
练习要求模拟一笔请求已发出但连接中断，不能立即释放预留。稍后查询到实际用量后结算；重复查询不能再次增加余额。可以直接复用 createBudget，在 reserve 后不调用 settle，观察 pending 维持为一。
参考实现与解释
在 budget-ledger.mjs 的 createBudget 定义之后，用下面完整场景替换原演示入口。第一次快照表示结果未知，第二次表示已核对，第三次重复结算被明确阻止。真实服务将“已核对”状态持久保存，恢复进程后继续使用同一个操作编号。
```javascript
const budget = createBudget(100);
budget.reserve("unknown-call", 60);
console.log("连接中断，等待核对", budget.snapshot());
budget.settle("unknown-call", 45);
console.log("完成核对", budget.snapshot());
try { budget.settle("unknown-call", 45); }
catch { console.log("重复结算未改变余额", budget.snapshot()); }
```
预期余额先为四十且一笔待结算，核对后为五十五且没有待结算，重复结算后仍为五十五。此片段依赖本章 createBudget，不能单独保存运行；按说明替换入口后，完整文件仍用 node budget-ledger.mjs 执行。
参考答案
fakeProvider 的两次分支都抛出 RATE_LIMIT 后，第二次 catch 会继续抛出，main 的统一 catch 输出一次请求失败。对成功但无 usage 的响应，用适配层生成 usage: null，把它计入 unknown_usage_attempts。费用状态改为 estimated 或 incomplete，只有与账单对齐后才标 reconciled。生产上使用共享预算存储，在发起每次尝试前执行原子预留，不能依赖日志事后阻止花费。