追踪与调试

请求很慢，可能慢在 CPU、运行队列、锁或设备。追踪应先确定测量对象和起止边界⁠，再收集足以验证假设的事件。

1. 先确定问题和测量对象

同一个“请求耗时”可能包含应用排队、系统调用、块层排队和设备处理。不同层的延迟不能直接相加，除非明确事件嵌套与并行关系。

2. ftrace 与 tracefs

现代 tracefs 常挂载于 /sys/kernel/tracing，历史路径 /sys/kernel/debug/tracing 仍可能存在。available_tracers 列出当前可用 tracer，available_filter_functions 列出可跟踪函数；配置不同会改变可见内容。

cat /sys/kernel/tracing/available_tracers
cat /sys/kernel/tracing/events/sched/sched_switch/format

这些只读命令先确认能力与字段，读取失败不应直接判断函数不存在。开启 function/function_graph 会改变追踪状态；实际采集宜使用独立 trace instance，先设置过滤范围与缓冲区，再开启采集，结束后停用并清理。

• function 记录所选函数进入；无过滤全量启用可能产生大量事件。
• function_graph 关联函数进入和返回，展示调用层次及持续时间。是否计入被调度出去的时间等受到 tracer 选项影响。
• trace 提供格式化缓冲区视图；trace_pipe 是消费式读取，多个读者会竞争事件，不能当作互不影响的广播日志。

CPU 缓冲区可能覆盖或丢失记录，跨 CPU 比较也需要理解 trace_clock。trace instance 可隔离多种采集配置，但共享动态探针定义等资源仍可能相互影响。接口和选项见 ftrace 文档。

动态 ftrace 不等于 kprobe event

动态 ftrace 通过可跟踪函数的插桩位置启停函数追踪；向 kprobe_events 或 dynamic_events 注册的是动态探针事件，属于另一种机制。读取 state+0x12(%di) 之类固定偏移表达式必须同时匹配架构、函数签名和结构布局，不能作为通用 TCP 状态读取示例。

优先检查是否有合适 tracepoint；确需动态函数探测时，再结合目标符号、BTF/DWARF 和实际源码解释参数。见 kprobe events。

3. perf：计数和采样回答不同问题

perf stat 汇总计数；perf record 按事件产生样本；perf report 汇总样本。记录一个 sleep 进程的 cycles，并不能代表整机十秒的 CPU 热点。

# 测量该命令及相应继承范围，不是整机。
perf stat -e cycles,instructions,cache-misses -- ./workload

# 记录实际工作负载的调用栈；DWARF 展开有额外开销。
perf record -e cycles -g --call-graph dwarf -- ./workload
perf report

# 若问题确实是整机热点，再明确使用系统范围采样。
perf record -a -e cycles -g -- sleep 10

./workload 代表待测程序，需替换为实际命令。权限、PMU、虚拟化和平台能力决定事件是否可用；cache-misses 等通用名字在不同 CPU 上不一定对应完全相同的硬件含义。

事件过多导致 multiplexing 时，应检查运行时间比例和缩放结果。调用栈质量还依赖 frame pointer、DWARF、符号及展开方法；缺少符号、丢样本和错误展开都可能改变热点图。样本百分比是当前事件与记录范围下的占比，不是任意函数的精确墙钟耗时。工具语义见 perf stat与 perf record。

4. 正确构造延迟直方图

hist(nsecs) 展示的是时间戳分布，不是操作延迟。下面以 bpftrace 0.24 为例，记录指定进程在采集期间完整发生的 write 系统调用，使用 TID 关联入口与出口。

先检查目标 tracepoint 与字段存在：

bpftrace -lv 'tracepoint:syscalls:sys_enter_write'
bpftrace -lv 'tracepoint:syscalls:sys_exit_write'

保存为 write-latency.bt：

tracepoint:syscalls:sys_enter_write
/pid == $1/
{
    @start[tid] = nsecs(monotonic);
}

