ftrace学习笔记

目录

1. 前言

2. ARM64栈帧结构

3. 编译阶段

3.1 未开启ftrace时的blk_update_request

3.2 开启ftrace时的blk_update_request

4. 链接阶段

4.1 未开启ftrace时的blk_update_request

4.2 开启ftrace时的blk_update_request

5. 运行阶段

5.1 ftrace_init执行后的blk_update_request

5.2 设定trace函数blk_update_request

6. 钩子函数的替换过程

7.总结

参考文档

1. 前言

本文主要是根据阅码场 《Linux内核tracers的实现原理与应用》视频课程,我自己在aarch64上的实践。通过观察钩子函数的创建过程以及替换过程，理解trace的原理。本文同样以blk_update_request函数为例进行说明。

kernel版本：5.10平台：arm64

2.ARM64栈帧结构

在开始介绍arm64架构下的ftrace之前，先来简要说明一下arm64栈帧的相关知识。arm64有31个通用寄存器r0-r30，其中r0-r7用于Parameter/result 寄存器; r29为Frame Pointer寄存器，r30为Link寄存器，指向上级函数的返回地址；SP为栈指针。将以如下代码为例，说明它的栈帧结构：

/*

 * ARCH: armv8

 * GCC版本：aarch64-linux-gnu-gcc (Linaro GCC 5.4-2017.01) 5.4.1 20161213

 */

intfun2(int c,int d)

{

 return0;

}

intfun1(int a,int b)

{

 int c = 1;

 int d = 2;

fun2(c, d);

 return0;

}

intmain(int argc,char **argv)

{

 int a = 0;

 int b = 1;

 fun1(a,b);

}

aarch64-linux-gnu-objdump -d a.out 反汇编后的结果为：

