三次调用之后,日志对不上了
「回声」的三能力样本链路跑成功了:检索重排、内容摘要、回复生成依次完成,成本 3,786 微元,端到端 1,269ms。用户投诉回复慢,团队打开日志,却只能看到三条彼此独立的请求记录:每条都有 requestId、模型名、token 数和耗时,但没有任何字段说明第二条属于哪次工作流、它的上游是谁、这是第几次尝试。
卷一第 12 章已经把单次请求的观测字段讲清楚了:traceId、requestId、模型、区域、分段耗时、用量、错误类别、降级原因。那些字段是原子,不是链路。把三个原子并排放进日志,仍然拼不出一条可解释的编排:重试会把同名节点写成两条记录,并行分支的耗时无法判断谁在关键路径上,提示改版后更无法回答「这次失败用的是哪版提示」。
编排观测要新增的,是四类关系:这次调用属于哪次工作流、它的父节点是谁、这是第几次尝试、它消费了哪一版上游交接产物。本节只定义回答这四类关系所需的最小字段,不重复单次请求字段。文中数字都来自 ai-lab 示例样本上的运行结果,不是生产实测。
九个字段与它们的采集边界
最小字段不是「越少越好」,而是「少一个就无法重建链路」。九个字段分成三组:
| 字段 | 采集位置 | 回答的问题 | 缺失后的症状 |
|---|---|---|---|
workflowId | 根 span start | 属于哪次业务运行 | 无法把三条调用归并成一次交付 |
nodeId / spanId | 每个 span start | 这是哪个节点、哪一次执行 | 同名节点重试后互相覆盖 |
parentSpanId | 每个 span start | 谁发起了这次调用 | 只能看到平铺列表,画不出树 |
attempt | 每个 span start | 这是第几次尝试 | 重试被当成两个不同节点 |
modelId / promptVersion | 能力节点 start | 用的哪版模型与提示 | 事故后无法按版本归因 |
handoffToken / handoffTokens | 非根节点 start | 消费了哪版上游产物、带了多少 token | 交接成本与版本错配无法追查 |
durationMs | 每个 span end | 节点自身耗时 | 只能看到端到端总数 |
errorCode | 每个 span end | 失败属于哪一类 | 重试与告警口径分裂 |
degraded / degradedReason | 每个 span end | 是否降级、为什么 | 降级被误记为成功 |
三能力样本的交接 token 是 820,共享上下文是 3,200。handoffTokens 记录本次交接实际携带的 820 个 token;handoffToken 是一个稳定令牌,用来把下游结果指回上游产物的版本。只有令牌没有数量,算不出交接成本;只有数量没有令牌,事故里对不上是哪一版上游结果。
为什么必须在节点边界采集
这些字段里有六个只能在节点边界拿到,事后聚合补不出来。
第一,parentSpanId 是调用事实。编排器在发起子调用时知道父 span,日志聚合器只看到两条独立记录。第三章的执行图边表达数据依赖,trace 的父子关系表达调用关系,两者不能互相替代:一个汇合节点可能依赖两条边,但只由最后一个完成的父调用发起。
第二,promptVersion 属于能力实现,不属于网关。网关只知道模型名;提示版本在能力节点组装请求时才能确定。事故后要回答「是不是 v12 提示导致的」,就必须在调用发生的那一刻写下版本。
第三,handoffToken 只存在于交接动作中。上游产出结果时生成令牌,下游消费时携带;中间任何一层日志系统都无法凭空重建这个对应关系。
第四,attempt 必须在重试发起时递增。等到失败后补写,重试与并行分支就无法区分:两者都会产生同名节点的多条记录。
第五,durationMs 必须由节点自己结束计时。用上下游时间戳相减,会把排队、交接和下游等待都算进节点耗时,关键路径就失去意义。
第六,degraded 是节点的自我声明。模板兜底、缓存答案、跳过可选步骤,只有执行节点知道;从错误码看不出来,因为降级通常没有错误码。
采集方式因此是两段式:span 开始时写身份与版本,span 结束时写结果与代价。一次尝试一对事件,重试就是第二对。start 事件不允许携带耗时、成本或终态,否则同一字段会出现两个事实来源。
从事件重建树与关键路径
拿到成对事件后,重建分三步。
第一步配对:按 spanId 把 start 与 end 合成一个 span,finishOffsetMs = startOffsetMs + durationMs。缺 end 的 span 直接拒绝,不用零值补齐,否则一条断掉的调用会被算成瞬时完成。
第二步建树:按 parentSpanId 挂孩子,按开始时间排序。排序必须稳定,否则同一份 trace 两次重建会得到不同顺序,回放无法比较。
第三步走关键路径:从根 span 出发,每次选择「最后结束的孩子」继续下探,直到叶子。返回的是墙钟路径,包含重试空档与交接延迟;再把路径上的节点耗时相加,两者之差就是等待与交接。这个算法不要求子 span 完全包含在父 span 内,因为父节点只记录自己的执行区间,不记录整棵子树。
三能力样本的路径是 search.rerank → content.summarize → chat.reply。关键路径 1,269ms,节点忙碌 1,199ms,差值 70ms 正好是两次 35ms 交接。重试样本里,摘要第一次尝试 40ms 超时,第二次 620ms 成功,关键路径选择第二次,attempt 序列是 [1, 2, 1]。
实现
下面的模块只做四件事:定义事件、校验边界字段、重建树、算关键路径。它不做 I/O,也不访问模型;输入是一组已经采集好的事件,输出是可断言的确定性结构。
// file: src/orch/observability.ts
// tier: L2
// verify: node --test test/orch/observability.test.ts
import { AiError } from "../core/errors.ts";
import type { AiErrorKind } from "../core/errors.ts";
export const TRACE_SCHEMA_VERSION = 1;
export type TracePhase = "start" | "end";
export type NodeKind = "workflow" | "capability" | "human" | "action";
export type TraceStatus = "ok" | "degraded" | "error" | "skipped";
/**
* 一次编排 trace 的最小事件。start 与 end 成对出现:
* 身份与版本在 start 采集,结果与代价在 end 采集。
*/
export interface WorkflowTraceEvent {
schemaVersion: number;
phase: TracePhase;
workflowId: string;
traceId: string;
spanId: string;
parentSpanId: string | null;
nodeId: string;
nodeKind: NodeKind;
attempt: number;
capability: string;
modelId: string | null;
promptVersion: string | null;
/** 上游交接令牌;根节点为 null,用于把下游结果与上游产物版本对齐。 */
handoffToken: string | null;
/** 本次交接携带的 token 数;根节点为 0,三能力样本为 820。 */
handoffTokens: number;
/** 相对 workflow 起点的开始时间,毫秒。 */
startOffsetMs: number;
/** 仅 end:节点自身耗时,毫秒。 */
durationMs: number;
/** 仅 end:节点计费,整数微元;start 固定为 0。 */
costMicros: number;
status: TraceStatus;
errorCode: AiErrorKind | null;
degraded: boolean;
degradedReason: string | null;
}
/** 这些字段无法事后补采,必须由节点边界上的埋点直接写出。 */
export const BOUNDARY_FIELDS: Record<TracePhase, readonly (keyof WorkflowTraceEvent)[]> = {
start: ["schemaVersion", "workflowId", "traceId", "spanId", "parentSpanId", "nodeId",
"nodeKind", "attempt", "capability", "modelId", "promptVersion",
"handoffToken", "handoffTokens", "startOffsetMs"],
end: ["spanId", "durationMs", "costMicros", "status", "errorCode", "degraded", "degradedReason"],
};
export interface TraceIssue {
path: string;
code: string;
message: string;
}
const KINDS: readonly NodeKind[] = ["workflow", "capability", "human", "action"];
const STATUSES: readonly TraceStatus[] = ["ok", "degraded", "error", "skipped"];
const ID_FIELDS = ["workflowId", "traceId", "spanId", "nodeId", "capability"] as const;
function isRecord(value: unknown): value is Record<string, unknown> {
return typeof value === "object" && value !== null && !Array.isArray(value);
}
function text(value: unknown): boolean {
return typeof value === "string" && value.trim() !== "";
}
function count(value: unknown, min = 0): boolean {
return typeof value === "number" && Number.isInteger(value) && value >= min;
}
function push(issues: TraceIssue[], path: string, code: string, message: string): void {
issues.push({ path, code, message });
}
/** 边界校验返回问题列表而不抛异常:坏事件可以同时进入告警与拒收统计。 */
export function validateTraceEvent(value: unknown): TraceIssue[] {
if (!isRecord(value)) return [{ path: "$", code: "not-object", message: "event 必须是对象" }];
const issues: TraceIssue[] = [];
if (value.schemaVersion !== TRACE_SCHEMA_VERSION) push(issues, "schemaVersion", "bad-version", `必须等于 ${TRACE_SCHEMA_VERSION}`);
if (value.phase !== "start" && value.phase !== "end") push(issues, "phase", "bad-phase", "必须是 start 或 end");
for (const field of ID_FIELDS) if (!text(value[field])) push(issues, field, "empty", "必须是非空字符串");
if (value.parentSpanId !== null && !text(value.parentSpanId)) push(issues, "parentSpanId", "bad-parent", "必须是 null 或非空字符串");
if (!KINDS.includes(value.nodeKind as NodeKind)) push(issues, "nodeKind", "bad-kind", "未知节点类型");
if (!count(value.attempt, 1)) push(issues, "attempt", "bad-attempt", "必须是 >= 1 的整数");
if (!count(value.startOffsetMs)) push(issues, "startOffsetMs", "bad-offset", "必须是非负整数");
if (!count(value.handoffTokens)) push(issues, "handoffTokens", "bad-handoff", "必须是非负整数");
if (value.parentSpanId === null) {
if (value.handoffTokens !== 0) push(issues, "handoffTokens", "root-handoff", "根节点不得携带交接 token");
if (value.handoffToken !== null) push(issues, "handoffToken", "root-handoff", "根节点交接令牌必须为 null");
} else {
if (!text(value.handoffToken)) push(issues, "handoffToken", "missing-handoff", "非根节点必须有交接令牌");
if (!count(value.handoffTokens, 1)) push(issues, "handoffTokens", "missing-handoff", "非根节点交接 token 必须 >= 1");
}
if (value.nodeKind === "capability") {
if (!text(value.modelId)) push(issues, "modelId", "missing-model", "能力节点必须记录模型版本");
if (!text(value.promptVersion)) push(issues, "promptVersion", "missing-prompt", "能力节点必须记录提示版本");
} else if (value.nodeKind === "human" && (value.modelId !== null || value.promptVersion !== null)) {
push(issues, "modelId", "human-model", "人工节点不应携带模型或提示版本");
}
if (!count(value.durationMs)) push(issues, "durationMs", "bad-duration", "必须是非负整数");
if (!count(value.costMicros)) push(issues, "costMicros", "bad-cost", "必须是非负整数");
if (!STATUSES.includes(value.status as TraceStatus)) push(issues, "status", "bad-status", "未知终态");
if (value.status === "error" && value.errorCode === null) push(issues, "errorCode", "missing-error", "error 必须带错误码");
if (value.status !== "error" && value.errorCode !== null) push(issues, "errorCode", "unexpected-error", "非 error 不得带错误码");
if (value.degraded !== (value.status === "degraded")) push(issues, "degraded", "degrade-mismatch", "degraded 必须与 status 一致");
if (value.status === "degraded" && !text(value.degradedReason)) push(issues, "degradedReason", "missing-degrade", "降级必须写明原因");
if (value.status !== "degraded" && value.degradedReason !== null) push(issues, "degradedReason", "unexpected-degrade", "非降级不得带降级原因");
if (value.phase === "start") {
if (value.durationMs !== 0 || value.costMicros !== 0) push(issues, "$", "start-has-result", "start 事件不得包含耗时或成本");
if (value.status !== "ok" || value.errorCode !== null || value.degraded) push(issues, "$", "start-has-outcome", "start 事件不得包含终态");
}
return issues;
}
export interface TraceNode extends WorkflowTraceEvent { finishOffsetMs: number; }
export interface CriticalStep { spanId: string; nodeId: string; attempt: number; finishOffsetMs: number; }
export interface TraceSummary {
workflowId: string; traceId: string; spans: number; attempts: number; retries: number;
failures: number; degraded: number; totalCostMicros: number; endOffsetMs: number;
rootSpanId: string; nodes: TraceNode[]; children: Record<string, string[]>;
criticalPath: CriticalStep[]; criticalPathMs: number; busyMs: number; handoffMs: number;
}
/** 值为 null 也算已采集;缺键或 undefined 才算缺失。 */
export function missingBoundaryFields(event: WorkflowTraceEvent): string[] {
return BOUNDARY_FIELDS[event.phase].filter(
(field) => !(field in event) || event[field] === undefined,
);
}
function fail(message: string): never {
throw new AiError("invalid-output", `observability: ${message}`);
}
function assertTrace(events: readonly WorkflowTraceEvent[]): void {
if (events.length === 0) fail("trace 至少需要一条事件");
const issues = events.flatMap((event, index) =>
validateTraceEvent(event).map((issue) => ({ ...issue, path: `events[${index}].${issue.path}` })),
);
if (issues.length > 0) fail(issues.map((issue) => `${issue.path}: ${issue.message}`).join("; "));
const starts = new Map<string, WorkflowTraceEvent>();
const ends = new Map<string, WorkflowTraceEvent>();
for (const event of events) {
const target = event.phase === "start" ? starts : ends;
if (target.has(event.spanId)) fail(`span ${event.spanId} 的 ${event.phase} 事件重复`);
target.set(event.spanId, event);
}
for (const spanId of starts.keys()) {
if (!ends.has(spanId)) fail(`span ${spanId} 缺少 end 事件`);
}
if (starts.size !== ends.size) fail(`start 与 end 数量不一致:${starts.size} vs ${ends.size}`);
const roots = [...starts.values()].filter((event) => event.parentSpanId === null);
if (roots.length !== 1) fail(`trace 必须恰好有一个根 span,实际 ${roots.length}`);
if (roots[0].nodeKind !== "workflow") fail("根 span 必须是 workflow 节点");
for (const event of starts.values()) {
if (event.parentSpanId === null) continue;
if (event.parentSpanId === event.spanId) fail(`span ${event.spanId} 指向自己`);
const parent = starts.get(event.parentSpanId);
if (!parent) fail(`span ${event.spanId} 的父 span ${event.parentSpanId} 不存在`);
if (event.startOffsetMs < parent.startOffsetMs) fail(`span ${event.spanId} 早于父 span 开始`);
const chain = new Set<string>([event.spanId]);
let cursor: WorkflowTraceEvent | undefined = event;
while (cursor.parentSpanId !== null) {
if (chain.has(cursor.parentSpanId)) fail(`span ${event.spanId} 的父链存在环`);
chain.add(cursor.parentSpanId);
cursor = starts.get(cursor.parentSpanId);
}
}
}
/**
* 从事件重建节点树与关键路径。关键路径沿“父链上最后结束的孩子”下探,
* 返回的是墙钟路径,包含重试空档与交接延迟。
*/
export function rebuildTrace(events: readonly WorkflowTraceEvent[]): TraceSummary {
assertTrace(events);
const starts = new Map<string, WorkflowTraceEvent>();
const ends = new Map<string, WorkflowTraceEvent>();
for (const event of events) {
(event.phase === "start" ? starts : ends).set(event.spanId, event);
}
const bySpan = new Map<string, TraceNode>();
for (const [spanId, start] of starts) {
const end = ends.get(spanId) as WorkflowTraceEvent;
bySpan.set(spanId, { ...start, ...end, finishOffsetMs: start.startOffsetMs + end.durationMs });
}
const nodes = [...bySpan.values()].sort(
(left, right) => left.startOffsetMs - right.startOffsetMs || left.spanId.localeCompare(right.spanId),
);
const children: Record<string, string[]> = {};
for (const node of nodes) {
if (node.parentSpanId !== null) (children[node.parentSpanId] ??= []).push(node.spanId);
}
for (const list of Object.values(children)) {
list.sort((left, right) => (bySpan.get(left) as TraceNode).startOffsetMs - (bySpan.get(right) as TraceNode).startOffsetMs);
}
const root = nodes.find((node) => node.parentSpanId === null) as TraceNode;
const path: TraceNode[] = [];
let cursor: TraceNode | undefined = root;
while (cursor) {
path.push(cursor);
cursor = (children[cursor.spanId] ?? [])
.map((spanId) => bySpan.get(spanId) as TraceNode)
.sort((left, right) => right.finishOffsetMs - left.finishOffsetMs || left.spanId.localeCompare(right.spanId))[0];
}
const body = path.filter((node) => node.spanId !== root.spanId);
const endsList = [...ends.values()];
const criticalPathMs = (body.at(-1)?.finishOffsetMs ?? root.finishOffsetMs) - root.startOffsetMs;
const busyMs = body.reduce((total, node) => total + node.durationMs, 0);
return {
workflowId: root.workflowId,
traceId: root.traceId,
spans: nodes.length,
attempts: endsList.length,
retries: endsList.filter((event) => event.attempt > 1).length,
failures: endsList.filter((event) => event.status === "error").length,
degraded: endsList.filter((event) => event.status === "degraded").length,
totalCostMicros: endsList
.filter((event) => event.nodeKind !== "workflow")
.reduce((total, event) => total + event.costMicros, 0),
endOffsetMs: Math.max(...endsList.map((event) => (bySpan.get(event.spanId) as TraceNode).finishOffsetMs)),
rootSpanId: root.spanId,
nodes,
children,
criticalPath: body.map((node) => ({
spanId: node.spanId,
nodeId: node.nodeId,
attempt: node.attempt,
finishOffsetMs: node.finishOffsetMs,
})),
criticalPathMs,
busyMs,
handoffMs: criticalPathMs - busyMs,
};
}
validateTraceEvent 返回问题列表而不是抛异常。一条坏事件可以同时进入告警、拒收统计和采样决策;如果校验器只会抛异常,聚合侧就只剩一个失败计数。
assertTrace 在重建前检查三件事:start/end 必须成对、根 span 必须唯一且是 workflow 类型、父 span 必须存在且不早于自己开始。父链存在环时直接拒绝,因为环会让关键路径永不终止。
rebuildTrace 的 totalCostMicros 排除了根 span,避免把工作流总成本与节点成本重复相加。busyMs 与 handoffMs 分开返回,是因为它们对应不同的优化动作:前者要换模型或缩输出,后者要减少交接次数。
示例样本上的运行结果
对三能力样本与一个重试变体分别重建,结果如下。所有数字来自 node --test test/orch/observability.test.ts 的确定性断言。
| 指标 | 主样本 | 重试变体 |
|---|---|---|
| span 数 | 4 | 5 |
| 尝试次数 | 4 | 5 |
| 重试次数 | 0 | 1 |
| 失败次数 | 0 | 1 |
| 总成本 | 3,786 微元 | 3,906 微元 |
| 关键路径 | 1,269ms | 1,269ms |
| 节点忙碌 | 1,199ms | 1,124ms |
| 交接等待 | 70ms | 145ms |
| 路径上的 attempt | 1 / 1 / 1 | 1 / 2 / 1 |
重试变体的关键路径没有变长,因为第一次尝试只花了 40ms,第二次从 270ms 开始,仍在原来的交付窗口内完成。但它多花了 120 微元,并把失败次数从 0 变成 1。如果没有 attempt 与 errorCode,这两条记录会被读成「摘要节点跑了两次」,而不是「一次失败加一次成功」。
字段少,不等于采集少
九个字段是下限,不是上限。成本、token 用量、缓存命中、队列等待都可以加,但都必须遵守两条边界:原文不进观测链路,只留长度与摘要;可选字段不能替代必填字段。提示词原文、用户输入、上游结果正文都不应该出现在 trace 事件里,否则观测系统会变成第二个数据泄漏面。
字段一旦定下,就要有 schema 版本。schemaVersion 不匹配的事件应该被拒收并计数,而不是让下游按缺失字段猜。编排链路的观测数据往往跨多个服务、多个版本,版本漂移是常态,不是异常。
小结
编排 trace 的最小字段回答四类关系:属于哪次工作流、父节点是谁、第几次尝试、消费了哪版上游产物。九个字段分两段采集:身份与版本在节点 start 写入,耗时、错误码与降级标记在节点 end 写入。从成对事件重建树,再沿「最后结束的孩子」下探,就得到包含重试空档与交接延迟的关键路径。
三能力样本重建出 4 个 span、3,786 微元、1,269ms,其中节点忙碌 1,199ms、交接 70ms。重试变体多一个 span、多 120 微元,关键路径不变。这些数字说明:没有 attempt 与版本字段,重试和改版都会被读成同一次执行。
阅读导航:上一节:9.3 注入在多能力间的传播 · 下一节:10.2 节点级 SLO 与整体 SLO 。
常见错误与边界
- 用
requestId当workflowId。一次工作流包含多次请求,前者是原子,后者是容器。 - 只记录节点名,不记录
spanId与attempt。重试和并行分支会互相覆盖。 - 让网关写
promptVersion。网关不知道能力层用的是哪版提示,只能猜。 - 在 end 事件里补写模型与提示版本。重试跨版本时,补写会记成同一版。
- 用上下游时间戳相减算节点耗时。排队、交接和下游等待都会被算进来。
- 把 trace 的父子关系当成执行图的数据依赖。前者是调用事实,后者是依赖事实。
- 缺失字段用零值补齐。零耗时会被算进关键路径,零成本会低估事故损失。
- 把 prompt 原文写进 trace。观测链路只保留版本、长度与摘要。
- 不校验 schema 版本。旧版本事件缺字段时,下游会把缺失当成正常。
- 把示例样本的 820 token 当成所有链路的交接量。交接结构一变,数量就要重算。
继续阅读
探索更多技术文章
浏览归档,发现更多关于系统设计、工具链和工程实践的内容。