tracepoint:syscalls:sys_exit_write
/pid == $1 && @start[tid]/
{
    @lat_us = hist((nsecs(monotonic) - @start[tid]) / 1000);
    @returns[args->ret < 0] = count();
    delete(@start, tid);
}

interval:s:10
{
    exit();
}

END
{
    clear(@start);
}

bpftrace write-latency.bt 12345

将 12345 替换为待测进程 PID。@returns[0] 是非负返回，@returns[1] 是负返回；正值还可能是短写，不能直接叫“完整业务成功”。时间单位为微秒，10000 微秒是 10 毫秒。

此测量包括 syscall 期间阻塞和调度等待，不等于设备完成延迟；例如文件 write 返回后，数据可能还在页缓存。它也不覆盖 writev、io_uring 等其他写路径。采集开始前已进入或结束时尚未返回的调用不会进入完整样本，长尾分析应考虑这种截断。

关联身份：同步 syscall 与异步请求分开设计

TID 足以关联普通同步 syscall 的入口和出口，但异步 I/O 请求会跨线程/中断完成，应改用真正的请求身份，并处理复用、合并、重试和清理。追踪通用可递归函数时还需区分嵌套深度，不能照搬单个 start[tid]。语言与时间接口参阅 bpftrace 0.24 标准库。

让同一线程发起两项重叠请求，再选择完成线程。两种关联方法同时处理相同事件；即使错误关联算出一个正数，也不代表它是这项请求的真实延迟。

5. 聚合、丢失与开销

逐事件 printf 可能使用户态输出成为瓶颈。只需分布时优先在内核侧聚合 count/hist/sum；确需明细时明确采样、过滤、缓冲容量与丢失计数。

必须记录丢失并清理残留条目，不能让下一次请求继承旧时间戳。

BCC 提供大量现成工具，但传统 BCC 工作流通常在运行时编译 BPF，并非一整套固定预编译 CO-RE 二进制。biolatency、runqlat、tcpretrans 等名字说明大致用途，准确测量起止点和过滤条件仍要看所安装版本。见 BCC 项目。

6. 日志、动态调试与故障转储

printk 日志等级影响记录的严重性分类，控制台阈值决定哪些记录打印到控制台，不等于其他等级从日志环中消失。实际 KERN_* 宏编码应使用内核头文件，不要把可读的 <0> 展示形式伪写成当前宏定义。

dynamic debug 只控制已编译进相应机制的 pr_debug() / dev_dbg() 等调用点。按函数名查询没有条目，并不等于函数没有执行；该函数可能没有相应调试调用点。接口可能位于 /proc/dynamic_debug/control 或 debugfs，依配置而定。

kdump 需要预留 crashkernel 内存并准备捕获内核、initramfs 和保存路径。崩溃后切入捕获内核，原内存经 /proc/vmcore 等接口导出，再由用户态工具保存或过滤。不能只执行 kexec -p 就假设下一次一定获得完整可读转储；设备状态与捕获环境也必须支持。

转储分析：符号必须匹配崩溃时的内核

分析时使用崩溃内核匹配的 vmlinux、调试符号和必要模块，而不是机械套用当前 uname -r：机器可能已经重启到另一版本。crash 中 bt 通常查看当前/指定任务回溯，foreach bt 才是逐任务回溯。参见 kdump与 crash 帮助。

KGDB 可设断点、读寄存器及单步，暂停执行会改变时间行为，不适合用断点结果直接推断真实时延；连接传输、内核配置和符号也要匹配。配置与示例另见构建与开发目录。

7. 一次可解释的诊断流程

1. 固定场景。 记录请求、时间窗口、负载与延迟边界。
2. 缩小方向。 用计数或采样区分 on-CPU 与等待。
3. 验证假设。 选择少量事件，必要时深入相关函数路径。
4. 检查观测影响。 比较启用前后的吞吐、延迟与丢失情况。
5. 保留解释条件。 记录工具版本、配置、过滤和测量限制。

每一步都应缩小不确定性，而不是单纯扩大日志量。

关联阅读：eBPF 基础、程序类型、用户态 ftrace 与 bpftrace 实践。