2.1 ftrace 的原理与使用

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12

# 1. 重新挂在 debugfs  
mount -t debugfs none /debugs

# 2. debugfs/tracing 目录
ll /debugs/tracing

# 3. 创建新的 ftrace trace 实例
mkdir /debugs/tracing/instance/python

# ftrace 会创建新的内存缓冲区并生成 ftrace 相关文件
ll tracing/instances/python/

 1
 2
 3
 4
 5
 6
 7
 8
 9
10

ls
available_events            free_buffer               printk_formats       snapshot            trace_stat
available_filter_functions  function_profile_enabled  README               stack_max_size    tracing_cpumask
available_tracers           hwlat_detector            saved_cmdlines       stack_trace   tracing_max_latency
buffer_size_kb              instances                 saved_cmdlines_size  stack_trace_filter  tracing_on
buffer_total_size_kb        kprobe_events             set_event            trace              tracing_thresh
current_tracer              kprobe_profile            set_ftrace_filter    trace_clock        uprobe_events
dyn_ftrace_total_info       max_graph_depth           set_ftrace_notrace   trace_marker       uprobe_profile
enabled_functions           options                   set_ftrace_pid       trace_options
events                      per_cpu                   set_graph_function   trace_pipe

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21

# 1. 假设我们要跟踪一个 Python 文件执行中的进程调度
> vim run.py
with open("./content.csv") as bf:
    print(bf.readlines())

# 2. 将 ftrace 的选项写入脚本中
> vim ftrace.sh
py=/home/tao/debugs/tracing/
mkdir -pv $py
echo nop > $py/current_tracer
echo 0 > $py/tracing_on
echo $$ > $py/set_ftrace_pid
echo "sched:*" > $py/set_event
#replace test_proc_show by your function name
#echo test_proc_show > $py/set_graph_function
echo 1 > $py/tracing_on
exec "$@"

# 3.启动跟踪并查看结果
> bash ftrace.sh python ftrace.py && echo 0 > /home/tao/debugs/tracing/tracing_on
> vim /home/tao/debugs/tracing/trace

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43

# 这次使用系统默认挂载的 debugfs
$ cd /sys/kernel/debug/tracing/

# 1. 设置要显示调用栈的函数
$ echo do_sys_open > set_graph_function 

# 2. 配置跟踪选项，开启函数调用跟踪，并跟踪调用进程
$ echo function_graph > current_tracer
$ echo funcgraph-proc > trace_options

# 3. 开启追踪
$ echo 1 > tracing_on

# 4. 执行一个 ls 命令后，再关闭跟踪：
$ ls
$ echo 0 > tracing_on

# 5.查看追踪结果

$ cat trace
# tracer: function_graph
#
# CPU  TASK/PID         DURATION                  FUNCTION CALLS
# |     |    |           |   |                     |   |   |   |
 0)    ls-12276    |               |  do_sys_open() {
 0)    ls-12276    |               |    getname() {
 0)    ls-12276    |               |      getname_flags() {
 0)    ls-12276    |               |        kmem_cache_alloc() {
 0)    ls-12276    |               |          _cond_resched() {
 0)    ls-12276    |   0.049 us    |            rcu_all_qs();
 0)    ls-12276    |   0.791 us    |          }
 0)    ls-12276    |   0.041 us    |          should_failslab();
 0)    ls-12276    |   0.040 us    |          prefetch_freepointer();
 0)    ls-12276    |   0.039 us    |          memcg_kmem_put_cache();
 0)    ls-12276    |   2.895 us    |        }
 0)    ls-12276    |               |        __check_object_size() {
 0)    ls-12276    |   0.067 us    |          __virt_addr_valid();
 0)    ls-12276    |   0.044 us    |          __check_heap_object();
 0)    ls-12276    |   0.039 us    |          check_stack_object();
 0)    ls-12276    |   1.570 us    |        }
 0)    ls-12276    |   5.790 us    |      }
 0)    ls-12276    |   6.325 us    |    }
...

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27

# 1. 安装
$ yum install trace-cmd
# 2. 启动追踪
$ trace-cmd record -p function_graph -g do_sys_open -O funcgraph-proc ls

# 3. 查看追踪结果
$ trace-cmd report
...
              ls-12418 [000] 85558.075341: funcgraph_entry:                   |  do_sys_open() {
              ls-12418 [000] 85558.075363: funcgraph_entry:                   |    getname() {
              ls-12418 [000] 85558.075364: funcgraph_entry:                   |      getname_flags() {
              ls-12418 [000] 85558.075364: funcgraph_entry:                   |        kmem_cache_alloc() {
              ls-12418 [000] 85558.075365: funcgraph_entry:                   |          _cond_resched() {
              ls-12418 [000] 85558.075365: funcgraph_entry:        0.074 us   |            rcu_all_qs();
              ls-12418 [000] 85558.075366: funcgraph_exit:         1.143 us   |          }
              ls-12418 [000] 85558.075366: funcgraph_entry:        0.064 us   |          should_failslab();
              ls-12418 [000] 85558.075367: funcgraph_entry:        0.075 us   |          prefetch_freepointer();
              ls-12418 [000] 85558.075368: funcgraph_entry:        0.085 us   |          memcg_kmem_put_cache();
              ls-12418 [000] 85558.075369: funcgraph_exit:         4.447 us   |        }
              ls-12418 [000] 85558.075369: funcgraph_entry:                   |        __check_object_size() {
              ls-12418 [000] 85558.075370: funcgraph_entry:        0.132 us   |          __virt_addr_valid();
              ls-12418 [000] 85558.075370: funcgraph_entry:        0.093 us   |          __check_heap_object();
              ls-12418 [000] 85558.075371: funcgraph_entry:        0.059 us   |          check_stack_object();
              ls-12418 [000] 85558.075372: funcgraph_exit:         2.323 us   |        }
              ls-12418 [000] 85558.075372: funcgraph_exit:         8.411 us   |      }
              ls-12418 [000] 85558.075373: funcgraph_exit:         9.195 us   |    }
...