# TraceEvent TraceEvent是内核中一种探测的机制，据说在不使能的时候是没有损耗的。据说使用起来挺简单，但是要看懂着实需要花些力气。 ## 例子 从例子中学习，一般都是比较好的方法。内核开发者也比较nice，在内核源码samples/trace\_events目录下就有这么一个例子。 其中文件一共有三个： ``` total 56 -rw-r--r-- 1 weiyang staff 599 Feb 25 22:28 Makefile -rw-r--r-- 1 weiyang staff 2936 Feb 25 22:28 trace-events-sample.c -rw-r--r-- 1 weiyang staff 17495 May 2 14:43 trace-events-sample.h ``` 这个例子以内核模块的形式存在，所以只要执行make就可以编译完成。 总的来说，要定义和使用tracepoint，只要做两点。 * 用TRACE\_EVENT来定义一个新的tracepoint * 在需要的地方，使用函数trace\_XXX打印输出 有了例子我们就要跑一跑，来看看如何使用的。 首先我们要编译出我们的例子，这时候需要加上打开两个编译配置 * CONFIG\_SAMPLES * CONFIG\_SAMPLE\_TRACE\_EVENTS 编译 > make M=samples/trace\_events 然后加载这个例子模块 > modprobe trace-events-sample 因为用户接口在debugfs上，所以还要确保debugfs挂载了。 > mount -t debugfs none /sys/kernel/debug/ 此时我们就能在 /sys/kernel/debug/tracing/events/sample-trace/ 目录下看到该模块创建好的trace event了。 接下来，我们就可以打开这个探测时间，并且查看探测的输出了。 > cd /sys/kernel/debug/tracing > echo 1 > events/sample-trace/enable > cat trace > echo 0 > events/sample-trace/enable 通过cat trace观察，可以看出系统运行时的一些状态。 让我们进一步再来看看events/sample-trace这个目录： ``` ll events/sample-trace/ total 0 -rw-r--r-- 1 root root 0 May 4 23:24 enable -rw-r--r-- 1 root root 0 May 4 23:24 filter drwxr-xr-x 2 root root 0 May 4 23:24 foo_bar drwxr-xr-x 2 root root 0 May 4 23:24 foo_bar_with_cond drwxr-xr-x 2 root root 0 May 4 23:24 foo_bar_with_fn drwxr-xr-x 2 root root 0 May 4 23:24 foo_with_template_cond drwxr-xr-x 2 root root 0 May 4 23:24 foo_with_template_fn drwxr-xr-x 2 root root 0 May 4 23:24 foo_with_template_print drwxr-xr-x 2 root root 0 May 4 23:24 foo_with_template_simple ``` 可以看到 * 目录名称sample-trace由TRACE\_SYSTEM这个宏定义，所以通过查找这个宏，就能知道由多少events的大类 * 每一个TRACE\_EVENT都有一个自己的目录 源文件中trace\_XXX的函数就是执行探测记录的地方了。那么这些函数是怎么定义的呢？ ## TRACE\_EVENT定义 看完了例子，我们就该看代码实现了。讲真，这是我见过的最长的宏展开了。之前在qemu上看到的那个hmp-command和这个比起来简直就是个小屁孩。 先来看一下例子中是如何定义一个trace event的。和其他定义不同，定义trace event的定义在头文件，而非源文件。 我把trace-events-sample.h文件做一个简要的打开。 ``` #include TRACE_EVENT(foo_bar, ...) ... #undef TRACE_INCLUDE_PATH #undef TRACE_INCLUDE_FILE #define TRACE_INCLUDE_PATH . #define TRACE_INCLUDE_FILE trace-events-sample #include ``` 中间我省略了很多TRACE\_EVENT及其变体，每一个TRACE\_EVENT对应了一个trace point。 可以看到，一个trace event的定义需要涉及到起码两个头文件。 ### 史上最长宏定义 你以为就这么简单吗？当然不是，作为有多年阅读c语言代码的老司机，看到真正的定义，我都差点没有吐出来。。。 好了，不扯淡了。怎么能很好的解释这个宏展开的过程呢？还是用一张图吧。倒吸一口气，准备一次无尽的代码阅读。 ``` trace-events-sample.h +----------------------------------------------------------------+ |#define TRACE_SYSTEM sample-trace | |#define TRACE_SYSTEM_VAR sample_trace | | | |#defined(TRACE_HEADER_MULTI_READ) | |#include | | | | #define TRACE_EVENT(name) DECLARE_TRACE(name) | | #define DECLARE_TRACE(name) __DECLARE_TRACE(name) | | #define __DECLARE_TRACE() \| | struct tracepoint __tracepoint_##name; \| | void trace_##name() {} \| | int register_trace_##name() { \| | tracepoint_probe_register(); \| | } \| | int register_trace_prio_##name() { \| | tracepoint_probe_register_prio(); \| | } \| | int unregister_trace_##name() { \| | tracepoint_probe_unregister(); \| | } \| | void check_trace_callback_type_##name() \| | bool trace_##name_enabled() \| | | |TRACE_EVENT(foo_bar, ); | <- expand 1st time |#endif // TRACE_HEADER_MULTI_READ | | | |#define TRACE_INCLUDE_FILE trace-events-sample | |#include | | | | #undef TRACE_EVENT() | | #define TRACE_EVENT() DEFINE_TRACE() | | #define DEFINE_TRACE() DEFINE_TRACE_FN() \| # in "linux/tracepoint.h" | char __tpstrtab_##name[] = #name; \| | section("__tracepoints_strings") \| | struct tracepoint __tracepoint_##name = \| | { \| | __tpstrtab_##name, \| | STATIC_KEY_INIT_FALSE, \| | reg, = NULL \| | unreg, = NULL \| | NULL, \| | }; \| | section("__tracepoints") \| | __TRACEPOINT_ENTRY(name); | | #define __TRACEPOINT_ENTRY(name) \| | tracepoint_ptr_t __tracepoint_ptr_##name \| | __attribute__((section("__tracepoints_ptrs"))) = \| | &__tracepoint_##name | | | | | | #define TRACE_HEADER_MULTI_READ | | #include "trace-events-sample.h" | # due to TRACE_HEADER_MULTI_READ | | # we just have TRACE_EVENT() left | TRACE_EVENT() | <- expand 2nd time | | | | | #include | | | | #undef TRACE_EVENT() | | #define TRACE_EVENT() \| | DECLARE_EVENT_CLASS() \| | DEFINE_EVENT() | | #undef DECLARE_EVENT_CLASS() | | #define DECLARE_EVENT_CLASS() \| | struct trace_event_raw_##name {}; \| | struct trace_event_class event_class_##name; | | #undef DEFINE_EVENT() | | #define DEFINE_EVENT() | | struct trace_event_call event_##name; | | | | #include "trace-events-sample.h" | | TRACE_EVENT() | <- expand 3rd time | | | #undef DECLARE_EVENT_CLASS() | | #define DECLARE_EVENT_CLASS() \| | struct trace_event_data_offset_##name {} | | | | #include "trace-events-sample.h" | | TRACE_EVENT() | <- expand 4th time | | | #undef DECLARE_EVENT_CLASS() | | #define DECLARE_EVENT_CLASS( , , , , , print) \| | enum print_line_t trace_raw_output_##name { \| | trace_seq_printf(s, print); \| | } \| | struct trace_event_functions \| | trace_event_type_funcs_##name { \| | .trace = trace_raw_output_##name, \| | } | | | | #include "trace-events-sample.h" | | TRACE_EVENT() | <- expand 5th time | | | #undef DECLARE_EVENT_CLASS() | | #define DECLARE_EVENT_CLASS() \| | struct trace_event_fields \| | trace_event_fields_##name[] = { tstruct }; | | | | #include "trace-events-sample.h" | | TRACE_EVENT() | <- expand 6th time | | | #undef DECLARE_EVENT_CLASS() | | #define DECLARE_EVENT_CLASS() \| | int trace_event_get_offsets_##name( \| | struct trace_event_data_offset_##name off, \| | proto) {} | | | | #include "trace-events-sample.h" | | TRACE_EVENT() | <- expand 7th time | | | #undef DECLARE_EVENT_CLASS() | | #define DECLARE_EVENT_CLASS() \| | void trace_event_raw_event_##name() {} | | #undef DEFINE_EVENT() | | #define DEFINE_EVENT() \| | void ftrace_test_probe_##name() {} | | | | #include "trace-events-sample.h" | | TRACE_EVENT() | <- expand 8th time | | | #undef DECLARE_EVENT_CLASS() | | #define DECLARE_EVENT_CLASS() \| | char print_fmt_##name[] = print; \| | struct trace_event_class event_class_##name = {}; | | #undef DEFINE_EVENT() | | #define DEFINE_EVENT() \| | struct trace_event_call event_##name = {}; \| | struct trace_event_call *__event_##name = \| | section("_ftrace_events") &event_##name; | | | | #include "trace-events-sample.h" | | TRACE_EVENT() | <- expand 9th time | | +----------------------------------------------------------------+ ``` 终于完了，也不知道有没有漏掉什么。。。大家如果真的想要看实际代码中展开后的代码，可以运行 > make samples/trace\_events/trace-events-sample.i 生成的文件是经过预处理后得到的源代码。不过相信我，你可能不太会愿意去看这个（捂脸） 回过头来再看这展开，让我们来总结一下这个过程： * 一共包含了两个头文件：linux/tracepoint.h 和 trace/define\_trace.h * 在trace/define\_trace.h中，反复定义了TRACE\_EVENT且再次包含samples/trace\_events/trace-events-sample.h，实现了一个宏定义多次展开的效果 ### 究竟定义了什么？ 哪怕有了上面这个图，我想大部分人也是不会去看的。或者说，看了可能也不知道这些宏展开究竟定义了些什么？ > 帮人帮到底，送佛送到西 既然都帮大家做了宏展开，那我就干脆再用一张图展示一下这么多宏定义究竟定义了些什么。 ``` trace_event_call +------------------------------+ |list | | (struct list_head) | |name | tp | = &__tracepoint_##name |(char * | struct tracepoint *)| | +-------------------------+ | |name | = "name" | | (char *) | | |key | = STATIC_KEY_INIT_FALSE | | (struct static_key) | | |regfunc | = NULL | |unregfunc | = NULL | | () | | |funcs | = NULL | |(struct tracepoint_func*)| first entry is assigned to | | | trace_event_raw_event_##name | | | by tracepoint_probe_register | | | | +-------------------------+ |class | = &event_class_##name | (struct trace_event_class*)| | +-------------------------+ | |name | = TRACE_SYSTEM_STRING | | (char *) | | |probe | = trace_event_raw_event_##name | | (void *) | | |reg | = trace_event_reg | | (void *) | | |raw_init | = trace_event_raw_init | | (int *) | | |fields_array | = trace_event_fields_##name | | (trace_event_fields *)| | +-------------------------+ |event | # be registered by register_trace_event() | (struct trace_event) | | +-------------------------+ | |funcs | = &trace_event_type_funcs_##name | | (trace_event_functions)| | | +----------------------+ | | |trace | = trace_raw_output_##name -> trace_seq_printf(s, print) | | |raw | = trace_nop_print | | |hex | = trace_nop_print | | |binary | = trace_nop_print | | | (trace_print_func)| | +--+----------------------+ |flags | | (int) | |print_fmt | = print_fmt_##name | (char *) | | | +------------------------------+ ``` 经过了一番云里雾里的宏展开，实际上就是(主要)定义出了这么一个数据结构 -- **trace\_event\_call**。而且这个数据结构关联了几个重要的小伙伴 * tracepoint * trace\_event\_class * trace\_event 后续，我们将逐渐看到在初始化和使能的过程中，这些数据结构之间的爱恨情仇。 ## 注册trace\_event 有了数据结构，想要使用这个功能，我们能想到的第一步就是要把相关的数据结构注册到某个地方，这样下次才能够被使用到是不是？ 这个秘密隐藏在了刚才宏展开的最后一次展开中，大家可以回过去搜“section("*ftrace\_events") \&event*##name;”。有内核代码经验的朋友可能已经才到了，这个意思是我们把一部分的内容强制保存在了一个名为\_ftrace\_events的section中。这些是什么呢？对了就是trace\_event\_call结构体的指针们。 有了这个信息，我们再来看链接文件的定义： ``` #define FTRACE_EVENTS() . = ALIGN(8); \ __start_ftrace_events = .; \ KEEP(*(_ftrace_events)) \ __stop_ftrace_events = .; \ __start_ftrace_eval_maps = .; \ KEEP(*(_ftrace_eval_map)) \ __stop_ftrace_eval_maps = .; ``` 我们看到\_ftrace\_events这个section被包含在\_\_start\_ftrace\_events之间。那就沿着这条线继续。 ``` struct trace_event_call **iter, *call; for_each_event(iter, __start_ftrace_events, __stop_ftrace_events) { call = *iter; ret = event_init(call); call->class->raw_init(call); if (!ret) list_add(&call->list, &ftrace_events); } ``` 看到了么？ 我们依次从\_\_start|stop\_ftrace\_events之间拿出每一个内容，再执行event\_init()。而这个类型正好是trace\_event\_call，和刚才的定义吻合上。 但是event\_init()里面又调用了什么call->class->raw\_init(call)，这是什么个鬼？别急，这个我已经给你写好了。请跳回到刚才解释trace\_event\_call的图上找找，这个raw\_init函数就是trace\_event\_raw\_init。最后这个通过register\_trace\_event将trace\_event\_call.event注册到系统中，而这个event的类型是trace\_event。 怎么样，是不是够刺激的？ 最后我们再来展示一下trace\_event注册到系统中后的样子吧。 ``` ftrace_event_list(struct list_head) | | struct trace_event +->+------------------------------+ |list | | (struct list_head) | |node | | (struct hlist_node) | |type | = sort of index in ftrace_event_list | (int) | also a key in event_hash[] |funcs | = &trace_event_type_funcs_##name | (trace_event_functions) | | +--------------------------+ | |trace | = trace_raw_output_##name -> trace_seq_printf(s, print) | |raw | = trace_nop_print | |hex | = trace_nop_print | |binary | = trace_nop_print | | (trace_print_func) | +---+--------------------------+ event_hash[128] (sturct hlist_head) ``` trace\_event结构会在两个地方注册： * ftrace\_event\_list： 这个链表用来遍历事件的号码 * event\_hash\[128]: 这个哈希表用来查找 有没有看到其中funcs的成员第一个是之前定义的 trace\_raw\_output\_##name？我猜这个就是最后输出到trace文件的代码，你觉得呢？ 好了，数据结构注册完了，接下来是什么呢？ ## 注册trace\_event\_call 在上一节中，我们看到了内核通过编译链接的方法找到了trace\_event\_call，并且将其中的trace\_event注册到了系统中，现在我们来看看trace\_event\_call是如何注册到系统中的。 这个过程就在event\_init()函数下面一点。一共有两个步骤： * 添加到ftrace\_events链表 * 添加到trace\_array的events 第一步就在刚才的代码片段中list\_add(\&call->list, \&ftrace\_events)，而第二步则是通过函数\_\_trace\_early\_add\_events()。 ``` __trace_early_add_events() list_for_each(call, &ftrace_events, list) __trace_early_add_new_event(call, tr) ``` 经过这次注册，将trace\_event\_call和trace\_array连接了起来： ``` struct trace_array +--------------------------------+ |events | | (struct list_head) | | ^ | | | | +--------------------------------+ | | | | trace_event_file trace_event_file trace_event_file | +--------------------------+ +--------------------------+ +--------------------------+ +----->|list |<-->|list |<-->|list | | (struct list) | | (struct list) | | (struct list) | |event_call | |event_call | |event_call | | (trace_event_call *) | | (trace_event_call *) | | (trace_event_call *) | | | | | | | +--------------------------+ +--------------------------+ +--------------------------+ ``` ## 创建tracefs 在使用trace工具的时候，会通过tracefs往某些文件里读写来控制ftrace。trace\_event也不例外，所以我们要先来看一下tracefs的构建，为后续的代码阅读做好准备。 说起来这个过程有点绕，因为创建tracefs的地方和刚才那些注册函数不在一个地方（系统启动时）。 ``` event_trace_init() tr = top_trace_array() d_tracer = tracing_init_dentry() tracefs_create_file("available_events", ,tr, &ftrace_avail_fops) trace_define_generic_fields() trace_define_common_fields() early_event_add_tracer(d_tracer, tr) create_event_toplevel_files(d_tracer, tr) /sys/kernel/debug/tracing/set_event, ftrace_set_event_fops /sys/kernel/debug/tracing/events /sys/kernel/debug/tracing/events/enable, ftrace_tr_enable_fops /sys/kernel/debug/tracing/set_event_pid, ftrace_set_event_pid_fops /sys/kernel/debug/tracing/set_event_notrace_pid, ftrace_set_event_notrace_pid_fops /sys/kernel/debug/tracing/events/header_page, ftrace_show_header_fops /sys/kernel/debug/tracing/events/header_event, ftrace_show_header_fops tr->event_dir = /sys/kernel/debug/tracing/events/ __trace_early_add_event_dirs(tr) event_create_dir(tr->event_dir, file), iterate on tr->events register_module_notifier(&trace_module_nb) ``` 具体细节可以看源代码，这里解释两点： * create\_event\_toplevel\_files 创建了和trace event相关的根目录的一些文件 * event\_create\_dir则是会对每一个trace\_array->events上的trace\_event\_file调用，创建每个event的目录 而这个trace\_array->events则是由, 刚才看到的函数\_\_trace\_early\_add\_new\_event()添加的。 ## 初始化过程的梳理 到这里估计你已经晕了，没事我自己写得也晕了。让我们来梳理一下整个初始化过程，明确一下这个注册和tracefs的创建顺序。 ``` start_kernel trace_init event_trace_enable event_init(trace_event_call) --- (1) list_add(trace_event_call, &ftrace_events) --- (2) __trace_early_add_event() list_for_each_entry(call, &ftrace_events, list) __trace_early_add_new_event() trace_create_new_event() --- (3) tracer_init_tracefs, fs_initcall() event_trace_init() early_event_add_tracer() __trace_early_add_event_dirs() --- (4) ``` * (1) 从特定的section中拿到trace\_event\_call数据结构，并注册了trace\_event * (2) 将trace\_event\_call添加到了ftrace\_events链表 * (3) 将每一个trace\_event\_call以trace\_event\_file的形式添加到trace\_array.events * (4) 为每一个trace\_array.events创建自己的tracefs 废了这么大力气我们都做了什么呢？ > 关联了tracefs和trace\_event\_file，也就是我嗯定义的trace\_event\_call。 所以，每当我们操作一个tracefs文件的时候，后面就对应这相应的trace\_event\_file和trace\_event\_call了。 ``` /sys/kernel/debug/tracing/events/sample-events/enable | | | v trace_event_file trace_event_call +-------------------+ +-------------------+ |event_call |---->| | | | | | +-------------------+ +-------------------+ ``` OK, 我们已经为tracefs的操作做好了准备，让我们来看看打开trace event选项时的动作吧。 ## 打开事件 在查看trace文件中的事件记录前，我们需要使能这个事件。 > echo 1 > events/sample-trace/enable 所以有个开关来控制事件。而当我们写这个文件的时候，触发到的内核函数就是刚才我们注册tracefs对应的ops中的event\_enable\_write。 ``` event_enable_write() ftrace_event_enable_disable(file, val) -> __ftrace_event_enable_disable() call->class->reg() -> trace_event_reg() tracepoint_probe_register(call->tp, class->class->probe, file) tracepoint_add_func(tp, &tp_func, prio) ``` 绕晕了，其实呢就是通过某种方式设置了tracepoint结构体中的funcs成员。刚才我们在trace\_event\_call结构体中已经看到了tracepoint结构，这次该好好看一眼了。 ``` tracepoint +------------------------------+ |name | = "name" | (char *) | |key | = STATIC_KEY_INIT_FALSE | (struct static_key) | |regfunc | = NULL |unregfunc | = NULL | () | |funcs | | (struct tracepoint_func*) | | +-------------------------+ | |func | = trace_event_raw_event_##name | |data | = &trace_event_file | | (void *) | | |prio | | | (int) | | +-------------------------+ | |func | = NULL | |data | | | (void *) | | |prio | | | (int) | +----+-------------------------+ ``` 主角终于登场了，经过这么一顿骚操作后，我们将之前定义好的 trace\_event\_raw\_event\_##name挂到了tracepoint的funcs列表中。当然我还省去了重要的一步--设置key。 ## 输出事件 终于到了最后了。之前说的都是定义和初始化，终于要看到调用的情况了。在例子中我们看到，当我们需要输出一个事件时，就会调用trace\_XXX()。这次该轮到它出场了。 先来看看trace\_XXX这个函数的定义，它也藏在了我们刚才宏定义的展开中，这次我们仔细看一眼 ``` static inline void trace_##name(proto) \ { \ if (static_key_false(&__tracepoint_##name.key)) \ __DO_TRACE(&__tracepoint_##name, \ TP_PROTO(data_proto), \ TP_ARGS(data_args), \ TP_CONDITION(cond), 0); \ if (IS_ENABLED(CONFIG_LOCKDEP) && (cond)) { \ rcu_read_lock_sched_notrace(); \ rcu_dereference_sched(__tracepoint_##name.funcs);\ rcu_read_unlock_sched_notrace(); \ } \ } \ ``` 每次我们调用trace\_XXX()函数的时候，先检查key是否使能了，如果使能了才继续往下走。接着我们再打开\_\_DO\_TRACE来看看。 ``` #define __DO_TRACE(tp, proto, args, cond, rcuidle) \ do { \ struct tracepoint_func *it_func_ptr; \ void *it_func; \ void *__data; \ \ it_func_ptr = rcu_dereference_raw((tp)->funcs); \ \ if (it_func_ptr) { \ do { \ it_func = (it_func_ptr)->func; \ __data = (it_func_ptr)->data; \ ((void(*)(proto))(it_func))(args); \ } while ((++it_func_ptr)->func); \ } \ \ preempt_enable_notrace(); \ } while (0) ``` 联系上上一小节的tracepoint结构体是不是能想到啥？对了，就是遍历tracepoint->funcs数组，然后调用它们。 好了，终于完整得看完了TRACE\_EVENT的定义和使用流程。小编累了，大家也累了，今天就到这里吧。 --- # Agent Instructions: Querying This Documentation If you need additional information that is not directly available in this page, you can query the documentation dynamically by asking a question. Perform an HTTP GET request on the current page URL with the `ask` query parameter: ``` GET https://richardweiyang-2.gitbook.io/kernel-exploring/00-index-2/02-trace_event.md?ask= ``` The question should be specific, self-contained, and written in natural language. The response will contain a direct answer to the question and relevant excerpts and sources from the documentation. Use this mechanism when the answer is not explicitly present in the current page, you need clarification or additional context, or you want to retrieve related documentation sections.