动态追踪把“某个函数可能慢”转成可观察事件:调用了多少次、传入什么、返回什么、入口到返回隔了多久。首先要确定探测的层次及对象身份,再决定脚本。函数名相同、路径相同或 TID 相同,都不一定代表同一个业务请求。
本文命令按 bpftrace 0.24 文档说明,/absolute/path/prog、函数名和 PID 是需要替换的模板。目标二进制、内核能力与权限必须满足要求;示例不假定所有系统都有相同 libc 路径。
各层工具分别负责什么
名称 作用 与用户态的关系
ftrace function tracer 追踪可插桩的内核函数 不是直接遍历任意用户函数调用
tracefs 事件系统 暴露内核事件、探测事件及缓冲接口 可记录 uprobe 产生的事件
uprobe / uretprobe 在用户代码位置及返回路径触发 依目标映射、指令位置与运行时支持
USDT 程序预先定义语义探测点及参数元数据 更容易表达请求、事务等稳定语义
bpftrace 将探测与聚合脚本编译为 BPF 等执行逻辑 可组合用户函数和内核事件
tracefs 常挂载在 /sys/kernel/tracing,兼容路径可能位于 debugfs 下。不要把 ftrace 的内核函数追踪器、整个 tracefs 基础设施和 BPF 当作同一个机制。ftrace 文档
探测地址:符号名、虚拟地址与文件偏移不同
bpftrace 或 perf probe 可以帮助解析 ELF 符号。但内核原始 uprobe_events 接口的定义使用目标文件路径和文件偏移 ,不能直接写 /bin/bash:readline 当作原始事件格式。
给定 ELF 中某个符号虚拟地址 v,要找到它所属的文件支持映射,典型转换是 file_offset = p_offset + (v - p_vaddr),并验证地址在对应段的文件内容范围内。PIE 的运行时加载基址与这个文件偏移不是一回事;直接把运行时地址填进去会探错位置。
原始接口的概念形式如下,属于格式说明,OFFSET 需换成已验证的数值:
p:group/event /absolute/path/prog:OFFSET
r:group/event_return /absolute/path/prog:OFFSET
这是接口语法,不是结构图。实际操作通常优先使用符号解析工具,避免手算出错。原始事件管理还涉及 enable、缓冲读取与按名删除。Uprobe tracer 文档
先列出能力与目标
bpftrace -- version
bpftrace -- info
bpftrace - l ' uprobe:/absolute/path/prog:*work*'
bpftrace - lv ' uprobe:/absolute/path/prog:work'
bpftrace - lv ' tracepoint:syscalls:sys_enter_openat'
readelf - Ws /absolute/path/prog
函数若被内联、删除或只剩优化后的克隆,未必有独立入口;C++ 名字修饰与多个同名符号也需要消歧。DWARF 可帮助获取类型化参数,但必须与运行的构建匹配。容器内外路径、已删除的旧映射和文件替换也会影响目标定位。
bpftrace 的 -p PID 对支持的用户探针附加到特定进程,对其他相关探针按 PID 过滤,并在目标结束时退出;具体行为见对应版本说明。--dry-run 会尝试加载、附加后退出,不是纯离线语法检查 。bpftrace CLI
先准备一个能核对符号和结果的小目标
保存为 trace-target.c。work 是非递归、同步返回的 C 函数,入口 size 表示参与循环的项数,返回值是累计结果;它并没有读写 size 字节,所以若使用后面的脚本模型,应把指标名字改成输入项数。
#include < stdio.h>
__attribute__ (( noinline ))
long work ( unsigned long size ) {
volatile unsigned long total = 0 ;
for ( unsigned long i = 0 ; i < size; + + i) total += i & 7u ;
return ( long ) total;
}
int main ( void ) {
long a = work ( 1000 ) ;
long b = work ( 2000 ) ;
printf ( " %ld %ld \n " , a, b) ;
return a == 3500 && b == 7000 ? 0 : 1 ;
}
cc - g - O1 trace-target.c - o trace-target
./trace-target
readelf - Ws ./trace-target
objdump - d ./trace-target
本例传入范围内累加与 long 转换都有效。先确认存在 work 的独立入口,程序输出 3500 7000,再建立探测;noinline 是帮助保留观察点的编译器属性,不保证任意生产构建都采用相同地址和代码形状。
短进程可能在手工附加前结束。若用 bpftrace -c 启动目标,应注意 0.24 不默认过滤所有探针到该子进程;对用户上下文探针可用 pid == cpid 明确筛选。工具启动的子进程还会继承工具权限,选择运行方式时要与原负载执行条件一致。bpftrace -c
参数:入口读参数,返回读结果
对于一个按常规本机 C ABI 编译的 long work(unsigned long size),入口 uprobe 可读 arg0,返回 uretprobe 可读 retval。返回时参数寄存器可能早已被覆盖,不能在 uretprobe 中把 arg0 当成原始 size。
argN 的位置取决于 ABI 和类型分类。浮点、结构体、栈上传参、语言运行时的专用 ABI,都不能靠把 %si、%rdi、x0 随意替换来解决。需要保留入口参数时,应在入口记录,再在匹配返回处取出。bpftrace 探针说明
读取字符串还需区分“指针地址”与“当时的内容”。str() 在探测时尝试读取用户内存,字符串长度受配置约束,错误地址或内容变化会影响结果。不要把返回指针自动当作入口字符串。
一个有明确前提的耗时脚本
下面保存为 work.bt。前提是同一线程不会嵌套、递归或由信号处理器重入 work,且调用正常返回;这些条件不满足时,应改用后面的关联设计。
uprobe:/absolute/path/prog:work
{
@start[tid] = nsecs(monotonic);
@size[tid] = arg0;
}
uretprobe:/absolute/path/prog:work
/@start[tid]/
{
@lat_us = hist((nsecs(monotonic) - @start[tid]) / 1000);
if ((int64)retval >= 0) {
@successful_input_bytes = sum(@size[tid]);
}
delete(@start, tid);
delete(@size, tid);
}
END
{
clear(@start);
clear(@size);
}
bpftrace - p 12345 work.bt
这里额外约定非负返回值代表成功,累计的是成功调用的入口 size 之和 ,不是存活内存、实际写入字节或返回值。若 work 的接口定义不同,应修改指标语义。
nsecs(monotonic) 明确使用不含系统挂起时间的单调时钟;差值除以 1000 后是微秒。因此 lat_us > 10000 表示超过 10 毫秒,不能注释成 10 微秒。hist 在内核侧聚合,避免每次调用都输出文本;map 删除语法按 0.24 标准库。bpftrace 标准库
入口与返回配对:观测耗时包含执行和等待
入口探测
返回探测
运行 20 μs
等待 / 被抢占 100 μs
运行 30 μs
返回时间 − 入口时间 = 150 μs
它不是 CPU 执行时间;还需调度、锁或 I/O 事件才能解释等待来源。
函数入口到返回的时间包含 CPU 执行、被抢占、阻塞以及探测开销。调用耗时很长不能单独证明发生了 futex wait;即使期间看见 futex 系统调用,也要检查操作类型、返回值和时间区间,才能判断实际等待。
递归、线程退出与异步请求怎么关联
只用 @start[tid] 保存一个时间戳,内层调用会覆盖外层。递归场景可按 TID 维护深度,并用 (tid, depth) 作为开始时间与参数的键;返回时取当前层再递减。需要同时考虑附加时已有调用、漏掉返回、longjmp、异常展开、线程退出和 map 容量,否则深度仍可能失配。
协程或异步请求会跨线程、跨多次函数调用。此时 TID 适合表示执行线程,不能充当请求 ID。最好通过 USDT 或应用已有的关联标识记录 request_id,把开始、挂起、恢复和完成事件连接起来。
返回探针也不是对所有语言运行时都透明:自定义栈、特殊返回路径等需要核对支持情况。对复杂运行时,语义明确的 USDT 往往比依赖某个内部函数的机器 ABI 更稳定。
用事件序列看清递归覆盖了哪个时间戳
假设同一线程的外层 work 在 100 μs 进入,递归内层在 130 μs 进入,内层在 170 μs 返回,外层在 200 μs 返回。只保存一个 @start[tid] 时,130 会覆盖 100;第一次返回得到 40 μs 并删除条目,外层的 100 μs 耗时就丢了。
下面的离线模型使用每线程栈,只用于验证配对逻辑,不会加载 BPF 或附加探针。它另外记录“没有入口的返回”和观测结束时未完成的调用。
from collections import defaultdict
stacks = defaultdict ( list )
durations = [ ]
orphan_returns = 0
events = [
( 1 , " return" , 90 ) ,
( 1 , " enter" , 100 ) , ( 1 , " enter" , 130 ) ,
( 1 , " return" , 170 ) , ( 1 , " return" , 200 ) ,
( 2 , " enter" , 210 ) ,
]
for tid , kind , timestamp in events :
if kind == " enter" :
stacks [ tid ] . append ( timestamp )
elif stacks [ tid ] :
start = stacks [ tid ] . pop ( )
assert timestamp >= start
durations . append ( ( tid , timestamp - start ) )
else :
orphan_returns += 1
assert durations == [ ( 1 , 40 ) , ( 1 , 100 ) ]
assert orphan_returns == 1
assert sum ( map ( len , stacks . values ( ) ) ) == 1
这个模型假设同一线程事件顺序完整且嵌套正常。实际丢失中间返回、longjmp 或异常路径可能让栈深度永久错位;因此加上 depth 并不等于彻底解决关联。应记录失配数量、限制每线程深度及总键数,并在能确认的线程退出或会话边界清理。
特别是观测结束时仍在执行的慢调用,没有返回就不会进入完成耗时直方图。若把它们直接清空而不计数,报告可能偏向较快的已完成调用。可以另报未完成数量和截至停止时的已等待时间下界,不能把它们当成耗时为零。
内层调用覆盖了谁的开始时间?
时间轴把包含关系画出来:外层100 μs已经包含内层时间。若入口只写同一个 start[TID],内层会覆盖100,内层返回后删除条目,外层就失去配对依据。栈能保留每层起点,但不能凭空恢复漏掉的事件;未完成与失配数量仍应随结果报告。
正在呈现知识画面 重新加载
内层调用覆盖了谁的开始时间? 每线程单个时间戳会被递归覆盖。栈式关联可保留正常嵌套的每层,但异常退出与漏事件仍需单独处理。
{"id":"trace-nested-time","title":"内层调用覆盖了谁的开始时间?","summary":"每线程单个时间戳会被递归覆盖。栈式关联可保留正常嵌套的每层,但异常退出与漏事件仍需单独处理。","height":1000,"html":"<h2 data-i18n=\"heading\"></h2><p class=\"intro\" data-i18n=\"intro\"></p><div class=\"control\"><label for=\"start\" data-i18n=\"start\"></label><output for=\"start\" id=\"start-value\"></output><input id=\"start\" type=\"range\" min=\"101\" max=\"139\" value=\"130\" step=\"1\"></div><div class=\"control\"><label for=\"duration\" data-i18n=\"duration\"></label><output for=\"duration\" id=\"duration-value\"></output><input id=\"duration\" type=\"range\" min=\"1\" max=\"60\" value=\"40\" step=\"1\"></div><div class=\"intervals\" id=\"timeline\"></div><div class=\"metrics\"><div><span data-i18n=\"naive\"></span><strong id=\"naive\"></strong></div><div><span data-i18n=\"stack\"></span><strong id=\"stack\"></strong></div><div><span data-i18n=\"innerTime\"></span><strong id=\"innerTime\"></strong></div><div><span data-i18n=\"self\"></span><strong id=\"self\"></strong></div></div><p class=\"formula\" id=\"equation\"></p><details class=\"scope\"><summary data-i18n=\"scopeLabel\"></summary><p data-i18n=\"scope\"></p></details>","css":".intro{margin:8px 0 18px;color:var(--muted);font-size:14px}.caption,.hint{font-size:12px;color:var(--muted);margin-top:12px}.control{display:grid;grid-template-columns:minmax(0,1fr) auto;gap:6px 12px;align-items:center;margin:14px 0;font-size:13px}.control label{font-size:13px}.control output{color:var(--accent);min-width:5em;text-align:right;font-variant-numeric:tabular-nums}.control input{grid-column:1/-1;width:100%;margin:0}.presets{display:flex;gap:4px;align-items:stretch}.presets button{flex:1 1 0;min-width:0;overflow-wrap:anywhere;font-size:13px}.actions{display:flex;gap:8px;flex-wrap:wrap;margin:14px 0}.actions button{flex:1;min-width:0;font-size:13px;min-height:42px}.copy{display:grid;font-size:14px;margin:16px 0}.copy>*{grid-area:1/1;margin:0}.reserve{visibility:hidden}.scope{margin-top:14px;color:var(--muted);font-size:12px}.scope summary{padding:8px 0;cursor:pointer}.scope p{margin-top:10px}.two{display:grid;grid-template-columns:repeat(2,minmax(0,1fr));gap:12px;margin:16px 0}.card{border:1px solid var(--rule);border-radius:9px;padding:14px;min-width:0}.card header{font-size:14px;font-weight:600;margin-bottom:10px}.card button{font-size:12px;width:100%;min-width:0}.card small{display:block;font-size:12px;color:var(--muted)}.card code{font-size:12px;overflow-wrap:anywhere}.metrics{display:grid;grid-template-columns:repeat(2,minmax(0,1fr));gap:12px;margin:16px 0}.metrics>div{border-left:2px solid var(--accent);padding-left:10px;min-width:0}.metrics span{display:block;min-height:3.2em;color:var(--muted);font-size:12px}.metrics strong{font-size:23px;display:block;font-weight:500;overflow-wrap:anywhere;font-variant-numeric:tabular-nums}.formula{border-top:1px solid var(--rule);padding-top:12px;margin-top:14px;font-size:13px;font-variant-numeric:tabular-nums;overflow-wrap:anywhere}.value{font:500 20px var(--viz-font-ui)}.legend{display:flex;flex-wrap:wrap;gap:6px 14px;font-size:12px;color:var(--muted);margin:12px 0}.legend span:before{content:'';display:inline-block;width:8px;height:8px;border-radius:2px;background:var(--accent);margin-right:6px}.legend .second:before{background:var(--second)}.check{display:flex;align-items:center;gap:8px;font-size:13px;margin:12px 0}.check input{width:16px;height:16px;flex-shrink:0;accent-color:var(--accent)}select,input[type=text],input[type=number]{background:var(--paper);color:var(--ink);font:inherit;font-size:13px;padding:10px;border:1px solid var(--rule);border-radius:7px;max-width:100%;min-width:0}select{width:100%;min-height:42px}.band{height:20px;display:flex;background:var(--surface);border-radius:4px;overflow:hidden}.band i{height:100%;display:block;background:var(--accent);transition:width .25s}.band i.second{background:var(--second)}button:disabled{cursor:default}.status{font-size:13px;min-height:4.8em}.mono{font-family:var(--viz-font-mono);font-variant-numeric:tabular-nums}.muted{color:var(--muted)}\n@media(max-width:480px){.two{gap:8px}.card{padding:12px 9px}.actions button,.presets button{font-size:12px}.metrics strong{font-size:20px}.metrics{gap:8px}}\n@media(prefers-reduced-motion:reduce){*,*::before,*::after{transition:none!important;animation:none!important}}\n.track-row{margin:16px 0}.track-row>span{display:block;font-size:12px;color:var(--muted);margin-bottom:7px}.track{display:flex;gap:5px;min-width:0}.cell{flex:1;min-width:0;min-height:48px;border:1px solid var(--rule);border-radius:5px;background:var(--surface);display:flex;align-items:center;justify-content:center;text-align:center;padding:5px 3px;font-size:12px;overflow-wrap:anywhere;font-variant-numeric:tabular-nums}.cell.on{background:var(--accent-soft);border-color:var(--accent)}.cell.gold{background:var(--second-soft);border-color:var(--second)}.cell.empty{border-style:dashed;color:var(--muted)}.cell.error{border-color:var(--second);text-decoration:line-through}.choices{display:grid;grid-template-columns:repeat(4,minmax(0,1fr));gap:6px;margin:14px 0}.choices button{min-width:0;padding:10px 4px;font-size:12px;overflow-wrap:anywhere}.choices button[aria-current=true]{border-color:var(--accent);background:var(--accent-soft)}.relation{display:grid;grid-template-columns:minmax(0,1fr) 28px minmax(0,1fr);align-items:center;gap:6px;margin:12px 0}.relation .cell{min-height:72px}.relation>i{text-align:center;font-style:normal;color:var(--accent)}.readout{font-size:13px;white-space:pre-line;min-height:6.4em;overflow-wrap:anywhere}.plot{position:relative;border-left:1px solid var(--rule);border-bottom:1px solid var(--rule);padding:8px 0;margin:18px 0}.plot-row{height:28px;position:relative;margin:4px 0;background:var(--surface)}.plot-row i{position:absolute;inset-block:5px;background:var(--accent);min-width:2px;transition:width .2s,left .2s}.plot-row b{position:relative;padding:4px 6px;font:11px/28px var(--viz-font-ui);background:var(--paper);border-radius:3px}.axis{display:flex;justify-content:space-between;font-size:11px;color:var(--muted)}\n\n/* Action labels must remain readable across locales and narrow embeds. */\n.actions{display:grid;grid-template-columns:repeat(2,minmax(0,1fr));gap:8px}\n.actions button{overflow-wrap:anywhere;white-space:normal;min-height:58px;padding:8px}\nbutton{overflow-wrap:anywhere}\n@media(min-width:640px){.actions{grid-template-columns:repeat(3,minmax(0,1fr))}}\n\n.metrics span{overflow-wrap:anywhere}\n.panel{border:1px solid var(--rule);border-radius:9px;padding:12px;margin:14px 0;min-width:0}.panel h3{font-size:13px;margin:0 0 10px;color:var(--muted)}.source{font:13px/1.8 var(--viz-font-mono);white-space:pre-wrap;overflow-wrap:anywhere;margin:12px 0}.source mark{background:var(--accent-soft);color:var(--ink);border-bottom:2px solid var(--accent)}.source .fault{background:var(--second-soft);border-color:var(--second)}.diagram{display:block;width:100%;height:auto;max-height:320px;margin:14px 0;overflow:visible}.diagram text{fill:var(--ink);font:12px var(--viz-font-ui)}.diagram .edge{stroke:var(--muted);stroke-width:1.5;fill:none}.diagram .edge.on{stroke:var(--accent);stroke-width:3}.diagram .node{fill:var(--surface);stroke:var(--rule);stroke-width:1.5}.diagram .node.on{fill:var(--accent-soft);stroke:var(--accent)}.diagram .node.gold{fill:var(--second-soft);stroke:var(--second)}.log{font:12px/1.8 var(--viz-font-mono);white-space:pre-line;overflow-wrap:anywhere;min-height:7.2em}.table{display:grid;gap:5px;margin:14px 0}.table .tr{display:grid;grid-template-columns:repeat(3,minmax(0,1fr));gap:5px}.table .tr>*{padding:8px 5px;background:var(--surface);border-radius:4px;min-width:0;overflow-wrap:anywhere;font-size:12px}.table .tr .on{background:var(--accent-soft)}.table .tr .gold{background:var(--second-soft)}.choices button{min-height:44px}.metrics strong{min-height:1.6em}.code-line{display:block}.code-line.on{background:var(--accent-soft);border-left:2px solid var(--accent);padding-left:6px}.status-badge{font-size:12px;color:var(--accent)}.tile-grid{display:grid;grid-template-columns:repeat(4,minmax(0,1fr));gap:6px}.tile-grid .cell{min-height:40px}.actions button{min-height:48px}.form-field{display:grid;gap:8px;margin:14px 0;font-size:13px}.form-field input{width:100%;font-family:var(--viz-font-ui)}.metrics.three{grid-template-columns:repeat(3,minmax(0,1fr))}.formula{min-height:3.2em}.presets{flex-wrap:wrap}.presets button{flex-basis:25%;min-height:44px}\n\n.budget{display:flex;height:28px;margin:16px 0;background:var(--surface);border-radius:5px;overflow:hidden}.budget i{display:block;background:var(--accent);transition:width .2s}.budget i.gold{background:var(--second)}.intervals{margin:16px 0}.interval{position:relative;height:36px;background:var(--surface);margin:6px 0;border-radius:4px;overflow:hidden}.interval i{position:absolute;height:100%;background:var(--accent-soft);border-left:2px solid var(--accent)}.interval i.gold{background:var(--second-soft);border-color:var(--second)}.interval span{position:relative;z-index:1;font:12px/36px var(--viz-font-ui);padding-left:7px}.table .tr>*{min-height:4.8em}.formula{white-space:pre-line;min-height:7.2em}.actions:has(>button:only-child){grid-template-columns:1fr}.metrics strong{min-height:3.2em}.rangegrid{display:grid;grid-template-columns:repeat(12,minmax(0,1fr));gap:3px;margin:14px 0}.rangegrid .cell{min-height:30px;padding:3px 1px;font-size:10px}.message{min-height:7.2em;white-space:pre-line;font:13px/1.8 var(--viz-font-ui);overflow-wrap:anywhere}\n/* Allow CJK hanging punctuation without overflowing a metric's border box. */\n.metrics>div{padding-right:4px}.metrics span{line-break:anywhere}\n\n.metrics strong{font-size:17px}","js":"const $=s=>document.querySelector(s);const set=(id,v)=>$('#'+id).textContent=v;const t=k=>viz.t(k);function cells(id,values){$('#'+id).replaceChildren(...values.map(v=>{const e=document.createElement('div');e.className='cell '+(v.cls||'');e.textContent=v.text;e.title=v.title||v.text;return e;}));}function pressed(mode){document.querySelectorAll('[data-mode]').forEach(e=>e.setAttribute('aria-pressed',String(e.dataset.mode===mode)));}const esc=s=>String(s).replace(/[&<>\"']/g,c=>({'&':'&','<':'<','>':'>','\"':'"',\"'\":'''}[c]));const fmt=s=>'{'+[...s].sort().join(', ')+'}';function graph(id,nodes,edges){const el=$('#'+id);el.setAttribute('viewBox','0 0 360 200');el.innerHTML='<defs><marker id=\"arrow-'+id+'\" viewBox=\"0 0 10 10\" refX=\"8\" refY=\"5\" markerWidth=\"5\" markerHeight=\"5\" orient=\"auto-start-reverse\"><path d=\"M 0 0 L 10 5 L 0 10 z\" fill=\"var(--muted)\"/></marker></defs>'+edges.map(e=>{const a=nodes[e[0]],b=nodes[e[1]],dx=b.x-a.x,dy=b.y-a.y,d=Math.hypot(dx,dy)||1;if(edges.some(r=>r[0]===e[1]&&r[1]===e[0])){const nx=-dy/d,ny=dx/d;return '<path class=\"edge '+(e[2]?'on':'')+'\" d=\"M '+(a.x+dx/d*22+nx*12)+' '+(a.y+dy/d*22+ny*12)+' Q '+((a.x+b.x)/2+nx*38)+' '+((a.y+b.y)/2+ny*38)+' '+(b.x-dx/d*25+nx*12)+' '+(b.y-dy/d*25+ny*12)+'\" marker-end=\"url(#arrow-'+id+')\"/>';}return '<line class=\"edge '+(e[2]?'on':'')+'\" x1=\"'+(a.x+dx/d*25)+'\" y1=\"'+(a.y+dy/d*25)+'\" x2=\"'+(b.x-dx/d*28)+'\" y2=\"'+(b.y-dy/d*28)+'\" marker-end=\"url(#arrow-'+id+')\"/>';}).join('')+nodes.map(n=>'<g><circle class=\"node '+(n.cls||'')+'\" cx=\"'+n.x+'\" cy=\"'+n.y+'\" r=\"25\"/><text x=\"'+n.x+'\" y=\"'+(n.y+4)+'\" text-anchor=\"middle\">'+esc(n.name)+'</text>'+(n.sub?'<text x=\"'+n.x+'\" y=\"'+(n.y+43)+'\" text-anchor=\"middle\">'+esc(n.sub)+'</text>':'')+'</g>').join('');}function table(id,rows){$('#'+id).classList.add('table');$('#'+id).replaceChildren(...rows.map(r=>{const row=document.createElement('div');row.className='tr';r.forEach(x=>{const c=document.createElement('div');if(typeof x==='object'){c.textContent=x.text;c.className=x.cls||'';}else c.textContent=x;row.append(c)});return row;}));}function band(id,parts,total){$('#'+id).replaceChildren(...parts.map((p,i)=>{const e=document.createElement('i');e.style.width=(100*p.value/total)+'%';e.className=i%2?'gold':'on';e.title=p.name+': '+p.value;return e}));}function intervals(id,items,total){$('#'+id).replaceChildren(...items.map(p=>{const row=document.createElement('div');row.className='interval';const bar=document.createElement('i');bar.style.left=(100*p.start/total)+'%';bar.style.width=(100*(p.end-p.start)/total)+'%';bar.className=p.cls||'';const label=document.createElement('span');label.textContent=p.label;row.append(bar,label);return row;}));}function draw(){const s=+$('#start').value,d=+$('#duration').value;set('start-value',s);set('duration-value',d);intervals('timeline',[{start:0,end:100,label:t('outer')+' · 100–200 μs'},{start:s-100,end:s+d-100,label:t('inner')+' · '+s+'–'+(s+d)+' μs',cls:'gold'}],100);set('naive',t('lost'));set('stack','100 μs');set('innerTime',d+' μs');set('self',(100-d)+' μs');set('equation','start[TID]: 100 → '+s+' → ∅\\nstack[TID]: [100] → [100, '+s+'] → [100] → []');}document.querySelectorAll('input').forEach(e=>e.oninput=draw);draw();","audio":false,"strings":{"duration":"内层时长(μs)","heading":"内层调用覆盖了谁的开始时间?","inner":"内层调用","innerTime":"内层时长","intro":"拖动内层调用起止,比较单时间戳与栈式关联。","lost":"已被内层返回删除","naive":"单时间戳的外层结果","outer":"外层调用","reset":"重置","scope":"外层100–200 μs,内层限制在其内,正常嵌套、事件完整、同一单调时钟;内层包含于外层,二者不能相加作墙钟总量。","scopeLabel":"模型范围与约定","self":"外层排除内层的时间","stack":"栈式关联的外层时长","start":"内层开始(μs)"}}
USDT:提前约定可观察的业务事件
应用可用 SDT 宏定义请求开始点,例如以下片段中的 request_id 与 size 由业务代码提供:
#include < sys/sdt.h>
DTRACE_PROBE2 ( myapp, request_start, request_id, size ) ;
这段放在函数体中,需安装相应头文件并完成构建。列出目标实际携带的探针后,再按其参数契约消费:
readelf - n /absolute/path/prog
bpftrace - l ' usdt:/absolute/path/prog:*'
bpftrace - p 12345 - e ' usdt:/absolute/path/prog:myapp:request_start {
@requests = count();
}'
USDT 通过编译产物中的探测元数据描述位置和参数,某些实现还使用 semaphore 协调激活。未激活时成本通常很低,但并非绝对零:代码布局、参数计算和构建方式仍可能有成本。不能统一写成所有架构都把某段 NOP 改成 x86 INT3。
线程标识描述在哪里执行,请求标识描述哪件事
TID 10:start
request = (42, generation 7)
TID 10:suspend
同一线程可转去处理请求 43
TID 20:finish
仍完成 request (42, 7)
配对键:请求 ID + 代次 / 会话
TID 单独记录,用于解释调度而不是拼接请求
ID 若被复用,迟到事件可能串到新请求;需要在事件契约中定义唯一性范围。
业务探针需要连同字段语义一起版本化
事件字段 必须约定什么 不明确时的误配
request_id 唯一性范围,是否跨进程 两个进程的 ID 42 混在一起
generation / session ID 复用和重启边界 上一代迟到完成关闭了新请求
timestamp 时钟来源、单位、是否跨主机可比 将本机单调时钟直接相减求跨机延迟
size 字节、元素、压缩前后、请求还是响应 指标名叫 bytes,实际统计循环项数
result 成功码、错误码、部分完成 非负值全部误判为完整成功
事件通常需要 start/finish 成对,也可能增加 suspend/resume 或显式 cancel。若请求跨机器,不能直接相减各自的 monotonic 数值;单机耗时与分布式追踪中的时钟和因果关系应分开处理。
指标聚合也要控制维度。把每个 request_id 都长期留作直方图键会造成高基数 map;通常用 ID 维护短期关联,完成后删除,再按操作名、结果类型等有限维度聚合。少量异常样本可以保留明细,但不应让所有正常请求都变成永久键。
从用户函数延伸到系统行为
bpftrace - p 12345 - e ' tracepoint:syscalls:sys_enter_openat {
@open_calls = count();
}'
该计数描述 openat 入口次数,不表示打开成功;成功、失败和耗时需配对出口。文件名也不能完全表达最终解析的文件身份,目录 fd、挂载名字空间、符号链接和路径修改都可能参与。
现成 BCC 工具适合先验证方向。例如 execsnoop 观察 exec 调用及其参数、结果,不是完整的“谁 fork 了谁”追踪;进程创建还需 fork、clone 或调度事件。工具可能运行时编译 BPF,并不因为是命令行程序就都是预编译内核程序。BCC execsnoop 源码
判断结果是否可信
明确目标 PID、构建身份、探测位置、参数类型、开始结束时间和计数分母。若没有事件,先确认实际路径确实执行,再检查符号解析、权限和支持能力;不要立即断言业务没有发生。
高频探针会改变被测程序。优先在探测端聚合,限制维度数量与观测时间,并检查丢失事件、map 满和读取失败等反馈。停止工具通常会释放它管理的附加;手工创建的 tracefs 事件应按本次名称清理,不能清空机器上所有 uprobe 配置。
采样适合找热点,事件追踪适合验证特定路径与时间关系。两者结合使用,见 perf 深度使用 。
关键词:ftrace, tracefs, uprobe, uretprobe, USDT, bpftrace, BCC, ABI, file offset, latency, correlation
给观测结果附上分母和缺口
计数 可解释什么 需要同时记录
入口总数 观测期间命中的调用次数 目标范围和探针覆盖
成功返回数 满足返回码约定的完成调用 失败返回与孤立返回数
完成耗时直方图 配对成功且完成的调用分布 尚未返回与配对失效数量
用户态输出事件数 消费端实际收到的事件 丢失、缓冲容量与输出压力
探针中已经完成的 map 聚合和用户态逐条输出有不同的数据通路;看到输出丢失不能不加区分地修改所有计数,但也不能据此假定整套观测毫无缺口。把采集覆盖、配对覆盖和输出覆盖分别描述,才能知道一个延迟分布到底代表哪些调用。