0000000000400530 :

 /* 更新sp到fun2的栈底 */

 400530: d10043ff sub sp, sp, #0x10

 400534: b9000fe0 str w0, [sp,#12]

 400538: b9000be1 str w1, [sp,#8]

 40053c: 52800000 mov w0, #0x0 // #0

 400540: 910043ff add sp, sp, #0x10

 400544: d65f03c0 ret

0000000000400548 :

 /* 分配48字节栈空间，先更新sp=sp-48, 再入栈x29, x30, 此时sp指向栈顶 */

 400548: a9bd7bfd stp x29, x30, [sp,#-48]!

 /* x29、sp指向栈顶*/

 40054c: 910003fd mov x29, sp

 /* 入栈fun1参数0 */

 400550: b9001fa0 str w0, [x29,#28]

 /* 入栈fun1参数1 */

 400554: b9001ba1 str w1, [x29,#24]

 /* 入栈fun1局部变量c */

 400558: 52800020 mov w0, #0x1 // #1

 40055c: b9002fa0 str w0, [x29,#44]

 /* 入栈fun1局部变量d */

 400560: 52800040 mov w0, #0x2 // #2

 400564: b9002ba0 str w0, [x29,#40]

 400568: b9402ba1 ldr w1, [x29,#40]

 40056c: b9402fa0 ldr w0, [x29,#44]

 /* 跳转到fun2 */

 400570: 97fffff0 bl 400530 

 400574: 52800000 mov w0, #0x0 // #0

 400578: a8c37bfd ldp x29, x30, [sp],#48

 40057c: d65f03c0 ret

0000000000400580 
:

 /* 分配48字节栈空间，先更新sp=sp-48, 再入栈x29, x30, 此时sp指向栈顶*/

 400580: a9bd7bfd stp x29, x30, [sp,#-48]!

 /* x29、sp指向栈顶*/

 400584: 910003fd mov x29, sp

 /* 入栈main参数0 */

 400588: b9001fa0 str w0, [x29,#28]

 /* 入栈main参数1 */

 40058c: f9000ba1 str x1, [x29,#16]

 /* 入栈变量a */

 400590: b9002fbf str wzr, [x29,#44]

 400594: 52800020 mov w0, #0x1 // #1

 /* 入栈变量b */

 400598: b9002ba0 str w0, [x29,#40]

 40059c: b9402ba1 ldr w1, [x29,#40]

 4005a0: b9402fa0 ldr w0, [x29,#44]

 /* 跳转到fun1 */

 4005a4: 97ffffe9 bl 400548 

 4005a8: 52800000 mov w0, #0x0 // #0

 4005ac: a8c37bfd ldp x29, x30, [sp],#48

 4005b0: d65f03c0 ret

 4005b4: 00000000 .inst 0x00000000 ; undefined

对应栈帧结构为：

总结一下：通过对aarch64代码反汇编的分析，可以得出：

1.每个函数在入口处首先会分配栈空间，且一次分配，确定栈顶，之后sp将不再变化；

2.每个函数的栈顶部存放的是caller的栈顶指针，即fun1的栈顶存放的是main栈顶指针;

3.对于最后一级callee函数，由于x29保存了上一级caller的栈顶sp指针，因此不在需要入栈保存，如示例中fun2执行时，此时x29指向fun1的栈顶sp

下面我们将根据是否开启ftrace配置，并区分编译阶段、链接阶段和运行阶段，分别查看钩子函数的替换及构建情况。

3. 编译阶段

3.1 未开启ftrace时的blk_update_request

00000000000012ac :

 12ac: d10183ff sub sp, sp, #0x60

 12b0: a9017bfd stp x29, x30, [sp,#16]

 12b4: 910043fd add x29, sp, #0x10

 12b8: a90253f3 stp x19, x20, [sp,#32]

 12bc: a9035bf5 stp x21, x22, [sp,#48]

 12c0: a90463f7 stp x23, x24, [sp,#64]

 12c4: f9002bf9 str x25, [sp,#80]

 12c8: aa0003f6 mov x22, x0

 12cc: 53001c38 uxtb w24, w1

 12d0: 2a0203f5 mov w21, w2

 12d4: 2a1803e0 mov w0, w24

 12d8: 94000000 bl 12c 

 ...

在未使能内核配置项CONFIG_FTRACE时，反汇编blk_update_request函数可以看出，不包含钩子函数。

3.2 开启ftrace时的blk_update_request

0000000000003f10 :

 3f10: d10183ff sub sp, sp, #0x60

 3f14: a9017bfd stp x29, x30, [sp,#16]

 3f18: 910043fd add x29, sp, #0x10

 3f1c: a90253f3 stp x19, x20, [sp,#32]

 3f20: a9035bf5 stp x21, x22, [sp,#48]

 3f24: a90463f7 stp x23, x24, [sp,#64]

 3f28: f9002bf9 str x25, [sp,#80]

 3f2c: aa0003f6 mov x22, x0

 3f30: 53001c38 uxtb w24, w1

 3f34: 2a0203f5 mov w21, w2

 3f38: aa1e03e0 mov x0, x30

 3f3c: 94000000 bl 0 <_mcount>

 ...

在使能内核配置项CONFIG_FTRACE时，可以看到blk_update_request函数增加了如下部分：

 3f3c: 94000000 bl 0 <_mcount>

那么 bl 0 <_mcount> 是由谁在何时插入的呢? 答案是编译器在编译时插入，编译选项-pg -mrecord-mcoun会在编译时在每个可trace函数插入bl 0 <_mcount>，并将所有可trace的函数放到一个__mcount_loc的section中。

通过查看blk-core.o的可重定位段，可以看到有大量的地址需要定位到_mcount函数，其中3f3c地址正是位于blk_update_request，它会在链接阶段被重定位到_mcount函数的地址。

ubuntu@VM-0-9-ubuntu:~/qemu/kernel/linux/block$ aarch64-linux-gnu-objdump -r blk-core.o | grep _mcount

0000000000000014 R_AARCH64_CALL26 _mcount

000000000000005c R_AARCH64_CALL26 _mcount

00000000000000ac R_AARCH64_CALL26 _mcount

0000000000000108 R_AARCH64_CALL26 _mcount

0000000000000164 R_AARCH64_CALL26 _mcount

00000000000001bc R_AARCH64_CALL26 _mcount

0000000000000214 R_AARCH64_CALL26 _mcount

...

0000000000003f3c R_AARCH64_CALL26 _mcount

...

我们还可以看到，blk-core.o有一个.rela__mcount_loc的可重定位段，里面存放了所有需要可trace函数中需要重定位到函数_mcount的地址。

ubuntu@VM-0-9-ubuntu:~/qemu/kernel/linux/block$ aarch64-linux-gnu-objdump -r blk-core.o

...

RELOCATION RECORDS FOR [__mcount_loc]:

OFFSET TYPE VALUE

0000000000000000 R_AARCH64_ABS64 .text+0x0000000000000014

0000000000000008 R_AARCH64_ABS64 .text+0x000000000000005c

0000000000000010 R_AARCH64_ABS64 .text+0x00000000000000ac

0000000000000018 R_AARCH64_ABS64 .text+0x0000000000000108

...

00000000000001b8 R_AARCH64_ABS64 .text+0x0000000000003f3c

...

4. 链接阶段

4.1 未开启ftrace时的blk_update_request

未使能内核配置项CONFIG_FTRACE时，链接阶段与编译阶段一样，反汇编blk_update_request函数可以看出，不包含钩子函数

4.2 开启ftrace时的blk_update_request

ffff8000104e43c8 :

ffff8000104e43c8: d10183ff sub sp, sp, #0x60

ffff8000104e43cc: a9017bfd stp x29, x30, [sp,#16]

ffff8000104e43d0: 910043fd add x29, sp, #0x10

ffff8000104e43d4: a90253f3 stp x19, x20, [sp,#32]

ffff8000104e43d8: a9035bf5 stp x21, x22, [sp,#48]

ffff8000104e43dc: a90463f7 stp x23, x24, [sp,#64]

ffff8000104e43e0: f9002bf9 str x25, [sp,#80]

ffff8000104e43e4: aa0003f6 mov x22, x0

ffff8000104e43e8: 53001c38 uxtb w24, w1

ffff8000104e43ec: 2a0203f5 mov w21, w2

ffff8000104e43f0: aa1e03e0 mov x0, x30

ffff8000104e43f4: 97ed1fde bl ffff80001002c36c <_mcount>

ffff8000104e43f8: 2a1803e0 mov w0, w24

ffff8000104e43fc: 97fff432 bl ffff8000104e14c4 

...

在链接阶段，使能内核配置项CONFIG_FTRACE时，可以看到编译阶段的如下代码

 3f3c: 94000000 bl 0 <_mcount>

在链接阶段已经被替换为：

ffff8000104e43f4: 97ed1fde bl ffff80001002c36c <_mcount>

其中_mcount函数反汇编为：

ffff80001002c36c <_mcount>:

ffff80001002c36c: d65f03c0 ret

5. 运行阶段

5.1ftrace_init执行后的blk_update_request

(gdb) x/20i blk_update_request

 0xffff8000104e43c8 : sub sp, sp, #0x60

 0xffff8000104e43cc : stp x29, x30, [sp,#16]

 0xffff8000104e43d0 : add x29, sp, #0x10

 0xffff8000104e43d4 : stp x19, x20, [sp,#32]

 0xffff8000104e43d8 : stp x21, x22, [sp,#48]

 0xffff8000104e43dc : stp x23, x24, [sp,#64]

 0xffff8000104e43e0 : str x25, [sp,#80]

 0xffff8000104e43e4 : mov x22, x0

 0xffff8000104e43e8 : uxtb w24, w1

 0xffff8000104e43ec : mov w21, w2

 0xffff8000104e43f0 : mov x0, x30

 0xffff8000104e43f4 : nop

 0xffff8000104e43f8 : mov w0, w24

 0xffff8000104e43fc : bl 0xffff8000104e14c4 

内核在start_kernel执行时，会调用ftrace_init，它会将所有可trace函数中的_mcount进行替换，如上可以看出链接阶段的 bl ffff80001002c36c <_mcount> 已经被替换为nop指令

5.2 设定trace函数blk_update_request

执行如下命令来trace函数blk_update_request

ubuntu@VM-0-9-ubuntu:~$echo blk_update_request > /sys/kernel/debug/tracing/set_ftrace_filter

ubuntu@VM-0-9-ubuntu:~$echo function > /sys/kernel/debug/tracing/current_tracer

我们再来查看blk_update_request反汇编代码

(gdb) x/20i blk_update_request

 0xffff8000104e43c8 : sub sp, sp, #0x60

 0xffff8000104e43cc : stp x29, x30, [sp,#16]

 0xffff8000104e43d0 : add x29, sp, #0x10

 0xffff8000104e43d4 : stp x19, x20, [sp,#32]

 0xffff8000104e43d8 : stp x21, x22, [sp,#48]

 0xffff8000104e43dc : stp x23, x24, [sp,#64]

 0xffff8000104e43e0 : str x25, [sp,#80]

 0xffff8000104e43e4 : mov x22, x0

 0xffff8000104e43e8 : uxtb w24, w1

 0xffff8000104e43ec : mov w21, w2

 0xffff8000104e43f0 : mov x0, x30

 0xffff8000104e43f4 : bl 0xffff80001002c370 

 0xffff8000104e43f8 : mov w0, w24

 0xffff8000104e43fc : bl 0xffff8000104e14c4 

可以看到之前在blk_update_request的nop指令被替换成
bl 0xffff80001002c370

继续反汇编ftrace_caller得到如下的汇编代码：

(gdb) disassemble ftrace_caller

Dump of assembler code for function ftrace_caller:

 0xffff80001002c374 <+0>: stp x29, x30, [sp,#-16]!

 0xffff80001002c378 <+4>: mov x29, sp

 // x30是blk_update_request的lr，-4是当前执行函数的入口地址，也就是ftrace_caller的ip

 // 它将作为参数0传递给ftrace_ops_no_ops

 0xffff80001002c37c <+8>: sub x0, x30, #0x4

 // 参考前面arm64栈帧结构，x29指向上一级函数blk_update_request栈顶

 //[x29]指向blk_mq_end_request函数的栈顶

 //[[x29]+8]为blk_mq_end_request的ip(实际是ip的下条指令)

 0xffff80001002c380 <+12>: ldr x1, [x29]

 0xffff80001002c384 <+16>: ldr x1, [x1,#8]

 0xffff80001002c388 <+20>: bl 0xffff800010188ffc 

 0xffff80001002c38c <+24>: nop

 0xffff80001002c390 <+28>: ldp x29, x30, [sp],#16

 0xffff80001002c394 <+32>: ret

End of assembler dump.

可以看到ftrace_caller会调用ftrace_ops_no_ops，我们在ftrace_ops_no_ops源码中看到它会遍历ftrace_ops_list链表，并执行这个链表上的回调函数，这里看下ftrace_ops_list上都链接了哪些func

(gdb) p *ftrace_ops_list

$4 = {

 func = 0xffff8000101a0b1c , //ftrace_ops_list链表唯一func

 next = 0xffff800011c5a438 , //说明ftrace_ops_list链表只有一个func

 flags = 8273,

private = 0xffff800011cf94e8 ,

saved_func = 0xffff8000101a0b1c ,

local_hash = {

 notrace_hash = 0xffff800010cf7118 ,

filter_hash = 0xffff00000720af80,

regex_lock = {

 owner = {

 counter = 0

 },

......

从ftrace_ops_list链表中可以看到只有一个function_trace_call函数组成，因此可以说ftrace_caller最终会调用到function_trace_call。

通过前面的分析，我们一步步找到了blk_update_request的钩子函数function_trace_call，其函数原型如下，其中参数ip指向ftrace_caller，参数parent_ip指向blk_mq_end_request：

staticvoid

function_trace_call(unsignedlong ip, unsignedlong parent_ip,

 struct ftrace_ops *op, struct pt_regs *pt_regs)

下一节我们将追踪钩子函数的构造以及替换过程。

6. 钩子函数的替换过程

前面我们看到blk_update_request的nop指令被替换成bl ftrace_caller，那么此处的ftrace_caller是在哪里定义的呢？我们可以看到arch/arm64/kernel/entry-ftrace.S有如下的定义：

/*

 * void ftrace_caller(unsigned long return_address)

 * @return_address: return address to instrumented function

 *

 * This function is a counterpart of _mcount() in 'static' ftrace, and

 * makes calls to:

 * - tracer function to probe instrumented function's entry,

 * - ftrace_graph_caller to set up an exit hook

 */

SYM_FUNC_START(ftrace_caller)

 mcount_enter

 mcount_get_pc0 x0 // function's pc

 mcount_get_lr x1 // function's lr

SYM_INNER_LABEL(ftrace_call, SYM_L_GLOBAL) // tracer(pc, lr);

 nop // This will be replaced with "bl xxx"

 // where xxx can be any kind of tracer.

#ifdef CONFIG_FUNCTION_GRAPH_TRACER

SYM_INNER_LABEL(ftrace_graph_call, SYM_L_GLOBAL) // ftrace_graph_caller();

 nop // If enabled, this will be replaced

 // "b ftrace_graph_caller"

#endif

 mcount_exit

SYM_FUNC_END(ftrace_caller)

通过 gdb可以看到ftrace_caller的反汇编代码如下：

(gdb) disassemble ftrace_caller

Dump of assembler code for function ftrace_caller:

 0xffff80001002c370 <+0>: stp x29, x30, [sp,#-16]!

 0xffff80001002c374 <+4>: mov x29, sp

 0xffff80001002c378 <+8>: sub x0, x30, #0x4

 0xffff80001002c37c <+12>: ldr x1, [x29]

 0xffff80001002c380 <+16>: ldr x1, [x1,#8]

 0xffff80001002c384 <+20>: nop /*ftrace_call*/

 0xffff80001002c388 <+24>: nop /*ftrace_graph_call,暂不讨论*/

 0xffff80001002c38c <+28>: ldp x29, x30, [sp],#16

 0xffff80001002c390 <+32>: ret

End of assembler dump.

当执行echo blk_update_request >set_ftrace_filter时相当于使能了blk_update_request的钩子替换标志，当执行echo function >current_tracer时会检查这个标志，并执行替换，它会产生如下的调用链：

/sys/kernel/debug/tracing # echo function > current_tracer

[ 45.632002] CPU: 0 PID: 111 Comm: sh Not tainted 5.10.0-dirty #35

[ 45.632457] Hardware name: linux,dummy-virt (DT)

[ 45.632697] Call trace:

[ 45.632981] dump_backtrace+0x0/0x1f8

[ 45.633169] show_stack+0x2c/0x7c

[ 45.634039] ftrace_modify_all_code+0x38/0x118

[ 45.634269] arch_ftrace_update_code+0x10/0x18

[ 45.634495] ftrace_run_update_code+0x2c/0x48

[ 45.634727] ftrace_startup_enable+0x40/0x4c

[ 45.634943] ftrace_startup+0xec/0x11c

[ 45.635137] register_ftrace_function+0x68/0x84

[ 45.635369] function_trace_init+0xa0/0xc4

[ 45.635574] tracer_init+0x28/0x34

[ 45.635768] tracing_set_tracer+0x11c/0x17c

[ 45.635982] tracing_set_trace_write+0x124/0x170

[ 45.636224] vfs_write+0x16c/0x368

[ 45.636409] ksys_write+0x74/0x10c

[ 45.636594] __arm64_sys_write+0x28/0x34

[ 45.636923] el0_svc_common+0xf0/0x174

[ 45.637138] do_el0_svc+0x84/0x90

[ 45.637330] el0_svc+0x1c/0x28

[ 45.637510] el0_sync_handler+0x3c/0xac

[ 45.637721] el0_sync+0x140/0x180

进一步查看ftrace_modify_all_code的代码，我们可以看到如下的调用流程：

ftrace_modify_all_code(command)

 --ftrace_update_ftrace_func(ftrace_ops_list_func)

 |--pc = (unsignedlong)&ftrace_call

 | //此处ftrace_ops_list_func为ftrace_ops_no_ops，

 | //因此会返回bl ftrace_ops_no_ops给new*/

 |--new = aarch64_insn_gen_branch_imm(pc, (unsignedlong)ftrace_ops_list_func,

 | AARCH64_INSN_BRANCH_LINK);

 --ftrace_modify_code(pc, 0, new, false)

如上，ftrace_modify_code通过修改text段，将指令ftrace_call替换为bl ftrace_ops_no_ops，此处是第一次替换；

ftrace_modify_all_code(command)

 --ftrace_replace_code(mod_flags | FTRACE_MODIFY_ENABLE_FL);

 --do_for_each_ftrace_rec(pg, rec) {

 __ftrace_replace_code(rec, enable);

 } while_for_each_ftrace_rec();

如上，会遍历每一个可trace的函数，对于使能了替换标记的函数，将其nop替换为bl ftrace_caller，此处是第二次替换，ftrace_caller也就是我们所认为的钩子函数。

7.总结

到此我们已经分析完了ftrace的各个阶段的行为，以及钩子函数的替换过程，基本上包含如下过程：

1.编译阶段。通过编译选项 -pg -mrecord-mcount 在每个支持ftrace的函数中插入bl 0 <_mcount>指令

2.链接阶段。会根据重定位段将bl 0 <_mcount>指令地址重定位为_mcount函数地址。

3.运行阶段 （1）ftrace_init：会将可trace函数中的bl _mcount替换为nop指令；（2）执行echo blk_update_request >set_ftrace_filter：会使能blk_update_request的钩子函数替换标记（nop替换为ftrace_caller）; （3）执行echofunction > current_tracer：触发两步替换：第一步，ftrace_caller中ftrace_call被替换为ftrace_ops_no_ops；第二步，blk_update_request中的nop被替换为ftrace_caller。ftrace_caller最终会调用到function_trace_call，它会记录函数调用堆栈信息，并将结果写入 ring buffer，用户可以通过/sys/kernel/debug/tracing/trace文件读取该 ring buffer 中的内容。

最后，给出一个通过ftrace跟踪dd写入操作的例子，脚本为ftrace.sh

#!/bin/bash

debugfs=/sys/kernel/debug

echo nop > $debugfs/tracing/current_tracer

echo 0 > $debugfs/tracing/tracing_on

echo $$ > $debugfs/tracing/set_ftrace_pid

echo function > $debugfs/tracing/current_tracer

#replace test_proc_show by your function name

echo ksys_write > $debugfs/tracing/set_ftrace_filter

echo 1 > $debugfs/tracing/tracing_on

exec "$@"

ubuntu@VM-0-9-ubuntu:$ ./ftrace.sh dd if=/dev/zero of=test bs=512 count=1048576

执行结果：

root@VM-0-9-ubuntu:# cat /sys//kernel/debug/tracing/trace

# tracer: function

#

# entries-in-buffer/entries-written: 102454/1048579 #P:2

#

# _-----=> irqs-off

# / _----=> need-resched

# | / _---=> hardirq/softirq

# || / _--=> preempt-depth

# ||| / delay

# TASK-PID CPU# |||| TIMESTAMP FUNCTION

# | | | |||| | |

 dd-32307 [000] .... 1380661.568624: vfs_write <-SyS_write

 dd-32307 [000] .... 1380661.568626: vfs_write <-SyS_write

 dd-32307 [000] .... 1380661.568630: vfs_write <-SyS_write

 dd-32307 [000] .... 1380661.568632: vfs_write <-SyS_write

......

审核编辑：汤梓红