认识 Ftrace 机制

认识 Ftrace 机制

1 说明背景

从做工作的角度，我能体会到的是trace event工具能带来工作效率的提升。从学习的角度，我相信使用ftrace工具能更加方便观测内核

文档作为会议的记录和补充，会议主题是《使用Ftrace研究Linux内核》，主讲人是谢欢

回放链接：阅码场录播

2 基本内容

2.1 Ftrace整体框架

根据官方文档的定义，Ftrace是一个内部跟踪器，旨在帮助系统的开发者和设计者去观测内核的运行。它可以被用于调试或分析发生在用户空间之外的延迟和性能问题。随着发展，目前已经演变成为一个基础的调试框架（支持多个不同类型的trace功能）。直观理解有两层含义：一是提供函数钩子的基础设施，二是基于tracefs文件系统的trace框架。

[外链图片转存失败,源站可能有防盗链机制,建议将图片保存下来直接上传(img-FhsAbBjK-1671863034979)(images/202208210954.png)]

• function tracer：在函数头挂钩子函数
• function graph tracer：可以带时间戳函数执行流打印
• kprobe：一般是挂在函数入口点，用于获取参数
• trace event：函数执行时调用静态的钩子函数
• kretprobe：通常是函数出口点，执行钩子函数

mount -t tracefs nodev /sys/kernel/tracing # 挂载tracefs
ls -l /sys/kernel/tracing # 查看挂载点

2.2 function tracer使用

2.2.1 case01: 过滤"vfs_open"函数

cd /sys/kernel/debug/tracing
echo vfs_open > ./set_ftrace_filter # 过滤要跟踪的函数
echo function > ./current_tracer
cp trace /test.txt && cat /test.txt

# 可配置功能
cat ./set_ftrace_filter
cat ./set_ftrace_pid
cat ./options/func_stack_trace

# tracer: function
#
# entries-in-buffer/entries-written: 61/61   #P:2
#
#                                _-----=> irqs-off
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| /     delay
#           TASK-PID     CPU#  ||||   TIMESTAMP  FUNCTION
#              | |         |   ||||      |         |
         systemd-1       [000] .... 549571.137111: vfs_open <-do_open
         systemd-1       [000] .... 549571.137177: vfs_open <-do_open
      multipathd-496     [001] .... 549572.062027: vfs_open <-do_open
      multipathd-496     [001] .... 549572.062797: vfs_open <-do_open
      multipathd-496     [001] .... 549572.064078: vfs_open <-do_open
 systemd-journal-358     [001] .... 549572.064461: vfs_open <-do_open
 systemd-journal-358     [001] .... 549572.064552: vfs_open <-do_open
 systemd-journal-358     [001] .... 549572.064603: vfs_open <-do_open
 systemd-journal-358     [001] .... 549572.064642: vfs_open <-do_open
 systemd-journal-358     [001] .... 549572.064807: vfs_open <-do_open

2.3 function graph tracer使用

2.3.1 case01: 函数"vfs_open"的执行时间

echo vfs_open > ./set_ftrace_filter
echo function_graph > ./current_tracer
echo 1 > ./options/funcgraph-proc # 打印进程TASK/PID
cp trace /test.txt && cat /test.txt

# tracer: function_graph
#
# CPU  TASK/PID         DURATION                  FUNCTION CALLS
# |     |    |           |   |                     |   |   |   |
 1)  multipa-496   | + 14.596 us   |  vfs_open();
 0)  irqbala-637   |   7.785 us    |  vfs_open();
 0)  irqbala-637   |   3.493 us    |  vfs_open();
 0)  irqbala-637   |   1.775 us    |  vfs_open();
 0)  irqbala-637   |   1.189 us    |  vfs_open();
 0)  irqbala-637   |   1.146 us    |  vfs_open();
 0)  irqbala-637   |   1.261 us    |  vfs_open();
 0)  irqbala-637   |   1.101 us    |  vfs_open();
 0)  irqbala-637   |   1.177 us    |  vfs_open();
 0)  irqbala-637   |   1.056 us    |  vfs_open();
 0)  irqbala-637   |   1.169 us    |  vfs_open();
 0)  irqbala-637   |   1.117 us    |  vfs_open();
 1)  multipa-496   | + 16.365 us   |  vfs_open();
 1)  multipa-496   |   9.509 us    |  vfs_open();
 1)  multipa-496   | + 15.136 us   |  vfs_open();
 ------------------------------------------
 1)  multipa-496   =>  systemd-358  
 ------------------------------------------
.....

2.3.2 case02: 函数"vfs_open"向下执行流

echo > ./set_ftrace_filter # 不使用过滤!!!
echo vfs_open > ./set_graph_function #  使用函数图表
echo function_graph > ./current_tracer
echo 1 > ./options/funcgraph-proc # 打印进程TASK/PID
echo 1 > ./options/funcgraph-tail # 尾部注释(方便观察)
cp trace /test.txt && cat /test.txt

