跳到主要内容

9.7 实战:使用 set_event 接口跟踪单次 Ping 请求

上一节我们用 available_filter_functions 这种「大撒网」的方式,把整个网络栈的函数调用图给扒了出来。虽然直观,但这就好比为了听清楚两个人在说什么,你把整栋楼人的麦克风都打开了——噪音太大,信息量太溢出。

其实,ftrace 还有另一种视角。它不是盯着「函数」看,而是盯着「事件」看。

这不仅仅是换个接口的问题——这两种方式看到的内核,是完全不同的两个切面。

从函数到事件

回想一下上一节的流程:我们把函数名写进 set_ftrace_filter,告诉 ftrace 「盯着这几个函数」。这很直觉,但有个问题:你得先知道函数名。

对于那些内核里已经定义好的「关键节点」,为什么还要我们自己去猜函数名呢?内核开发者早就帮我们把标记插好了。这些标记,就是 Tracepoints(跟踪点)

你可以把 Tracepoints 想象成埋在高速公路上的感应线圈。 上一种方法(available_filter_functions)就像是在路边派每个人去盯每一辆车;而 set_event 则是直接读取感应线圈的记录。

但这个类比有个地方需要小心:感应线圈只能告诉你「车经过了」,上下文不如盯梢的人丰富。在 ftrace 里,这意味着你会看到具体的参数值,但可能会失去函数调用的缩进层级

所有这些事件,都整齐地排列在 /sys/kernel/tracing/events 目录下。

看看这张图(图 9.16),这就是内核的「事件超市」:

图 9.16 – /sys/kernel/tracing/events 目录内容——所有内核跟踪点

还记得我们在第 4 章(《Debug via Instrumentation – Kprobes》)里聊过的动态 kprobes 吗?其实我们在那里已经用过这个事件追踪框架了。当时是用它来追踪那些没有内置跟踪点的函数,而现在,我们是在用内核自带的「原装」追踪点。

精简追踪范围——只看网络

如果我们只关心网络,那么 events 目录下的 netsockskbtcpudp 这些子目录就是我们的目标。

使用 set_event 接口的语法非常简单:直接把「系统:事件」的字符串 echo 进去就行了。如果你想一次性开启某个子系统下的所有事件,通配符 * 就派上用场了。

这比上一节的脚本要清爽得多。我们只需要把 FILTER_VIA_AVAIL_FUNCS 设为 0,脚本就会走另一条分支:

// ch9/ftrace/ping_ftrace.sh
[...]
FILTER_VIA_AVAIL_FUNCS=0
echo "[+] Function filtering:"
if [ ${FILTER_VIA_AVAIL_FUNCS} -eq 1 ] ; then
[... 上一节的逻辑 ...]
else
# 通过 set_event 接口进行过滤
# 这种方法很快,但细节会少一些!
# 我们会失去函数图的缩进,但能看到函数参数!
echo " Alternate event-based filtering (via set_event):"
echo 'net:* sock:* skb:* tcp:* udp:* napi:* qdisc:* neigh:* syscalls:*' >> set_event
fi

注意这里我加了一句 syscalls:*。为什么要看系统调用?因为我们需要上下文。只看网络包的来龙去脉,不知道是谁发的,就像看一场没有主角的电影。

输出结果——有得必有失

跑一下这个脚本,然后再发起一次 Ping。这一次,trace 文件里的内容画风大变。

这是部分输出(图 9.17):

图 9.17 – 通过 set_event 接口获取的 ftrace 报告(已过滤)

看出来了吗?

我们失去了一些东西,也得到了一些东西。

失去的:那个漂亮的、像代码缩进一样的函数调用层级图不见了。这就像把调用栈拍扁了,你很难一眼看出 udp_sendmsg 是不是嵌套在 ip_send_fill_frag 里面。

得到的:每一行后面多了详细的东西——函数参数的值。这太关键了。对于调试来说,知道「调用了这个函数」只是第一步,知道「传入的缓冲区指针是多少」才是定纷止争的关键。

如果是用 trace-cmd 工具(下一节马上讲),当你不使用 function_graph 插件时,它默认就会把参数打印出来,这和现在的行为是一致的。

回到那个「高速公路感应线圈」的类比: 现在输出的报告里,每一个参数值就像是感应线圈抓拍的照片。你可能没看到车是怎么开进来的(失去了层级缩进),但你可以清晰地看到车牌号和载重(得到了参数值)。对于排查「为什么参数错了导致丢包」这类问题,这种视角往往比看几千行缩进图更管用。

快速插入调试点——trace_printk()

说到调试参数,这里插播一个极其好用的 API:trace_printk()

很多内核新手喜欢用 printk() 打日志,跑起来才发现:「卧槽,日志刷得太慢了,把系统时序都打乱了」,或者更惨的,「printk() 缓冲区溢出了,关键信息丢了」。

trace_printk() 就是为了解决这个痛点存在的。它的语法和 printf() 一模一样:

trace_printk("myprj: at %s:%s():%d\n",__FILE__, __func__, __LINE__);

它和 printk 的本质区别在于

  1. 速度:它只写内存(ftrace 的 ring buffer),绝不碰控制台设备。这在处理中断这种「快如闪电」的代码路径时至关重要,否则就会出现海森堡 Bug——你看它,它就变样。
  2. 容量:ftrace 的缓冲区通常比 printk 的日志缓冲区大得多,而且是可调的。
  3. 读取方式:你在 dmesg 里是看不到它的。必须去读 /sys/kernel/tracing/tracetrace_pipe

还有一个小技巧:如果你用 function_graph 跟踪器,trace_printk() 的输出会显示为注释(/* ... */),混在函数调用流里,非常方便定位是哪一步打印的。

⚠️ 注意 内核文档明确说了,这东西仅供调试使用。不要把它留在正式代码里。

如果你只需要打印一个固定的字符串(不需要格式化),用 trace_puts() 会更快。内核开发者连这都想到了。

如果你想关掉这个功能(不想让 trace_printk 污染你的 trace),可以在 trace_options 里把 notrace_printk 写进去,或者往 options/trace_printk 里写 0