1. 前言
限于作者能力水平,本文可能存在谬误,因此而给读者带来的损失,作者不做任何承诺。
2. 背景
本文基于内核文档 Event Tracing 翻译整理而成。
3. 使用内核事件跟踪系统
我们可以使用 tracepoint
来跟踪内核状态。但并不是所有的 tracepoint
都可以使用 事件跟踪系统
来进行跟踪。
3.1 启用、禁用追踪事件
我们使用 ftrace 跟踪系统
的 set_event
文件接口来跟踪内核预定义事件:
# cd /sys/kernel/debug/tracing/
# ls -l set_event
-rw-r--r-- 1 root root 0 4月 17 15:41 set_event
向 set_event
写入一个事件名,启用对某事件的追踪
。譬如,按如下操作跟踪进程唤醒事件
:
# echo 0 > tracing_on
# echo > trace
# echo sched_wakeup >> set_event
# echo 1 > tracing_on
# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 2557/2557 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
Xorg-1099 [001] d... 3236.276655: sched_wakeup: comm=compiz pid=2325 prio=120 target_cpu=000
bash-3053 [003] d... 3236.276988: sched_wakeup: comm=kworker/u256:0 pid=3827 prio=120 target_cpu=002
<idle>-0 [000] dNh. 3236.277061: sched_wakeup: comm=gnome-terminal- pid=2996 prio=120 target_cpu=000
<idle>-0 [000] dNh. 3236.278700: sched_wakeup: comm=compiz pid=2325 prio=120 target_cpu=000
<idle>-0 [003] dNs. 3236.278708: sched_wakeup: comm=kworker/3:0 pid=29 prio=120 target_cpu=003
<idle>-0 [000] dNs. 3236.278710: sched_wakeup: comm=kworker/0:0 pid=3658 prio=120 target_cpu=000
<idle>-0 [001] dNs. 3236.278710: sched_wakeup: comm=kworker/1:1 pid=36 prio=120 target_cpu=001
<idle>-0 [003] dNs. 3236.278737: sched_wakeup: comm=rcu_sched pid=8 prio=120 target_cpu=002
compiz-2325 [000] d... 3236.278901: sched_wakeup: comm=Xorg pid=1099 prio=120 target_cpu=001
Xorg-1099 [001] d... 3236.279001: sched_wakeup: comm=compiz pid=2325 prio=120 target_cpu=000
compiz-2325 [000] d... 3236.279319: sched_wakeup: comm=Xorg pid=1099 prio=120 target_cpu=001
Xorg-1099 [001] d... 3236.279416: sched_wakeup: comm=compiz pid=2325 prio=120 target_cpu=000
compiz-2325 [000] d... 3236.279700: sched_wakeup: comm=Xorg pid=1099 prio=120 target_cpu=001
Xorg-1099 [001] d... 3236.279813: sched_wakeup: comm=compiz pid=2325 prio=120 target_cpu=000
compiz-2325 [000] d... 3236.280148: sched_wakeup: comm=Xorg pid=1099 prio=120 target_cpu=001
Xorg-1099 [001] d... 3236.280441: sched_wakeup: comm=compiz pid=2325 prio=120 target_cpu=000
命令 echo sched_wakeup >> set_event
中使用 >>
而不是 >
,因为如果使用 >
,会先禁用所有的追踪事件,而使用 >>
可以防止这种事情。移除某个事件追踪
:
# echo '!sched_wakeup' >> set_event
在事件名前加上 !
移除对事件的追踪。移除对所有事件的追踪
:
# echo > set_event
启用对所有事件的追踪
:
# echo *:* > set_event
系统支持的所有事件记录在文件 available_events
中:
# root@bill-virtual-machine:/sys/kernel/debug/tracing# more available_events
v4l2:v4l2_dqbuf
v4l2:v4l2_qbuf
v4l2:vb2_v4l2_buf_done
v4l2:vb2_v4l2_buf_queue
v4l2:vb2_v4l2_dqbuf
v4l2:vb2_v4l2_qbuf
vb2:vb2_buf_done
vb2:vb2_buf_queue
vb2:vb2_dqbuf
vb2:vb2_qbuf
drm:drm_vblank_event
drm:drm_vblank_event_queued
drm:drm_vblank_event_delivered
raw_syscalls:sys_exit
raw_syscalls:sys_enter
vsyscall:emulate_vsyscall
xen:xen_cpu_set_ldt
xen:xen_cpu_write_gdt_entry
xen:xen_cpu_load_idt
[...]
在内核启动阶段,可以通过命令行选项,开启指定事件追踪:
trace_event=[event-list]
3.2 追踪事件的目录结构
所有的追踪事件按子系统类别
组织在目录 events
下:
# ls events/
alarmtimer dma_fence fs iommu migrate page_isolation rcu sock timer writeback
block drm fs_dax irq mmc pagemap regmap spi tlb x86_fpu
bpf enable ftrace irq_matrix module percpu regulator swiotlb udp xdp
bridge exceptions gpio irq_vectors mpx power rpm sync_trace v4l2 xen
cgroup ext4 header_event jbd2 msr printk sched syscalls vb2 xhci-hcd
clk fib header_page kmem napi qdisc scsi task vmscan
cma fib6 huge_memory libata net random signal tcp vsyscall
compaction filelock hyperv mce nmi ras skb thermal wbt
cpuhp filemap i2c mdio oom raw_syscalls smbus thermal_power_allocator workqueue
events 目录
下所有子目录就是子系统类别,如 sched,syscalls,...
。写入到 set_event
文件接口启用的事件,可以按格式 <subsystem>:*
的形式组织,如开启所有 irq
类别的追踪事件,可以向 set_event
写入:
# echo irq:* > set_event
每个子系统类别(如 irq, sched, ..
.)下的每个事件,在子系统目录下,都会有一个以事假名命名的目录:
# ls events/irq
enable filter irq_handler_entry irq_handler_exit softirq_entry softirq_exit softirq_raise
我们看到,irq 事件子系统包含 irq_handler_entry,irq_handler_exit ,softirq_entry ,softirq_exit softirq_raise
这 5 个事件,每个事件对应一个目录,目录下包含事件的属性节点。如 irq_handler_entry 事件:
# ls events/irq/irq_handler_entry/
enable filter format hist id trigger
启用禁用某个跟踪事件,除了可以通过写 set_event
外,还可以通过修改事件目录下的 enable
文件接口:
# echo 1 > events/irq/irq_handler_entry/enable 启用 irq:irq_handler_entry 事件
# echo 0 > events/irq/irq_handler_entry/enable 禁用 irq:irq_handler_entry 事件
修改事件的 enable
,会间接的修改 set_event
文件接口。
3.3 追踪事件数据格式
每个追踪事件,都有一个格式文件 format
:
# ls -l events/sched/sched_wakeup/format
-r--r--r-- 1 root root 0 4月 17 15:41 events/sched/sched_wakeup/format
# cat events/sched/sched_wakeup/format
# cat events/sched/sched_wakeup/format
name: sched_wakeup
ID: 307
format:
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
field:int common_pid; offset:4; size:4; signed:1;
field:char comm[16]; offset:8; size:16; signed:1;
field:pid_t pid; offset:24; size:4; signed:1;
field:int prio; offset:28; size:4; signed:1;
field:int success; offset:32; size:4; signed:1;
field:int target_cpu; offset:36; size:4; signed:1;
print fmt: "comm=%s pid=%d prio=%d target_cpu=%03d", REC->comm, REC->pid, REC->prio, REC->target_cpu
format
文件描述了事件日志数据的每个域(field
):name:
部分显示了事件名称;ID:
部分显示了事件 ID;format:
部分显示了事件数据各域(field
)的 域数据类型,域名字,域偏移位置,域大小
,这些信息可用于解析跟踪事件二进制数据流,也可用于事件过滤器定位事件数据域(field
)名;print fmt:
部分显示在文本模式显示事件数据的格式化字串。
事件数据的数据域(field
)中,有一部分是所有事件都相同的,这些相同的数据域名以 common_
打头,如上面输出的 common_type,common_flags,common_preempt_count,common_pid
这 4 个数据域;事件的其它数据域因事件而异,对应域 TRACE_EVENT()
定义的数据域。
3.4 事件过滤器
当事件写入跟踪缓冲时,跟踪系统对比跟踪数据和跟踪事件关联的过滤器布尔表达式,和过滤表达式不匹配的数据将被丢弃。
3.4.1 过滤器表达式语法
过滤器表达式由一个或多个 谓词
组成,可以使用逻辑运算符 && 或 || 进行组合。谓词
是指比较事件数据域和常量值的子句:匹配返回1,不匹配返回0。看一下过滤表达式的语法:
field-name relational-operator value
括号
可用于提供任意逻辑分组,双引号
可用于防止 shell 将运算符解释为 shell 元字符。
可用数据域名称 field-name
,可以在事件的 format
文件中的 field
字段找到;关系运算符 relational-operator
,取决于要测试的数据域的类型:数字类型数据域
可用的关系运算符有 ==, !=, <, <=, >, >=, &
;字符串类型数据域
可硬的关系运算符有 ==, !=, ~
,~
关系运算符后可跟通配符 *,? ,字符集 ([) 。如:
prev_comm ~ "*sh"
prev_comm ~ "sh*"
prev_comm ~ "*sh*"
prev_comm ~ "ba*sh"
如果追踪事件的数据域名是指向用户空间的指针(例如 sys_enter_openat
中的filename
参数),则必须将 .ustring
附加到字段名称:filename.ustring ~ "password"
,因为内核必须知道指针指向的是用户空间内存。你可以将任何指向函数地址的 long 类型转换为函数地址(通过 .function
后缀),并与函数名做比较,如 call_site.function == security_prepare_creds
。当数据域 call_site
指向函数 security_prepare_creds
时,事件数据内容将进行过滤。也就是说,它将比较 call_site
的值,如果它大于或等于函数 security_prepare_creds
的起始地址且小于该函数的末尾地址时,则过滤器将返回 true。.function
后缀仅可用于 long
类型,且仅可用 ==
或 !=
运算符进行比较。
3.4.2 设置和清除事件过滤器
通过写事件的 filter
文件节点来设置事件的过滤器。如:
# echo "common_preempt_count > 4" > events/sched/sched_wakeup/filter
# echo "((sig >= 10 && sig < 15) || sig == 17) && comm != bash" > events/signal/signal_generate/filter
通过向事件的 filter
文件节点写 0 来清除事件过滤器:
# echo 0 > events/sched/sched_wakeup/filter
# cat events/sched/sched_wakeup/filter
none
# echo 0 > events/signal/signal_generate/filter
# cat events/signal/signal_generate/filter
none
3.4.3 事件过滤器的限制
如果事件过滤器是针对字符串指针(char *
)的, 且该指针不是指向跟踪系统 ring buffer 内的字符串,而是指针内核或用户空间内存,在这样的情形下,出于安全考虑,最多将指针指向的 1024
个字节拷贝到临时缓冲进行比较;另外,如果指针指向的地址无法访问,则认为比较不匹配。
3.4.4 事件子系统(subsystem)过滤器
我们看到,不光事件自身目录下会有过滤器文件接口 filter
,事件所属的子系统下也会有一个 filter
文件接口:
# ls events/sched/filter -l
-rw-r--r-- 1 root root 0 4月 19 12:06 events/sched/filter
通过子系统(subsystem)
过滤器接口文件 filter
,可以对子系统(subsystem)
下所有事件进行的事件过滤器设置和清除。但请注意,如果子系统中任何事件的过滤器缺少子系统(subsystem)
过滤器中指定的数据域,或者由于任何其他原因无法应用过滤器,则该事件的过滤器将保留其以前的设置。混合对事件和事件子系统(subsystem)
的过滤器接口进行配置,这可能会导致意料之外的设置,从而造成一定的混乱。
看一个设置子系统(subsystem)
的例子:
# echo "common_pid == 1970" > events/sched/filter
# cat events/sched/filter
### global filter ###
# Use this to set filters for multiple events.
# Only events with the given fields will be affected.
# If no events are modified, an error message will be displayed here
# cat events/sched/*/filter
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
common_pid == 1970
看到了吗?子系统(subsystem)
的 filter
文件里面,没有设置的过滤器配置,取而代之的是将对子系统(subsystem)
的 filter 文件的设置,传递给子系统(subsystem)
下各个事件的 filter
文件接口。
如果我们对 子系统(subsystem)
的 filter
文件写 0 ,又会产生什么效果呢?
# echo 0 > events/sched/filter
# cat events/sched/*/filter
none
none
none
none
none
none
none
none
none
none
none
none
none
none
none
none
none
none
none
none
none
none
none
none
整个子系统(subsystem)
事件的 filter
设置都被清除了。试图设置非公共数据域到子系统(subsystem)
的 filter ,设置将被不支持数据域的事件忽略。
3.4.5 按进程ID进行过滤
# echo $$ > set_event_pid
echo 123 244 1 >> set_event_pid
3.5 事件触发器(trigger)命令
跟踪事件可以按条件调用触发器(trigger)命令
,这些命令将在后面详细介绍。这些命令可以启用或禁用事件,或者在事件触发时,进行栈跟踪。每当事件触发时,都会调用事件关联的触发器命令(trigger)
集。被过滤器规则过滤掉的事件的命令不会被触发。
可通过改写事件的 trigger
文件,将触发器(trigger)命令
添加到事件或从事件中移除。事件可以关联任意个数的触发器(trigger)命令
,但前提是命令要支持关联的事件。
写入到 trigger
文件接口的语法,基本上基于写入 set_ftrace_filter
的语法,但它们之间还是存在一些重要差异。
注意,写 trace_marker
文件将触发 events/ftrace/print/trigger
中配置的触发器命令。
3.5.1 配置事件触发器(trigger)命令表达式语法
添加触发器(trigger)命令表达式语法:
echo 'command[:count] [if filter]' > trigger
移除触发器(trigger)命令表达式语法,在添加的表达式前面添加一个 !
:
echo '!command[:count] [if filter]' > trigger
移除触发器(trigger)命令表达式语法中,[if filter]
不用于匹配命令,因此将其删除,仍然可以达到相同的效果。
添加移除表达式中 filter
部分的语法,和章节 3.4
中过滤器语法相同。
3.5.2 支持的触发器(trigger)命令
3.5.2.1 enable_event / disable_event
关联了 enable_event / disable_event
触发器命令的事件,当被触发时可以禁用或启用其它跟踪事件。
# echo 'enable_event:kmem:kmalloc:1' > events/syscalls/sys_enter_read/trigger
上面的命令,导致在进入 read()
系统调用时,启用对事件 kmem:kmalloc
的追踪1次
。
# echo 'disable_event:kmem:kmalloc' > events/syscalls/sys_exit_read/trigger
上面的命令,导致每次
退出 read()
系统调用时,禁用对事件 kmem:kmalloc
的追踪。
设置 enable_event / disable_event
触发命令的语法表达式为:
enable_event:<system>:<event>[:count]
disable_event:<system>:<event>[:count]
移除前面的触发命令语法表达式为:
echo '!enable_event:kmem:kmalloc:1' > events/syscalls/sys_enter_read/trigger
echo '!disable_event:kmem:kmalloc' > events/syscalls/sys_exit_read/trigger
3.5.2.2 stacktrace
每当事件触发时,导出跟踪缓冲中的堆栈追踪记录。如下面的命令,每次 kmalloc
被触发时,导出跟踪缓冲中堆栈追踪记录:
# echo 'stacktrace' > events/kmem/kmalloc/trigger
下面的命令表示,前5次
调用 kmalloc
分配大于等于 64KB
的内存时,导出跟踪缓冲中堆栈追踪记录:
# echo 'stacktrace:5 if bytes_req >= 65536' > events/kmem/kmalloc/trigger
stacktrace
触发器命令的语法表示式为:
stacktrace[:count]
通过下面的操作,移除前述添加的stacktrace
触发器命令:
# echo '!stacktrace' > events/kmem/kmalloc/trigger
# echo '!stacktrace:5 if bytes_req >= 65536' > events/kmem/kmalloc/trigger
后一条命令的移除操作也可以通过如下命令达到:
# echo '!stacktrace:5' > events/kmem/kmalloc/trigger
3.5.2.3 snapshot
事件被触发时,记录当前事件数据快照到 snapshot
缓冲。如下面的命令表示,每当磁盘拔出时,如果磁盘请求队列的长度大于1(还有数据没刷往磁盘?),则记录当前事件数据快照到 snapshot
缓冲。
# echo 'snapshot if nr_rq > 1' > events/block/block_unplug/trigger
如果要仅记录一个事件数据快照,按如下操作:
# echo 'snapshot:1 if nr_rq > 1' > events/block/block_unplug/trigger
移除操作:
# echo '!snapshot if nr_rq > 1' > events/block/block_unplug/trigger
# echo '!snapshot:1 if nr_rq > 1' > events/block/block_unplug/trigger
3.5.2.4 traceon / traceoff
在事件触发时,开启或关闭事件追踪,如果不指定次数,则开关次数不限。如下面的命令,当第一次拔出磁盘时,如果磁盘请求队列的长度大于1(还有数据没刷往磁盘?),则关闭事件追踪。
# echo 'traceoff:1 if nr_rq > 1' > events/block/block_unplug/trigger
为了总是在磁盘拔出,且磁盘请求队列的长度大于1时,总是关闭追踪事件,按如下操作:
# echo 'traceoff if nr_rq > 1' > events/block/block_unplug/trigger
移除操作:文章来源:https://www.toymoban.com/news/detail-421817.html
# echo '!traceoff:1 if nr_rq > 1' > events/block/block_unplug/trigger
# echo '!traceoff if nr_rq > 1' > events/block/block_unplug/trigger
3.5.2.5 hist
参见 https://www.kernel.org/doc/html/latest/trace/histogram.html 。文章来源地址https://www.toymoban.com/news/detail-421817.html
到了这里,关于Linux:ftrace之事件跟踪的文章就介绍完了。如果您还想了解更多内容,请在右上角搜索TOY模板网以前的文章或继续浏览下面的相关文章,希望大家以后多多支持TOY模板网!