# tracer: function_graph
#
# CPU  TASK/PID         DURATION                  FUNCTION CALLS
# |     |    |           |   |                     |   |   |   |
 0)  systemd-358   | + 38.350 us   |            } /* single_release */
 0)  systemd-358   |   0.504 us    |            module_put();
 0)  systemd-358   |   0.500 us    |            put_pid();
 0)  systemd-358   |               |            dput() {
 0)  systemd-358   |               |              __cond_resched() {
 0)  systemd-358   |   0.478 us    |                rcu_all_qs();
 0)  systemd-358   |   1.433 us    |              } /* __cond_resched */
 0)  systemd-358   |   0.480 us    |              _raw_spin_lock();
 0)  systemd-358   |   0.459 us    |              rcu_read_unlock_strict();
 0)  systemd-358   |   0.553 us    |              pid_delete_dentry();
 0)  systemd-358   |   5.900 us    |            } /* dput */
 0)  systemd-358   |               |            mntput() {
 0)  systemd-358   |               |              mntput_no_expire() {
 0)  systemd-358   |   0.493 us    |                rcu_read_unlock_strict();
 0)  systemd-358   |   1.592 us    |              } /* mntput_no_expire */
 0)  systemd-358   |   2.607 us    |            } /* mntput */
 0)  systemd-358   |               |            security_file_free() {
 0)  systemd-358   |   0.607 us    |              apparmor_file_free_security();
 0)  systemd-358   |   1.038 us    |              kmem_cache_free();
 0)  systemd-358   |   3.355 us    |            } /* security_file_free */
....

2.4 kprobe event

2.4.1 case01: 查看"vfs_open"当前打开文件名

# 理论计算：
# $arg1, 第一个参数
# +0x8($arg1), 地址偏移+0x8
# +0x70(+0x8($arg1)), 相当与C语言的 *(*($arg1 + 0x8) + 0x70)
echo 'p vfs_open name=+0x70(+0x8($arg1)):string namep=+0(+0x60(+0x8($arg1))):string' > ./kprobe_events
echo 1 > ./events/kprobes/p_vfs_open_0/enable
echo > trace && cat /test.txt
cp trace /test.txt && cat /test.txt

cat-1317 [003] ..... 14640.951607: p_vfs_open_0: (vfs_open+0x0/0x30) name="cat" namep="cat"
cat-1317 [003] ..... 14640.953115: p_vfs_open_0: (vfs_open+0x0/0x30) name="ld-2.31.so" namep="ld-2.31.so"
cat-1317 [003] ..... 14640.954505: p_vfs_open_0: (vfs_open+0x0/0x30) name="ld.so.cache" namep="ld.so.cache"
cat-1317 [003] ..... 14640.954947: p_vfs_open_0: (vfs_open+0x0/0x30) name="libc-2.31.so" namep="libc-2.31.so"
cat-1317 [003] ..... 14640.955536: p_vfs_open_0: (vfs_open+0x0/0x30) name="locale-archive" namep="locale-archive"
cat-1317 [003] ..... 14640.955655: p_vfs_open_0: (vfs_open+0x0/0x30) name="test.txt" namep="test.txt"
cat-1318 [003] ..... 14643.884073: p_vfs_open_0: (vfs_open+0x0/0x30) name="cat" namep="cat"

2.4.2 case02: 捕获"vfs_open"查看指定文件的信息的事件

# 功能: 利用filter和trigger文件
root@debian:/sys/kernel/debug/tracing# ls ./events/kprobes/p_vfs_open_0/
enable filter format hist id inject trigger

# 格式: kprobe event
root@debian:/sys/kernel/debug/tracing# cat ./events/kprobes/p_vfs_open_0/format

echo 'p vfs_open name=+0x70(+0x8($arg1)):string namep=+0(+0x60(+0x8($arg1))):string' > ./kprobe_events
echo 1 > ./events/kprobes/p_vfs_open_0/enable # 过滤包含"test"字段的文件的事件
echo 'name ~ "*test*"' > ./events/kprobes/p_vfs_open_0/filter
echo > trace && cat /test.txt
echo 'stacktrace if name ~ "*test*"' > ./events/kprobes/p_vfs_open_0/trigger  # 包含"test"字段的文件的事件会触发"stacktrace"堆栈打印

2.5 trace event

cat /sys/kernel/debug/tracing/available_events # 查看当前支持的跟踪事件列表

2.5.1 case01: 打开"gsgpu"驱动跟踪节点

echo 1 > /sys/kernel/debug/tracing/events/gsgpu/enable && \
echo 0 > /sys/kernel/debug/tracing/trace && \
/root/run_test.sh ; cp /sys/kernel/debug/tracing/trace /test.txt && \
echo 0 > /sys/kernel/debug/tracing/events/gsgpu/enable
cat /test.txt

2.5.2 case02: 通过filter过滤事件

echo 0 > /sys/kernel/debug/tracing/events/gsgpu/enable && \
echo 1 > /sys/kernel/debug/tracing/events/gsgpu/gsgpu_bo_move/enable && \
echo 0 > /sys/kernel/debug/tracing/trace && \
echo "bo_size >= 50000" > /sys/kernel/debug/tracing/events/gsgpu/gsgpu_bo_move/filter && \
/root/run_test.sh ; cp /sys/kernel/debug/tracing/trace /test.txt && \
echo 0 > /sys/kernel/debug/tracing/events/gsgpu/gsgpu_bo_move/filter
cat /test.txt

