ftrace中没有syscall信息问题的分析

最新推荐文章于 2026-03-25 01:26:51 发布

原创最新推荐文章于 2026-03-25 01:26:51 发布 · 1.2k 阅读

4 ·

本内容遵循CC 4.0 BY-SA版权协议

标签

#linux #ftrace

本文详细介绍了Linux内核ftrace中syscall事件的实现机制，包括如何启用syscalls跟踪，内核如何记录系统调用的进入和退出信息。在分析过程中，发现了一个问题：在ARM64架构的实时系统中，cyclictest等测试工具只能显示sys_enter事件，缺少sys_enter_xxx详细信息。问题根源在于内核初始化时，由于SYSCALL_DEFINEx的定义不匹配，导致无法找到正确的系统调用符号。解决方案是统一内核和ftrace中系统调用符号匹配的实现，修复后成功获取了sys_enter_xxx的日志。

1，ftrace中syscall events的实现

ftrace是内核的一个重要分析供给，在分析内核代码运行路径和时间问题上有着其他工具不可比拟的优势，比如对于系统调用，我们在分析cyclictest测试日志的时候，可以看到这样的信息：

cyclicte-30530 7....0 9479.661181: sys_enter: NR 115 (1, 1, ffffbbfae420, 0, 0, ffffbbfaecd0) //系统进入了nanosleep调用，信息包括时间和其他参数

cyclicte-30530 7...10 9479.661181: sys_enter_clock_nanosleep: which_clock: 0x00000001, flags: 0x00000001, rqtp: 0xffffbbfae420, rmtp: 0x00000000

cyclicte-30530 7....0 9479.662180: sys_exit: NR 115 = 0 //系统离开了nanosleep调用

cyclicte-30530 7...10 9479.662180: sys_exit_clock_nanosleep: 0x0

如果要在event tracer中使能syscalls，首先要在编译内核中选中编译选项kernel hacking --> Tracers --> Trace syscalls，与之对应的内核编译选项是CONFIG_FTRACE_SYSCALLS。

内核在初始化的时候，创建了两个关于syscalls的tracepoints，分别是：

