订单接口用了三百多毫秒。数据库执行也是三百多毫秒,还是应用在取连接之前等了三百多毫秒?这两个问题会把值班者带向不同的人和不同的改动。只看接口耗时,再打开一条“查询成功”的日志,无法作出这个区分。
下面的实验只使用 Node 内置模块。模拟应用和依赖在同一进程内,通过序列化载体传递上下文;程序用离散时间安排请求,输出结构化日志、窗口计数和手工构造的 span。全部耗时来自模型输入与计算,未启动 HTTP 服务、数据库、OpenTelemetry SDK 或 Prometheus,也没有测量本机延迟。固定输入让你可以逐项复算,代价是它无法代表真实网络与调度行为。
实验把订单按时返回定义为成功:内容正确且模拟耗时不超过二百毫秒。超过门槛的请求依然返回二百状态码,正文也含订单,但记作不良请求。这里的 deadline_exceeded 表示服务目标超时,不表示客户端取消或传输失败。若你的系统会在二百毫秒时中止工作,就要增加取消、连接归还和下游仍在执行的模型,不能照抄这份时间账。
先运行,再从窗口里挑请求
下面给出三个完整文件。把它们放在同一目录,用 Node.js 运行;本次使用 v26.8.1、Darwin arm64,未测试其他版本。simulate.mjs 生成事件,diagnose.mjs 执行关联查询,check.mjs 验证时间归账和反例。全部使用内置模块,不依赖文章所在网站或项目包。
生成器和有界队列
文件名为 simulate.mjs。
import assert from 'node:assert/strict';
// Discrete-event model. No sockets, SDK, collector, database, or wall-clock timing.
export class BoundedExporter {
constructor(maxRecords = 128, maxBytes = 65536, maxRecordBytes = 4096) {
this.maxRecords = maxRecords;
this.maxBytes = maxBytes;
this.maxRecordBytes = maxRecordBytes;
this.queue = [];
this.bytes = 0;
this.dropped = 0;
this.failedFlushes = 0;
}
offer(record) {
const json = JSON.stringify(record);
const bytes = Buffer.byteLength(json);
if (bytes > this.maxRecordBytes || this.queue.length >= this.maxRecords ||
this.bytes + bytes > this.maxBytes) {
this.dropped++;
return false;
}
this.queue.push({ json, bytes });
this.bytes += bytes;
return true;
}
flush(available) {
if (!available) {
this.failedFlushes++;
return [];
}
const result = this.queue.map(x => JSON.parse(x.json));
this.queue = [];
this.bytes = 0;
return result;
}
}
const epoch = Date.parse('2026-09-08T02:00:00.000Z');
const stamp = ms => new Date(epoch + ms).toISOString();
const hex = (n, width) => n.toString(16).padStart(width, '0');
const scenarios = [
{ name: 'baseline', base: 0, interval: 40, slots: 1, held: 0, execution: 20 },
{ name: 'queue', base: 60000, interval: 10, slots: 1, held: 300, execution: 20 },
{ name: 'execution', base: 120000, interval: 40, slots: 8, held: 0, execution: 320 },
{ name: 'recovered', base: 180000, interval: 10, slots: 2, held: 0, execution: 20 },
];
function extract(header) {
const match = /^00-([0-9a-f]{32})-([0-9a-f]{16})-(00|01)$/.exec(header);
assert.ok(match && !/^0+$/.test(match[1]) && !/^0+$/.test(match[2]));
return { trace_id: match[1], parent_span_id: match[2], sampled: match[3] === '01' };
}
export function simulate() {
const events = [];
let serial = 1;
for (const [scenarioIndex, s] of scenarios.entries()) {
const exporter = new BoundedExporter();
const slots = Array(s.slots).fill(s.base + s.held);
const durations = [];
let bad = 0;
const common = { simulation: true, scenario: s.name, environment: 'lab',
release: 'lab-v1', route: '/orders/:id' };
for (let i = 0; i < 8; i++) {
const arrival = s.base + i * s.interval;
const ready = arrival + 3;
const slot = slots.indexOf(Math.min(...slots));
const acquired = Math.max(ready, slots[slot]);
const executed = acquired + s.execution;
slots[slot] = executed;
const ended = executed + 5;
const duration = ended - arrival;
const queue = acquired - ready;
const sampled = !(s.name === 'queue' && i === 5);
const trace = hex(scenarioIndex * 100 + i + 1, 32);
const root = hex(serial++, 16);
const wait = hex(serial++, 16);
const client = hex(serial++, 16);
const server = hex(serial++, 16);
const query = hex(serial++, 16);
const request = `${s.name}-r${String(i + 1).padStart(2, '0')}`;
const traceparent = `00-${trace}-${client}-${sampled ? '01' : '00'}`;
// Explicit serialized carrier models an application/dependency boundary.
const wire = JSON.parse(JSON.stringify({ headers: { traceparent } }));
const remote = extract(wire.headers.traceparent);
assert.equal(remote.trace_id, trace);
assert.equal(remote.parent_span_id, client);
function span(service, name, id, parent, start, end) {
if (!sampled) return;
exporter.offer({ ...common, kind: 'span', service, name, trace_id: trace,
span_id: id, parent_span_id: parent, request_id: request,
start_ms: start, end_ms: end, duration_ms: end - start });
}
span('order-app', 'request', root, null, arrival, ended);
span('order-app', 'pool.wait', wait, root, ready, acquired);
span('order-app', 'dependency.client', client, root, acquired, executed);
span('order-dependency', 'dependency.server', server, remote.parent_span_id, acquired, executed);
span('order-dependency', 'query.execute', query, server, acquired, executed);
events.push({ ...common, kind: 'log', event: 'dependency_completed',
service: 'order-dependency', timestamp: stamp(executed), request_id: request,
trace_id: remote.trace_id, span_id: server, sampled: remote.sampled,
execution_ms: s.execution, traceparent_received: wire.headers.traceparent });
const good = duration <= 200;
events.push({ ...common, kind: 'log', event: 'request_completed',
service: 'order-app', timestamp: stamp(ended), request_id: request,
trace_id: trace, span_id: root, sampled, status_code: 200,
business_outcome: 'order_returned', slo_good: good,
error_kind: good ? 'none' : 'deadline_exceeded', duration_ms: duration,
app_pre_ms: 3, pool_wait_ms: queue, dependency_execution_ms: s.execution,
app_post_ms: 5, pool_capacity: s.slots });
// Record EVERY completion; independent of trace export and sampled flag.
durations.push(duration);
if (!good) bad++;
}
events.push(...exporter.flush(true));
events.push({ ...common, kind: 'metric', service: 'order-app',
window_start: stamp(s.base), window_end: stamp(s.base + 1000),
unit: 'seconds', request_count: durations.length, bad_count: bad,
bad_ratio: bad / durations.length,
duration_buckets: [0.05, 0.2, 0.4, 1].map(le => ({ le,
count: durations.filter(ms => ms / 1000 <= le).length })),
duration_count: durations.length,
duration_sum: durations.reduce((a, b) => a + b, 0) / 1000,
exporter_dropped: exporter.dropped });
}
return events;
}
if (process.argv[1]?.endsWith('/simulate.mjs') || process.argv[1] === 'simulate.mjs') {
for (const event of simulate()) process.stdout.write(`${JSON.stringify(event)}\n`);
}
从窗口关联到请求的查询
文件名为 diagnose.mjs。
import { readFileSync } from 'node:fs';
import assert from 'node:assert/strict';
const [file, request = 'queue-r08'] = process.argv.slice(2);
assert.ok(file, 'usage: node diagnose.mjs run.jsonl [request_id]');
const events = readFileSync(file, 'utf8').trim().split('\n').map(JSON.parse);
const scope = x => x.environment === 'lab' && x.release === 'lab-v1' && x.route === '/orders/:id';
const alert = events.find(x => scope(x) && x.kind === 'metric' && x.scenario === 'queue');
assert.ok(alert && alert.request_count >= 8 && alert.bad_ratio > 0.25);
console.log(JSON.stringify({ step: 'alert', window_start: alert.window_start,
window_end: alert.window_end, bad: alert.bad_count, total: alert.request_count }));
const log = events.find(x => scope(x) && x.event === 'request_completed' &&
x.service === 'order-app' && x.request_id === request &&
x.timestamp >= alert.window_start && x.timestamp < alert.window_end && !x.slo_good);
assert.ok(log, 'no matching bad request in the alert scope');
console.log(JSON.stringify({ step: 'request', ...log }));
const spans = events.filter(x => scope(x) && x.kind === 'span' && x.trace_id === log.trace_id);
console.log(JSON.stringify({ step: 'spans', count: spans.length,
rows: spans.map(x => ({ service: x.service, name: x.name, span_id: x.span_id,
parent_span_id: x.parent_span_id, start_ms: x.start_ms, end_ms: x.end_ms,
duration_ms: x.duration_ms })) }));
const dependency = events.filter(x => scope(x) && x.event === 'dependency_completed' &&
x.trace_id === log.trace_id && x.request_id === log.request_id);
console.log(JSON.stringify({ step: 'dependency_logs', rows: dependency }));
console.log(JSON.stringify({ step: 'diagnosis', duration_ms: log.duration_ms,
pool_wait_ms: log.pool_wait_ms, execution_ms: log.dependency_execution_ms,
residual_ms: log.duration_ms - log.pool_wait_ms - log.dependency_execution_ms,
next: spans.length ? 'inspect pool holders and release paths; SQL execution is only 20ms here' :
'use phase fields and dependency log; check sampling/export health; inspect pool holders',
unresolved: 'why the initial pool slot was occupied is not observed' }));
阶段、采样和导出边界检查
文件名为 check.mjs。
import assert from 'node:assert/strict';
import { simulate, BoundedExporter } from './simulate.mjs';
const events = simulate();
const requests = events.filter(x => x.event === 'request_completed');
const spans = events.filter(x => x.kind === 'span');
assert.equal(requests.length, 32);
for (const request of requests) {
assert.equal(request.duration_ms, request.app_pre_ms + request.pool_wait_ms +
request.dependency_execution_ms + request.app_post_ms);
const trace = spans.filter(s => s.trace_id === request.trace_id);
assert.equal(trace.length, request.sampled ? 5 : 0);
for (const child of trace.filter(s => s.parent_span_id)) {
const parent = trace.find(s => s.span_id === child.parent_span_id);
assert.ok(parent);
assert.ok(child.start_ms >= parent.start_ms && child.end_ms <= parent.end_ms);
}
}
const metrics = events.filter(x => x.kind === 'metric');
assert.deepEqual(metrics.map(x => x.bad_count), [0, 8, 8, 0]);
assert.deepEqual(metrics.map(x => x.request_count), [8, 8, 8, 8]);
const queued = requests.find(x => x.request_id === 'queue-r08');
const slow = requests.find(x => x.request_id === 'execution-r08');
assert.deepEqual([queued.duration_ms, queued.pool_wait_ms, queued.dependency_execution_ms], [395, 367, 20]);
assert.deepEqual([slow.duration_ms, slow.pool_wait_ms, slow.dependency_execution_ms], [328, 0, 320]);
console.log(JSON.stringify({ check: 'request_accounting_and_span_tree', result: 'PASS',
requests: requests.length, spans: spans.length, bad_counts: metrics.map(x => x.bad_count) }));
const exporter = new BoundedExporter(3, 512, 256);
for (let i = 0; i < 100; i++) exporter.offer({ sequence: i });
assert.deepEqual(exporter.flush(false), []);
assert.equal(exporter.queue.length, 3);
assert.equal(exporter.dropped, 97);
assert.ok(exporter.bytes <= 512);
const retainedBytes = exporter.bytes;
assert.deepEqual(exporter.flush(true).map(x => x.sequence), [0, 1, 2]);
assert.equal(exporter.bytes, 0);
const oversized = new BoundedExporter(3, 512, 16);
assert.equal(oversized.offer({ message: 'x'.repeat(100) }), false);
assert.equal(oversized.dropped, 1);
console.log(JSON.stringify({ check: 'export_outage', result: 'PASS', offered: 100,
retained: 3, retained_bytes: retainedBytes, dropped: exporter.dropped,
failed_flushes: exporter.failedFlushes, drained_after_recovery: 3,
oversized_rejected: true }));
// Averages of per-instance percentiles have no pooled-percentile meaning.
const nearestRank = xs => [...xs].sort((a, b) => a - b)[Math.ceil(xs.length * 0.95) - 1];
const a = Array(100).fill(10), b = Array(10).fill(1000);
assert.equal((nearestRank(a) + nearestRank(b)) / 2, 505);
assert.equal(nearestRank([...a, ...b]), 1000);
console.log(JSON.stringify({ check: 'percentile_counterexample', result: 'PASS',
averaged_p95_ms: 505, pooled_nearest_rank_p95_ms: 1000,
prometheus_query_executed: false }));
在这三个文件所在目录执行:
node simulate.mjs > run.jsonl
node check.mjs
node diagnose.mjs run.jsonl queue-r08
node diagnose.mjs run.jsonl queue-r06
程序生成四批请求,每批八条。第一批按四十毫秒间隔到达,一个连接名额足够服务;第二批十毫秒到一条,唯一名额先由模型中的背景工作占用三百毫秒;第三批给足八个名额,却把执行时间调到三百二十毫秒;最后一批释放背景占用、给两个名额,执行时间回到二十毫秒。每批使用独立的池状态,第四批是参数对照,没有模拟真实事故恢复。
排队时间可以从输入直接算出。把第二批窗口起点记作零,第一条请求在第三毫秒完成前处理,却到第三百毫秒才取得名额,所以等待二百九十七毫秒。此后每次执行占二十毫秒,第八条直到第四百四十毫秒才能取得名额。它在第七十毫秒到达,第七十三毫秒开始等,差值正是三百六十七毫秒。最后加上二十毫秒执行和五毫秒后处理,结束时刻为第四百六十五毫秒。
这个计算没有借助随机延迟或真实休眠。输入数组按到达次序排列,同一个名额的下一次借出时间从上次执行结束时间推导。它能演示等待如何累积,却没有建模等待超时、取消和公平调度。若往输入里加入乱序到达时间,先排序再分配名额;把现有循环误当成通用调度器,会算出并不存在的等待。
这四批对应四个独立的一秒统计窗口,窗口起点之间隔一分钟。程序给日志写入固定的示例日期,方便表达时间过滤;模拟时钟没有等到那个时刻。每条请求都有三毫秒前处理和五毫秒后处理。连接按最早空闲名额分配,名额在依赖执行结束时归还;并发不足时,程序计算出等候时间。
本次检查脚本的原始标准输出如下;其中的PASS只覆盖脚本列出的模型断言。
{"check":"request_accounting_and_span_tree","result":"PASS","requests":32,"spans":155,"bad_counts":[0,8,8,0]}
{"check":"export_outage","result":"PASS","offered":100,"retained":3,"retained_bytes":42,"dropped":97,"failed_flushes":1,"drained_after_recovery":3,"oversized_rejected":true}
{"check":"percentile_counterexample","result":"PASS","averaged_p95_ms":505,"pooled_nearest_rank_p95_ms":1000,"prometheus_query_executed":false}
本次执行得到以下窗口结果。它们是程序对模拟完成事件的统计,不是从追踪样本反推,也不是抓取真实服务得到的速率。
| 模型窗口 | 请求数 | 不良数 | 总耗时范围 | 连接等待范围 | 执行耗时 |
|---|---|---|---|---|---|
| baseline | 8 | 0 | 28 ms | 0 ms | 20 ms |
| queue | 8 | 8 | 325–395 ms | 297–367 ms | 20 ms |
| execution | 8 | 8 | 328 ms | 0 ms | 320 ms |
| recovered | 8 | 0 | 28 ms | 0 ms | 20 ms |
诊断脚本用“请求数至少八条且不良比例超过四分之一”选出排队窗口。这个条件只服务于小样本实验;八条请求不适合拿来宣布生产告警策略可靠。生产里还要结合流量、时间窗口与用户影响,选择何时叫醒值班人。此处的问题是告警出现以后怎样走到可解释的请求。
查询的第一步保留范围,第二步才使用 trace ID
窗口事件包含 environment=lab、release=lab-v1、服务名和路由模板。脚本先限定这些字段,再用左闭右开的完成时间范围查应用结束日志,最后限定不良请求。这样查出的记录与窗口口径一致。本例选择 queue-r08 展示最久等待的请求,便于讲清时间分配,不能据此推断整个服务的典型情况。
具体时间范围是 2026-09-08T02:01:00.000Z 至下一秒,不含右端点。两个相邻窗口这样定义可避免重复计数。真实系统若按请求开始时间统计,却按完成时间查日志,长请求可能跨出窗口,造成“有错误数、找不到样本”。查询入口可以额外扩大检索范围,但在计算比例时保留原口径。
版本过滤有助于区分发布变化,也可能隐藏共用依赖造成的跨版本故障。先沿告警中的版本找到样本,再在相同时间、路由和流量条件下比较其他版本。本例四批都用同一版本,演示的是输入变化;脚本里的版本条件是检索契约,不是已经做过发布归因的证据。
request_id 在这里是生成器分配的可读名字,便于指定样本;跨边界的因果关联使用 trace_id 和父 span。单靠时间接近,把两个服务恰好同时出现的日志拼在一起,会把并发请求串错。若真实请求标识包含业务信息,可在入口生成不带业务语义的关联 ID,并为检索规定访问与保留范围。
下面摘录本次输出中的请求字段。前面的查询命令会打印窗口、结束日志、span列表及依赖日志,读者可直接生成完整记录;这里保留的是实际运行所得字段。
{
"request_id": "queue-r08",
"trace_id": "0000000000000000000000000000006c",
"span_id": "000000000000004c",
"duration_ms": 395,
"pool_wait_ms": 367,
"dependency_execution_ms": 20,
"slo_good": false,
"sampled": true
}
从这条结束事件里,我们已经能怀疑连接等待。依赖执行字段来自本地模型,所以它与下游记录天然一致;真实应用取得的客户端耗时包含传输与协议处理,和服务端执行时间通常不同。把字段改名为“数据库耗时”并不会消除这段差异。接下来沿 trace 看上下游各自覆盖了哪段时间。
日志里只放关联标识、有限分类和阶段数值,排查这条路径用不到订单正文、认证头或完整查询参数。若还缺查询形状,可以单独记录经归一化的操作名,并在采集前处理敏感字段。把原始请求全部写入日志再承诺后续脱敏,会让敏感内容先进入多个存储副本,也增加本次诊断无须承担的检索成本。
把五条 span 放在同一张时间账里
脚本给应用根 span、连接等待、依赖客户端、依赖服务端和查询执行各分配一个 span ID。应用在调用载体中写入客户端 span 的上下文,下游解析后沿用 trace ID,并把自己的服务端 span 挂到客户端之下。ID 相同只说明属于同一 trace,父 ID 才表达这份模型里的调用关系。
这与 OpenTelemetry 上下文传播文档描述的注入与提取方向一致。文档中的 W3C traceparent 包含版本、trace ID、父 ID 和标志位。本程序只接受自己的固定格式,用来演示边界;它没有实现完整协议验证、信任边界策略或 SDK 上下文管理,也不适合拿去代替生产 propagator。
样本中的载体为下列字符串。末尾标志表示生成器决定保留这条模拟追踪,依赖日志也保存收到的值。这里序列化再解析,验证的是字段在应用与依赖之间如何对应,没有证明任意 HTTP 客户端会携带该头。
00-0000000000000000000000000000006c-000000000000004e-01
下表把完整输出中的起止时间减去请求起点。实际文件保存的是距模拟纪元的毫秒数。根 span 从第六万零七十毫秒开始,结束在第六万零四百六十五毫秒。
应用侧的三条 span 属于 order-app。004c 对应根请求 request,没有父 span;004d 对应 pool.wait,父为 004c;004e 对应 dependency.client,父也为 004c。
依赖侧属于 order-dependency。004f 对应 dependency.server,父为应用侧的 004e;0050 对应 query.execute,父为 004f。下表用这些 ID 的后缀列出时间,单位均为毫秒。
| span 后缀 | 相对开始 | 相对结束 | 耗时 |
|---|---|---|---|
| 004c | 0 | 395 | 395 |
| 004d | 3 | 370 | 367 |
| 004e | 370 | 390 | 20 |
| 004f | 370 | 390 | 20 |
| 0050 | 370 | 390 | 20 |
根请求的时间可分成前三毫秒处理、三百六十七毫秒取连接等待、二十毫秒依赖调用和后五毫秒处理,合计三百九十五。客户端、服务端与执行 span 覆盖同一段区间,三者相加会重复计费。阅读瀑布时先看嵌套和并行关系,再计算未被子阶段解释的余量;父节点的总耗时不等于所有后代耗时之和。
实验为前后处理保留八毫秒余量,断言检查它与日志字段相符。真实系统里的余量还可能包含事件循环等待、序列化或遗漏的观测区间。若出现负余量,先查阶段重叠、单位与时钟来源,别把负数当成优化收益。跨机器的墙上时钟也可能有偏移,阶段自身耗时宜用本进程的单调计时依据,再对照跨服务时间线。
依赖日志的执行时间也是二十毫秒,且收到的父 ID 指向应用客户端 span。至此,本条慢请求主要等在连接获取阶段的解释有了关联证据。接下来查连接持有者、归还路径、后台任务占用和池容量变化更有针对性;直接给 SQL 加索引,现有材料还没给出依据。
换一批输入,检验“数据库慢”的反例
第三批请求的总耗时为三百二十八毫秒,与排队批次的慢请求处于相近量级。区别是连接等待为零,依赖执行占三百二十毫秒。两个窗口都是八次里八次超过目标,只看不良比例和总延迟,诊断方向仍分不开。这也是为什么指标负责定位范围,具体样本负责解释一条路径。
如果只给查询执行建立 span,第二批追踪会显示二十毫秒的正常查询,留下三百多毫秒空白。工程师可能转而怀疑埋点或用户网络。补上连接获取边界后,读者可以看到等待发生在下游执行开始之前。这里选择为资源等待建一条 span,因为它能够改变下一步排查对象;为每个格式转换函数都建 span 未必有同样价值。
反过来,连接池的等待长,也不能证明池设置过小。泄漏、长事务、后台任务抢占或依赖变慢,都能让空闲连接减少。实验把初始占用设成三百毫秒,排队现象因此确定发生;我们没有输出占用者内部行为。调整池容量能减少这个模型里的等待,但把更多查询送给真实数据库也可能增加竞争,容量选择还缺数据库承载证据。
第四批的二十八毫秒说明释放背景占用并给出两个名额后,这份模型可以及时完成请求。它同时改了背景占用和容量两个参数,因此无法单独归因于其中一个。若要评价扩池效果,先保持其他输入相同,只改名额数;若要查泄漏,追踪借出与归还才是合适实验。当前结果支持诊断方法,不支持任何容量推荐值。
指标保留分布,但别把模拟桶当成监控接入
生成器在每次请求完成后更新计数,按秒写入累计桶:不大于零点零五、零点二、零点四和一秒。它另存总数和耗时和;这些都是单个模型窗口内的统计,既没有持续抓取,也没有跨窗口的累计计数器。本例桶不含正无穷标签,根本没有输出 Prometheus exposition 格式。
日志的时间字段以毫秒结尾,桶的单位则写成秒,比较前先除以一千。排队批次在二百毫秒桶内为零,四百毫秒桶内为八,因此能确认八条都超过门槛。若只用零点一和一秒两个边界,我们只能知道请求落在宽区间里,无法从桶计数精确判断二百毫秒目标。
对于真正接入的 classic histogram,Prometheus 直方图说明给出的聚合顺序是先对桶计数取速率,再聚合,最后求分位数。以下只是接入后的查询模板,指标名和标签需与实际导出约定相符,本实验没有执行它。
histogram_quantile(
0.95,
sum by (service, le) (
rate(http_request_duration_seconds_bucket{
environment="lab", route="/orders/:id"
}[5m])
)
)
脚本另外构造了一个分位数反例:一个实例有一百个十毫秒请求,另一个有十个一千毫秒请求。平均各自的百分之九十五分位数得五百零五毫秒;合并全部请求、采用最近秩定义,结果是一千毫秒。两者都能计算出数字,前者却没有整体分位数的含义。这里按最近秩定义进行离线计算。
本例也没有把 trace ID 加入指标标签。窗口指标只保留有限维度,找到窗口后再去日志查单个请求。按订单、用户或完整 URL 建普通时序,会让维度随业务增长;确有从指标跳到 trace 的需求,可以研究后端支持的 exemplar 路径,但这份最小实验不依赖它,也不假装已经配置成功。
读取原始文件时,还会发现日志先写入,span 在整批结束后才排出,事件并未按时间排序。诊断脚本按字段关联,因此不依赖相邻行关系。真实后端也可能晚收到数据,查询时要区分事件发生时间与入库时间;若第一次查询无结果,可以在明确的接收延迟范围内复查,同时观察导出状态。把“尚未到达”和“已经丢失”混成一种空值,会掩盖采集链路的问题。
有日志,无追踪:继续查同一条请求
对 queue-r06 执行相同查询,会得到三百七十五毫秒的结束日志、三百四十七毫秒连接等待,以及零条 span。生成器在请求开始前决定不保留它的追踪,同时继续传播上下文、记录结束事件和窗口计数。所以日志里的 trace ID 存在,追踪记录却缺席;两者并不矛盾。
这是预先指定的采样演示。OpenTelemetry 的采样说明区分了提前作决定的头部采样与根据已形成的 trace 信息作决定的尾部采样。前者无法仅凭早期信息保证保留后来出错的请求。尾部采样也涉及数据缓存和到达完整性,替换采样方式并不消除所有缺口。
这次查询没有停在空白页面。脚本用相同 trace ID 与请求名查依赖结束日志,取得二十毫秒执行值;应用阶段字段给出三百四十七毫秒等待,两侧还能沿传播载体对上关系。我们仍有理由优先检查连接池,但没有完整追踪可供查看中间细节。运行前面的第二条诊断命令即可得到这个分支,输出中的span数量为零,依赖结束日志仍在。
如果真实日志没有阶段字段,下一步会更窄:先找同时间、实例和版本的连接占用与等待量,查看是否有相关依赖结束记录,再决定在受控复现中增加连接获取计时。相邻 trace 可以提示共同现象,却无法证明缺失的这一条经过相同路径。跨请求推断要在诊断记录里写成假设。
如果日志连 trace ID 也没有,入口生成的请求 ID 只有在下游也收到并记录时才有桥梁。否则只剩时间、服务和实例范围,最多定位一批候选。此时检查上下文在哪个异步或进程边界断开,比在后端反复搜同一串字符更有效;已有日志里没有保存的调用关系,检索器补不回来。
后端收不到数据时,丢弃也留下计数
无追踪还可能来自导出故障。示例中的有界导出器限制条数、序列化字节总量与单条大小,队列满时丢弃新记录;一次发送失败保留旧队列,恢复后取出。测试向容量为三的队列投入一百条记录,模拟一次不可用,再恢复,实际得到保留三条、丢弃九十七条、恢复取出三条。测试也确认超大记录遭拒绝。
丢新记录的取舍是保留先前上下文,却可能失去最近故障。丢旧记录能保留最新事件,但会破坏较早 trace;按错误优先还可能改变观察样本分布。这份代码选择便于验证的策略,没有实现持久化、异步重试或 trace 完整性保护。字节上限约束的是序列化负载,运行时对象和数组仍有额外内存开销。
示例在入队前执行序列化,所以也没有证明它在高负载下对业务延迟无影响。实际接入可先限制字段长度,并把导出失败、队列长度和丢弃数通过独立可读的健康入口暴露。若健康信号只随同一个失效导出器发送,值班者仍会看见空白。实验的结果写入本地文件,供断言读取,没有连接观测后端。
这次诊断停在一个具体位置:queue-r08 的三百九十五毫秒中,三百六十七毫秒发生在取得连接之前;依赖执行只占二十毫秒。queue-r06 缺少 span,但现存阶段日志支持相同的排查方向。我们还不知道初始名额由谁持有、为何没有归还,下一份材料应是连接持有与释放记录。再加一张总延迟图,回答不了这两个问题。











