文章目录
- 1. 简介
- 2. 使用
- 2.1 加入ftrace
- 2.2 ftrace 基础
- 2.2.1 tracer
- 2.2.2 filter(可选)
- 2.2.3 读取trace
- 2.2.4 ftrace_enabled
- 2.3 使用function_graph查看do_sys_open的执行过程
- 2.3 使用function查看do_sys_open的执行
- 2.3 使用wakeup
- 2.3 使用wakeup_rt
- 2.4 event
- 3. trace-cmd
1. 简介
ftrace是一套内核调试工具,从2.6版本之后集成到linux内核中。通过它可以轻松的追踪到内核发生的行为,也能调试分析延迟和性能问题。
在常见的linux发行版中,一般都使能了ftrace,它的操作目录在/sys/kernel/debug/tracing
中
使用
mount | grep tracefs
命令验证ftrace是否可用
2. 使用
2.1 加入ftrace
在编译内核时需要将trace相关加入编译:
Kernel hacking -->Tracer --->....
ftrace通过debugfs向用户提供访问接口,所以需要系统挂载debugfs到/sys/kernel/debug/
:
将如下内容添加到/etc/fstab
:
debugfs /sys/kernel/debug debugfs defaults 0 0
或者在运行时挂载:
mount -t debugfs debugfs /sys/kernel/debug
2.2 ftrace 基础
ftrace的使用步骤如下:
2.2.1 tracer
通过cat available_tracers
可以查看当前可使用的追踪器:
[root@qemu_imx6ul:/tracing]# cat available_tracers
hwlat function_graph wakeup_dl wakeup_rt wakeup preemptirqsoff preemptoff irqsoff function nop
追踪器 | 作用 |
---|---|
function | 函数调用追踪器,可以看出哪个函数何时调用,可以通过过滤器指定要跟踪的函数 |
function_graph | 函数调用图表追踪器,可以看出哪个函数被哪个函数调用,何时返回 |
blk | block I/O追踪器,blktrace用户应用程序 使用的跟踪器 |
mmiotrace | MMIO(Memory Mapped I/O)追踪器,用于Nouveau驱动程序等逆向工程 |
wakeup | 跟踪进程唤醒信息,进程调度延迟追踪器 |
wakeup_rt | 与wakeup相同,但以实时进程为对象 |
nop | 将 nop 写入 current_tracer 文件可以删除之前所使用的跟踪器,并清空之前收集到的跟踪信息,即刷新 trace 文件 |
wakeup_dl | 跟踪并记录唤醒SCHED_DEADLINE任务所需的最大延迟(如"wakeup”和"wakeup_rt”一样) |
mmiotrace | 一种特殊的跟踪器,用于跟踪二进制模块。它跟踪模块对硬件的所有调用 |
hwlat | 硬件延迟跟踪器。它用于检测硬件是否产生任何延迟 |
通过写入current_tracer
可以设置当前使用的追踪器
echo function_graph > current_tracer
2.2.2 filter(可选)
过滤器 | 作用 |
---|---|
set_ftrace_filter | 设置要跟踪的函数 |
set_ftrace_notrace | 反向过滤器,设置后输出除了函数以外内容 |
set_graph_function | 设置要跟踪的函数 |
set_graph_notrace | 反向过滤器,打开后进入对应函数会关闭跟踪 |
通过cat available_filter_functions
可以查看可被过滤的函数列表(数量很多)
[root@qemu_imx6ul:/tracing]# cat available_filter_functions | wc -l
31103
使用方法:
echo sys_open > set_ftrace_filter
echo sys_close >> set_ftrace_filter
echo '*_open' '*do*' > set_ftrace_filter
2.2.3 读取trace
读取对象 | 用途 |
---|---|
trace | 直接读当前trace缓冲区的跟踪内容,trace满之后会被覆盖 |
trace_pipe | 作为管道被读取,有读清的机制 |
echo function > current_tracer
cat trace_pipe > /tmp/trace.out &
[1] 4153
echo 1 > tracing_on
usleep 1
echo 0 > tracing_on
2.2.4 ftrace_enabled
ftrace_enabled默认是使能的,不过需要时可以通过如下方式开关它
sysctl kernel.ftrace_enabled=0sysctl kernel.ftrace_enabled=1orecho 0 > /proc/sys/kernel/ftrace_enabledecho 1 > /proc/sys/kernel/ftrace_enabled
2.3 使用function_graph查看do_sys_open的执行过程
#!/bin/bashdebugfs=`sed -ne 's/^debugfs \(.*\) debugfs.*/\1/p' /proc/mounts`
echo nop > $debugfs/tracing/current_tracer
echo 0 > $debugfs/tracing/tracing_onecho $$ > $debugfs/tracing/set_ftrace_pid
echo do_sys_open > $debugfs/tracing/set_graph_function
echo function_graph > $debugfs/tracing/current_tracer
echo 1 > $debugfs/tracing/tracing_onexec "$@"
[root@qemu_imx6ul:~/myfb-test]# cat /tracing/trace | head -40
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |0) | do_sys_open() {0) | getname() {0) | getname_flags() {0) ! 979.000 us | kmem_cache_alloc();0) ==========> |0) | gic_handle_irq() {0) | __handle_domain_irq() {0) | irq_enter() {0) + 25.334 us | rcu_irq_enter();0) + 20.333 us | preempt_count_add();0) # 1192.333 us | }0) + 31.334 us | irq_find_mapping();0) | generic_handle_irq() {0) | handle_fasteoi_irq() {0) | _raw_spin_lock() {
如果命令执行时间很短,可以使用如下方式:
sh -c "echo $$ > set_ftrace_pid; echo 1 > tracing_on; kill xxx; echo 0 > tracing_on"
2.3 使用function查看do_sys_open的执行
#!/bin/bashdebugfs=`sed -ne 's/^debugfs \(.*\) debugfs.*/\1/p' /proc/mounts`
echo nop > $debugfs/tracing/current_tracer
echo 0 > $debugfs/tracing/tracing_on
echo $$ > $debugfs/tracing/set_ftrace_pidecho do_sys_open > $debugfs/tracing/set_ftrace_filter
echo function > $debugfs/tracing/current_tracer
echo 1 > $debugfs/tracing/tracing_onexec "$@"
[root@qemu_imx6ul:~/myfb-test]# cat /tracing/trace | head -40
# tracer: function
#
# entries-in-buffer/entries-written: 17/17 #P:1
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |myfb-test-239 [000] ...1 3462.834035: do_sys_open <-SyS_openmyfb-test-239 [000] ...1 3462.844034: do_sys_open <-SyS_openmyfb-test-239 [000] ...1 3462.851532: do_sys_open <-SyS_openmyfb-test-239 [000] ...1 3462.852319: do_sys_open <-SyS_openmyfb-test-239 [000] ...1 3462.853019: do_sys_open <-SyS_openmyfb-test-239 [000] ...1 3462.853713: do_sys_open <-SyS_open
2.3 使用wakeup
wakeup查看普通进程从被唤醒到真正执行的延时
[root@qemu_imx6ul:/tracing]# echo nop > current_tracer
[root@qemu_imx6ul:/tracing]# echo wakeup > current_tracer
[root@qemu_imx6ul:/tracing]# echo 1 > tracing_on
[root@qemu_imx6ul:/tracing]# cat trace | head -40
# tracer: wakeup
#
# wakeup latency trace v1.1.5 on 4.9.88-g8f6c88def
# --------------------------------------------------------------------
# latency: 9671 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:1)
# -----------------
# | task: kworker/0:0H-5 (uid:0 nice:-20 policy:0 rt_prio:0)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | / mmcqd/1-104 0dn.5 620us#: 104:120:R + [000] 5:100:R kworker/0:0Hmmcqd/1-104 0dn.5 3595us#: 0mmcqd/1-104 0d..3 8687us!: __schedulemmcqd/1-104 0d..3 8984us : 104:120:R ==> [000] 5:100:R kworker/0:0H
2.3 使用wakeup_rt
non-RT进程通常看平均延迟。RT进程的最大延迟非常有意义,反应了调度器的性能
2.4 event
event在ftrace中是一种低性能损耗,获取debug信息的一种信息输出机制。相对于printk,它有如下特点:
- 无需重新编译内核
- 不开启无性能损耗
- 开启不影响流程
event在ftrace中的events目录下:
事件以目录的形式作为主体,目录中的文件作为事件的属性。每个目录中都有一个enable文件,用于使能这个或者这类事件。
[root@qemu_imx6ul:/tracing/events/sched]# cd sched_switch
[root@qemu_imx6ul:/tracing/events/sched/sched_switch]# ls
enable filter format id trigger
[root@qemu_imx6ul:/tracing]# echo 1 > events/sched/sched_wakeup/enable
[root@qemu_imx6ul:/tracing]# echo nop > current_tracer
[root@qemu_imx6ul:/tracing]# cat trace | head -40
# tracer: nop
#
# entries-in-buffer/entries-written: 483/483 #P:1
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |sh-176 [000] dns3 31291.656047: sched_wakeup: comm=rcu_preempt pid=7 prio=120 target_cpu=000sh-176 [000] dns2 31291.661390: sched_wakeup: comm=ksoftirqd/0 pid=3 prio=120 target_cpu=000sh-176 [000] dns2 31291.714298: sched_wakeup: comm=rcu_preempt pid=7 prio=120 target_cpu=000sh-176 [000] dns2 31291.722990: sched_wakeup: comm=ksoftirqd/0 pid=3 prio=120 target_cpu=000<idle>-0 [000] dnh4 31292.612645: sched_wakeup: comm=kworker/u2:0 pid=6 prio=120 target_cpu=000<idle>-0 [000] dns4 31292.619844: sched_wakeup: comm=kworker/0:2 pid=102 prio=120 target_cpu=000<idle>-0 [000] dns3 31292.621198: sched_wakeup: comm=ksoftirqd/0 pid=3 prio=120 target_cpu=000kworker/u2:0-6 [000] dn.3 31292.633752: sched_wakeup: comm=sh pid=176 prio=120 target_cpu=000<idle>-0 [000] dnh3 31293.270182: sched_wakeup: comm=init pid=1 prio=120 target_cpu=000
3. trace-cmd
每次如果都是通过读写文件的方式使用ftrace就太复杂了,这个过程可以通过命令行的形式完成,实现这个功能的软件是:trace-cmd
常用子命令 | 用法 |
---|---|
start | 开始追踪 |
stop | 停止追踪 |
clear | 清空追踪结果 |
show | 查看缓冲区的追踪结果 |
reset | 停止内核追踪并清空缓存 |
report | 从trace.dat读取trace |
record | 记录追踪事件到trace.dat |
list | 列出可用的事件、选项、追踪器等 |
list:
-t
:查看可用的追踪器-e
:查看可追踪的事件-f
:查看可追踪的函数
[root@qemu_imx6ul:~]# tmd list -f | grep do_sys_open
do_sys_open
[root@qemu_imx6ul:~]# tmd list -f | wc -l
31103
[root@qemu_imx6ul:~]# cat /tracing/available_filter_functions | wc -l
31103
record:
-P {pid}
:指定进程-p {avalilable_tracers}
:指定追踪器-l {function}
:指定要追踪的函数-g {function}
:指定要追踪的函数(For graph function)--max-graph-depth 5
:指定追踪的函数调用深度-c -F
:追踪子进程
例如:
[root@qemu_imx6ul:~]# trace-cmd start -p function
[root@qemu_imx6ul:~]# trace-cmd record -p function_graph -g do_sys_open -O funcgraph-proc ls
[root@qemu_imx6ul:~]# trace-cmd report | head -40
cpus=1trace-cmd-551 [000] 72595.333330: funcgraph_entry: | do_sys_open() {trace-cmd-551 [000] 72595.493349: funcgraph_entry: | getname() {trace-cmd-551 [000] 72595.493856: funcgraph_entry: | gic_handle_irq() {trace-cmd-551 [000] 72595.495327: funcgraph_entry: | __handle_domain_irq() {......