TRACE_EVENT_FN(sys_enter,

TP_PROTO(struct pt_regs *regs, long id),

TP_ARGS(regs, id),

TP_STRUCT__entry(

__field( long, id )

__array( unsigned long, args, 6 )

TP_fast_assign(

__entry->id = id;

syscall_get_arguments(current, regs, __entry->args);

TP_printk("NR %ld (%lx, %lx, %lx, %lx, %lx, %lx)",

__entry->id,

__entry->args[0], __entry->args[1], __entry->args[2],

__entry->args[3], __entry->args[4], __entry->args[5]),

syscall_regfunc, syscall_unregfunc

);

TRACE_EVENT_FLAGS(sys_enter, TRACE_EVENT_FL_CAP_ANY)

TRACE_EVENT_FN(sys_exit,

TP_PROTO(struct pt_regs *regs, long ret),

TP_ARGS(regs, ret),

TP_STRUCT__entry(

__field( long, id )

__field( long, ret )

TP_fast_assign(

__entry->id = syscall_get_nr(current, regs);

__entry->ret = ret;

TP_printk("NR %ld = %ld",

__entry->id, __entry->ret),

syscall_regfunc, syscall_unregfunc

);

可以使用如下命令看到tracepoint的创建情况：

cat /proc/kallsyms |grep sys_enter

0000000000000000 t trace_event_raw_event_sys_enter

...

0000000000000000 D __tracepoint_sys_enter

其中__tracepoint_sys_enter为sys_enter的tracepoint结构，trace_event_raw_event_sys_enter具体负载将信息“sys_enter: NR 115 (1, 1, ffffbbfae420, 0, 0, ffffbbfaecd0)”打印到ftrace的ringbuffer中。

同时，syscalls在debugfs中还创建了用户空间的接口文件：

ls /debugfs/events/raw_syscalls/

sys_enter

sys_exit

当用户调用命令”echo 1 > /debugfs/event/raw_syscalls/enable”的时候，系统会根据命令调用

event_enable_write

--> ftrace_event_enable_disable

--> call->class->reg

--> trace_event_reg

--> tracepoint_probe_register

将trace_event_raw_event_sys_enter注册到tracepoint的回调函数列表中。

当用户空间调用syscall，以nanosleep为例，内核运行路径为：

el0_svc

-->el0_svc_handler

-->el0_svc_common

-->syscall_trace_enter

-->trace_sys_enter

-->invoke_syscall

-->syscall_fn(regs)

-->syscall_trace_exit

-->ret_to_user

-->work_pending

-->do_notify_resume

kernel_exit

其中trace_sys_enter会调用__DO_TRACE，进而调用trace_event_raw_event_sys_enter将sys_enter的信息打印到ftrace ringbuffer中。sys_exit的初始化，使能和调用与sys_enter相同，不在赘述。

以上分析的是raw_syscalls的初始化，使能和调用的过程，那么如sys_enter_clock_nanosleep这样具体的信息是如何打印出来的呢，我们还是从这几个步骤来分析。

初始化的时候，内核会调用init_ftrace_syscalls，在init_ftrace_syscalls中，调用find_syscall_meta-->kallsyms_lookup来根据系统调用的函数地址找到符号，最后在debugfs中创建用户接口，如：

ls events/syscalls

sys_enter_accept ... ....

在用户调用”echo 1 > /debugfs/event/syscalls/enable”的时候，内核会调用ftrace_event_enable_disable-->call->class->reg，其中reg函数为syscall_enter_register，它会进而调用register_trace_sys_enter将回调函数ftrace_syscall_enter挂在tracepoint的回调函数列表中，ftrace_syscall_enter负责将syscall的具体信息打印出来，如“sys_enter_clock_nanosleep: which_clock: 0x00000001, flags: 0x00000001, rqtp: 0xffffbbfae420, rmtp: 0x00000000”。

使能的过程与raw_syscalls相同，当系统调用到trace_sys_enter之后，会调用__DO_TRACE，我们具体看一看这个宏：

#define __DO_TRACE(tp, proto, args, cond, rcuidle)

...

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); \

}

...

我们只截取了跟本问题相关的部分，由代码可见，__DO_TRACE中一次调用了链表it_func_ptr的所有的回调函数，其中包括trace_event_raw_event_sys_enter和ftrace_syscall_enter，从而得到了下述两条日志：

cyclicte-30530 7....0 9479.661181: sys_enter: NR 115 (1, 1, ffffbbfae420, 0, 0, ffffbbfaecd0)

cyclicte-30530 7...10 9479.661181: sys_enter_clock_nanosleep: which_clock: 0x00000001, flags: 0x00000001, rqtp: 0xffffbbfae420, rmtp: 0x00000000

同样，sys_exit_xxx也不在赘述。

2，问题描述

我们的项目运行在ARM64架构的实时系统，内核版本为5.4，在运行cyclictest等测试工具时，只有sys_enter，而没有sys_enter_xxx的信息。

3，问题分析

一开始，我发现我们的项目关于系统调用的处理，也就是el0_svc跟社区代码相比，改动了很多，我以为是修改的时候把syscall_trace_enter-->trace_sys_enter给忘记了。后来仔细阅读了代码，日志这部分还是会正常调用的。

进一步排查，发现debugfs/events中只有raw_syscalls的目录，并没有syscalls的目录，也就是说，问题出在了初始化。

经过打印log排查，发现初始化过程中，运行到find_syscall_meta中：

static __init struct syscall_metadata *

find_syscall_meta(unsigned long syscall)

{

kallsyms_lookup(syscall, NULL, NULL, NULL, str);

for ( ; start < stop; start++) {

if ((*start)->name && arch_syscall_match_sym_name(str, (*start)->name))

return *start;

}

return NULL;

}

全部返回为空。进一步看一下arch_syscall_match_sym_name，它的实现有两个，一个在kernel/trace/trace_syscall.c中：

static inline bool arch_syscall_match_sym_name(const char *sym, const char *name)

{

return !strcmp(sym + 3, name + 3);

}

另一个在arch/arm64/include/asm/ftrace.h中：

static inline bool arch_syscall_match_sym_name(const char *sym, const char *name)

{

return !strcmp(sym + 8, name);

}

我们项目使用的是arm64的实现，需要偏移8个字节之后再比较，为什么？看一下SYSCALL_DEFINEx的定义。

SYSCALL_DEFINEx也有两个定义，一个定义在include/linux/syscalls.h中

#define __SYSCALL_DEFINEx(x, name, ...) \

asmlinkage long sys##name(const struct pt_regs *regs); \

系统调用的函数名即变为sys_mmap,sys_clock_nanosleep等。

另一个是在arch/arm64/include/asm/syscall_wrapper.h中：

#define __SYSCALL_DEFINEx(x, name, ...) \

asmlinkage long __arm64_sys##name(const struct pt_regs *regs); \

每个系统调用都加了一个前缀__arm64_，系统调用的函数名即变为__arm64_sys_mmap,__arm64_sys_clock_nanosleep等，这也是arch_syscall_match_sym_name为什么要偏移8个字节的原因。

我们这个项目在配置的时候，使用了include/linux/syscalls.h中的SYSCALL_DEFINEx，但arch_syscall_match_sym_name使用的是arch/arm64/include/asm/ftrace.h中的定义，需要偏移8个字节，难怪找不到匹配的字符串。

4，解决问题的方案

将arch/arm64/include/asm/ftrace.h中arch_syscall_match_sym_name的定义取消，使用kernel/trace/trace_syscall.c的定义，问题修复，debugfs中可以看到event/syscalls，而且ftrace中，也会找到相应的log。