2.5.3 case03: 通过trigger查看栈回溯

echo 0 > /sys/kernel/debug/tracing/events/gsgpu/enable && \
echo 1 > /sys/kernel/debug/tracing/events/gsgpu/gsgpu_bo_move/enable && \
echo 0 > /sys/kernel/debug/tracing/trace && \
echo 'stacktrace' > /sys/kernel/debug/tracing/events/gsgpu/gsgpu_bo_move/trigger && \
/root/run_test.sh ; cp /sys/kernel/debug/tracing/trace /test.txt && \
echo '!stacktrace' > /sys/kernel/debug/tracing/events/gsgpu/gsgpu_bo_move/trigger && \
cat /test.txt

2.6 objtrace

2.6.1 case01：观察对象数据在函数中流动

cd /sys/kernel/debug/tracing/
echo 'p bio_add_page arg1=$arg1 arg2=$arg2' > ./kprobe_events
echo 'objtrace:add:arg1,0x28:u32:5 if comm == "cat"' > ./events/kprobes/p_bio_add_page_0/trigger
# du -sh /test.txt // 12K
cat /test.txt > /dev/null

源码位置：https://github.com/x-lugoo/linux/tree/objtrace-v9

3 一些观点

1、ftrace很多功能在国内使用不充分，比如tracer网上资料少，ftrace功能很强大，可挖掘的潜力大。像是大家对shell的使用，如果大家能积累更多的案例，这样能更好的普及和使用。
2、ftrace和正常的日志环形缓冲区不同，如果大量日志向同一个缓冲区输入，一会导致信息混乱，二是容易覆盖有效数据。使用ftrace的过滤等功能，可以更好的解决此类问题（适用更加复杂的业务场景）。补充ftrace其他功能：自动保存结果输出到文件；生成直方图；触发其他事件；等等。
3、ftrace对内核的通用性还是比较强的，相比ebpf来说ftrace对于低版本的内核更加友好。
4、ftrace的用户群体大，但是名声没有ebpf的功能大。
5、ftrace的tracer在linux中使用shell脚本来实现，如果想要观察和定位，使用这种手段方便；如果转发类或者做业务相关的，推荐使用ebpf比较多。可以根据各自优势应用到不同的场景，也可以两者结合使用。

4 一些问答

0、perf/ftrace/ebpf关系
基于kprobe的ebpf通过ID找到字节码程序，当perf使用相同功能的时候，可以依据ID来找到这个字节码程序。ebpf程序本质上是基于ftrace，在挂载点通过ftrace框架来调用字节码程序

# 使用bpftrace工具将ebpf程序挂载到"kprobe:do_nanosleep"
bpftrace -e 'kprobe:do_nanosleep { printf("PID %d sleeping...\n", pid); }'

1、kprobe和function trace的钩子有什么区别？
基本相同，区别在于kprobe钩子函数会将寄存器信息放入堆栈，可以用于取出函数参数，而function trace没有这个功能。

2、什么是no trace函数？
如果函数本身参与ftrace功能，不能用于trace(避免递归) 这样的函数一般都是no trace。

3、uprobe是用什么实现的？
uprobe在用户层，基于断点指令来实现。

4、ftrace对性能影响多大?
看如何使用？如果对所有函数使用function tracer，如果只使用一个性能事件性能消耗很小。

5、如果从学习内核的角度来讲，怎样把ftrace作为一个辅助的工具来上手内核？
在调试内核的时候，通常使用printk/printf来使用，使用ftrace的前提要戒掉这个习惯，然后使用ftrace工具来调试。

6、对于可靠性和安全性比较高的领域，对于ftrace是不是要慎用一些？
是的，对原理理解要求比较高一些。对原理比较清楚的话，能很好的缩小ftrace的使用范围，来进一步降低对系统的性能消耗。

7、如何评估这些调试工具的开销?
正确对待ftrace是一个辅助工具，前提还是要对代码比较熟悉，ftrace辅助对代码的观察。

8、ftrace这样的工具好处？
使用在不破坏内核的情况下，提供一个对内核可观测手段；提供基础的tracer功能，灵活运用好tracer功能对分析问题帮助；perf工具将各种类型的挂载点收入囊中，一统江湖。

9、linux内核中有这么多钩子？都有什么局限，如何选择
看具体想使用哪些功能，比如查看函数怎么执行，选择function tracer；比如查看某一个函数的参数，使用kprobe挂载点对应的钩子函数不一样的。

10、ftrace的tracer在linux中使用shell脚本来实现，如果想要观察和定位，使用这种手段方便；如果转发类或者做业务相关的，推荐使用ebpf比较多
各有优势，应用到不同的场景，也可以两者结合使用。

11、在嵌入式场景，内存资源比较紧张的时候适用么？
内存消耗比较小。也可以设置，buffer可以调小一些。

12、ftrace在性能消耗比ebpf更小么？
也不一定，看使用那部分功能。

13、有没有推荐的日志化性能分析的图形工具？
tracecmd和KernelShark。