性能工具
  • perf工具使用

    perf工具使用

    perf介绍 perf 是一个强大的 Linux 性能分析工具,广泛用于分析程序的性能瓶颈,帮助开发者进行调优。perf 工具能够收集并分析多种硬件和软件事件,包括 CPU 的指令执行、缓存命中与失误、上下文切换等。 硬件事件驱:通过访问 CPU 的 PMU(性能监控单元)捕获硬件级事件,如 CPU 周期数、缓存命中/未命中、分支预测失败等。 采样与统计机制:采样模式,周期性记录程序执行状态,生成热点函数分布(默认基于 CPU 时钟周期);统计模式,精确记录特定事件的发生次数(如指令数、缓存访问次数); 内核集成优势:直接调用内核的 tracepoint 和 kprobe 机制,支持用户态与内核态的全栈追 基本语法: perf <command> [options] command:perf 工具的子命令,例如 record、stat、report 等。 options:提供给 command 的选项和参数。 perf record perf record 命令用于收集性能数据,通常用来分析程序的性能瓶颈。 perf record [options] <command> -p \<pid>:指定要分析的进程的 PID。 -F \<frequency>:指定采样的频率(每秒钟采样次数)。例如,-F 99 每秒采样 99 次。 -g:收集调用图信息(调用栈信息),可以用来分析函数调用的上下文。 -e \<event>:指定要计数的事件。例如:-e cycles 计数 CPU 周期,-e cache-misses 计数缓存未命中 -- sleep \<time>:执行指定命令,并在给定的时间内采样性能数据。例如,-- sleep 30 表示记录 30 秒的数据。 示例: perf record -F 99 -p 12345 -g -- sleep 30 # 这会对进程 PID 为 12345 的程序进行 30 秒的性能采样,采样频率为99Hz(默认是1000HZ),并收集调用图信息。 # record生成的是原始数据bin,无法直接查看,默认是生成perf.data,可以使用-o指定输出文件。 # 需要使用perf script转化才可解析。 perf report perf report 命令用于分析和展示 perf record 记录的性能数据。 perf report [options] -g:显示调用图(调用堆栈)信息,帮助分析函数的调用关系,如果要绘制图像,需要加这个参数。 -i \<file>:指定输入文件,默认情况下会使用 perf.data 文件。 示例: perf report -g 这会显示 perf record 记录的性能数据的调用图。 perf script perf script 是一个 perf 工具的子命令,主要用于将 perf record 采集到的性能数据转换为可读的格式,并允许用户对其进行进一步处理。它的主要功能是解析性能数据文件并输出到标准输出或指定文件,方便进一步分析。 perf script [options] 将 perf record 生成的性能数据(默认文件名为 perf.data)转化为易于阅读的文本格式。可以与其他工具结合,进一步分析和处理数据。 perf script -i perf.data > output.txt 指定输入文件转化为输出文件。 实践应用 perf sched perf sched 是 perf 工具中的一个子命令,用于分析与调度相关的性能数据,主要用于分析 Linux 系统中的调度器行为(即进程和线程的调度)。这个命令可以帮助开发人员深入了解进程或线程如何在 CPU 上执行,以及在多核系统上如何分配 CPU 时间。 perf sched 命令通过分析内核的调度事件(如进程切换、上下文切换、进程调度延迟等),帮助开发人员识别系统中可能的调度瓶颈或性能问题。 抓取数据 perf sched record -a -g -o sched_raw.data & 解析数据: killall perf #结束进程,注意是不要使用-9强行退出,需要等待退出,保证写入的文件完整。 perf sched timehist -i sched_raw.data > sched_timehist.log perf sched latency -i sched_raw.data > sched_latency.log # 显示进程或线程的调度延迟,帮助你理解调度延迟如何影响系统性能。 perf sched script -i sched_raw.data > sched.log 解析数据 killall perf #结束进程,注意是不要使用-9强行退出,需要等待退出,保证写入的文件完整。 perf sched timehist -i sched_raw.data > sched_timehist.log perf sched latency -i sched_raw.data > sched_latency.log # 显示进程或线程的调度延迟,帮助你理解调度延迟如何影响系统性能。 perf sched script -i sched_raw.data > sched.log perf irq perf irq是perf 工具中的一个子命令,用于分析与中断(IRQ, Interrupt Request)相关的性能数据。中断是操作系统用来响应硬件或软件事件的机制。perf irq 可以帮助开发者分析中断的发生频率、持续时间及其对系统性能的影响。 抓取数据 抓取中断的进入和退出 perf record -e irq:irq_handler_entry,irq:irq_handler_exit -a -g -o irq_raw.data & 解析数据 killall perf perf script -i irq_raw.data > irq.log perf report -i irq_raw.data > irq_report.log 火焰图 通过perf script将原始数据转换的数据,可以使用工具转换为火焰图。需要注意的时,在使用perf script转换之前,perf record需要加-g参数,记录调用栈。 火焰图工具下载链接:https://github.com/brendangregg/FlameGraph 下面是转换命令: ../FlameGraph-master/stackcollapse-perf.pl < sched.log | ../FlameGraph-master/flamegraph.pl > sched.svg 其中sched.log是perf script转换的处理的数据,先使用stackcollapse-perf.pl处理数据,然后再使用flamegraph.pl绘制图像,即可使用网页打开。 y轴(竖)表示调用栈,每一层都是一个函数,调用栈越深,火焰就越高,顶部就是正在执行的函数,下方都是它的父函数。 x轴(横)表示抽样数,若一个函数在x轴占据的宽度越宽,就表示它被抽到的次数多,即执行的时间长。注意,x 轴不代表时间,而是所有的调用栈合并后,按字母顺序排列的。 火焰图就是看顶层的哪个函数占据的宽度最大。只要有"平顶"(plateaus),就表示该函数可能存在性能问题。 点击一层会水平放大,左上角会同时显示"Reset Zoom",点击该链接,图片就会恢复原样。
  • function graph tracer原理

    function graph tracer原理

    概述 Function graph相对function trace的不同点是,在函数入口会trace,在函数出口也会trace。 ksys_read ->vfs_read ->ftrace_caller ->prepare_ftrace_return ->function_graph_enter ->ftrace_push_return_trace(&trace, &ret, frame_pointer) ->trace_graph_entry = funcgraph_ops.entryfunc ->__trace_graph_entry ->trace_buffer_unlock_commit_nostack(buffer, event) Xxxxxxx 函数体内容 ->return_to_handler ----修改的vfs_read的ra寄存器,让其执行ret返回是跳转到这个函数。 ->ftrace_return_to_handler ->ftrace_pop_return_trace(&trace, &ret, frame_pointer) ->ftrace_graph_return(&trace) ->trace_graph_return =funcgraph_ops.retfunc ->__trace_graph_return(tr, trace, trace_ctx) ->trace_buffer_unlock_commit_nostack(buffer, event); ret 注册 与前面章节的function tracer一样,当前执行echo function_graph > current_tracer时就会待用到graph_trace_init函数。 与function tracer一样,当echo function_graph > current_tracer后,函数的入口nop指令会被替换为ftracer_caller。 当还没有写入function_graph时,ftrace_caller的实现如下,其中第一处ftrace_stub是用于function tracer替换的,而第二处则是给function_graph替换的。 当写入function_graph到current_tracer后,第二处的ftrace_stub被替换为prepare_ftrace_return,如下: static struct fgraph_ops funcgraph_ops = { .entryfunc = &trace_graph_entry, .retfunc = &trace_graph_return, }; int graph_trace_init(struct trace_array *tr) ret = register_ftrace_graph(&funcgraph_ops); tracing_start_cmdline_record(); tracing_start_sched_switch(RECORD_CMDLINE); 跟踪入口函数 下面我们来实际跟踪一下ftrace_caller之后的实现。 ENTRY(ftrace_caller) SAVE_ABI addi a0, t0, -FENTRY_RA_OFFSET la a1, function_trace_op REG_L a2, 0(a1) mv a1, ra mv a3, sp ftrace_call: .global ftrace_call call ftrace_stub #ifdef CONFIG_FUNCTION_GRAPH_TRACER addi a0, sp, ABI_RA REG_L a1, ABI_T0(sp) addi a1, a1, -FENTRY_RA_OFFSET #ifdef HAVE_FUNCTION_GRAPH_FP_TEST mv a2, s0 #endif ftrace_graph_call: .global ftrace_graph_call call ftrace_stub #endif RESTORE_ABI jr t0 ENDPROC(ftrace_caller) 上面代码经过宏展开后,变成下面的代码,我们从调用vfs_read的函数ksys_read开始分析。 ksys_read->vfs_read ... 0xffffffff80384e6e <ksys_read+122>: auipc ra,0xfffff 0xffffffff80384e72 <ksys_read+126>: jalr 594(ra) # 0xffffffff803840c0 <vfs_read> ① ra=PC+4,即0xffffffff80384e76 ,PC=0xffffffff803840c0,这里保存了调用vfs_read的返回地址。 0xffffffff80384e76 <ksys_read+130>: mv s2,a0 0xffffffff80384e78 <ksys_read+132>: bltz a0,0xffffffff80384ef4 <ksys_read+256> vfs_read->ftrace_caller 0xffffffff803840c0 <vfs_read+0>: auipc t0,0xffc88 0xffffffff803840c4 <vfs_read+4>: jalr t0,1404(t0) # 0xffffffff8000c63c <ftrace_caller> ② t0=PC+4即0xffffffff803840c8,PC=0xffffffff8000c63c,这里没有使用ra,而是使用了t0,因此ra得以传递到ftrace_caller。 0xffffffff803840c8 <vfs_read+0>: addi sp,sp,-176 0xffffffff803840ca <vfs_read+2>: sd s0,160(sp) ftrace_caller->prepare_ftrace_return Dump of assembler code for function ftrace_caller: 0xffffffff8000c63c <+0>: addi sp,sp,-80 => 0xffffffff8000c63e <+2>: sd a0,0(sp) 0xffffffff8000c640 <+4>: sd a1,8(sp) 0xffffffff8000c642 <+6>: sd a2,16(sp) 0xffffffff8000c644 <+8>: sd a3,24(sp) 0xffffffff8000c646 <+10>: sd a4,32(sp) 0xffffffff8000c648 <+12>: sd a5,40(sp) 0xffffffff8000c64a <+14>: sd a6,48(sp) 0xffffffff8000c64c <+16>: sd a7,56(sp) 0xffffffff8000c64e <+18>: sd t0,64(sp) 存储了ftrace_caller的返回地址。 0xffffffff8000c650 <+20>: sd ra,72(sp) 存储了vfs_read的返回地址。 ③开辟一个栈空间,将寄存器入栈 0xffffffff8000c652 <+22>: addi a0,t0,-8 0xffffffff8000c656 <+26>: auipc a1,0x251c 0xffffffff8000c65a <+30>: addi a1,a1,578 # 0xffffffff82528898 <function_trace_op> 0xffffffff8000c65e <+34>: ld a2,0(a1) ④获取全局变量function_trace_op,这是struct ftrace_ops实例,function_trace_op.func存储了跟踪函数。 0xffffffff8000c660 <+36>: mv a1,ra 0xffffffff8000c662 <+38>: mv a3,sp ⑤a1参数记录了vfs_read的返回地址,a3记录了栈 0xffffffff8000c664 <+40>: auipc ra,0x0 0xffffffff8000c668 <+44>: jalr -1604(ra) # 0xffffffff8000c020 <ftrace_stub> ⑥因为使能的是function_graph,所以ftrace_stub没有被替换 0xffffffff8000c66c <+48>: addi a0,sp,72 ⑦sp+72存储的是vfs_read的ra,因此a0的值即为vfs_read函数ra的地址,*a0即返回地址,a0代表的是第一个函数参数,因此第一个函数参数为vfs_read的*parent。 0xffffffff8000c66e <+50>: ld a1,64(sp) 0xffffffff8000c670 <+52>: addi a1,a1,-8 ⑧ sp+64存储的是ftrace_caller的返回地址,用ftrace_call的返回地址-8就为vfs_read的入口地址,所以a1代表的是vfs_read的入口地址。 0xffffffff8000c672 <+54>: mv a2,s0 ⑨ a2为当前栈帧 0xffffffff8000c674 <+56>: auipc ra,0x0 0xffffffff8000c678 <+60>: jalr -1338(ra) # 0xffffffff8000c13a <prepare_ftrace_return> ⑩ 更新ra=0xffffffff8000c67c,跳转到prepare_ftrace_return 0xffffffff8000c67c <+64>: ld a0,0(sp) 0xffffffff8000c67e <+66>: ld a1,8(sp) 0xffffffff8000c680 <+68>: ld a2,16(sp) 0xffffffff8000c682 <+70>: ld a3,24(sp) 0xffffffff8000c684 <+72>: ld a4,32(sp) 0xffffffff8000c686 <+74>: ld a5,40(sp) 0xffffffff8000c688 <+76>: ld a6,48(sp) 0xffffffff8000c68a <+78>: ld a7,56(sp) 0xffffffff8000c68c <+80>: ld t0,64(sp) 0xffffffff8000c68e <+82>: ld ra,72(sp) 0xffffffff8000c690 <+84>: addi sp,sp,80 0xffffffff8000c692 <+86>: jr t0 End of assembler dump. 从上面可知,ftrace_caller函数后,就跳转到prepare_ftrace_return。 接下来看看prepare_ftrace_return void prepare_ftrace_return(unsigned long *parent, unsigned long self_addr, unsigned long frame_pointer) { unsigned long return_hooker = (unsigned long)&return_to_handler; unsigned long old; if (unlikely(atomic_read(¤t->tracing_graph_pause))) return; /* * We don't suffer access faults, so no extra fault-recovery assembly * is needed here. */ old = *parent; if (!function_graph_enter(old, self_addr, frame_pointer, parent)) *parent = return_hooker; 调用function_graph_enter,同时将vfs_read的返回地址修改为return_to_handler,也就是说当vfs_read函数执行返回时,会跳转到return_to_handler运行,这样就相当于在vfs_read的出口函数也插桩了。 } function_graph_enter int function_graph_enter(unsigned long ret, unsigned long func, unsigned long frame_pointer, unsigned long *retp) { struct ftrace_graph_ent trace; #ifndef CONFIG_HAVE_DYNAMIC_FTRACE_WITH_ARGS /* * Skip graph tracing if the return location is served by direct trampoline, * since call sequence and return addresses are unpredictable anyway. * Ex: BPF trampoline may call original function and may skip frame * depending on type of BPF programs attached. */ if (ftrace_direct_func_count && ftrace_find_rec_direct(ret - MCOUNT_INSN_SIZE)) return -EBUSY; #endif trace.func = func; trace.depth = ++current->curr_ret_depth; if (ftrace_push_return_trace(ret, func, frame_pointer, retp)) goto out; ① 将要跟踪函数vfs_read的返回地址、函数名称、进入时间存储到当前任务的task_struct中。 /* Only trace if the calling function expects to */ if (!ftrace_graph_entry(&trace)) goto out_ret; ②struct fgraph_ops funcgraph_ops.entryfunc = &trace_graph_entry,调用trace_graph_entry函数,将trace信息写入ring buffer。 return 0; out_ret: current->curr_ret_stack--; out: current->curr_ret_depth--; return -EBUSY; } ftrace_push_return_trace,将要跟踪函数vfs_read的返回地址、函数名称、进入时间存储到当前任务的task_struct中。 static int ftrace_push_return_trace(unsigned long ret, unsigned long func, unsigned long frame_pointer, unsigned long *retp) { unsigned long long calltime; int index; if (unlikely(ftrace_graph_is_dead())) return -EBUSY; if (!current->ret_stack) return -EBUSY; /* * We must make sure the ret_stack is tested before we read * anything else. */ smp_rmb(); /* The return trace stack is full */ if (current->curr_ret_stack == FTRACE_RETFUNC_DEPTH - 1) { atomic_inc(¤t->trace_overrun); return -EBUSY; } calltime = trace_clock_local(); index = ++current->curr_ret_stack; barrier(); current->ret_stack[index].ret = ret; current->ret_stack[index].func = func; current->ret_stack[index].calltime = calltime; //将vfs_read的返回地址、vfs_read函数、进入vfs_read时间记录到当前任务的ret_stack,后续vfs_read退出时会使用到。 //current是当前运行任务的struct task_sturct,在该结构中,为function graph专门定义了一块空间用于存储记录上面的信息。 #ifdef HAVE_FUNCTION_GRAPH_FP_TEST current->ret_stack[index].fp = frame_pointer; #endif #ifdef HAVE_FUNCTION_GRAPH_RET_ADDR_PTR current->ret_stack[index].retp = retp; #endif return 0; } 跟踪出口函数 当被跟踪的函数要退出时,由于修改了其ra寄存器,因此会跳转到return_to_handler,本文的实例是vfs_read,因此当vfs_read函数执行完时,本应该执行ret就退出,但是在前面将ra的内容改了,继而跳转执行return_to_handler。 #ifdef CONFIG_FUNCTION_GRAPH_TRACER ENTRY(return_to_handler) /* * On implementing the frame point test, the ideal way is to compare the * s0 (frame pointer, if enabled) on entry and the sp (stack pointer) on return. * However, the psABI of variable-length-argument functions does not allow this. * * So alternatively we check the *old* frame pointer position, that is, the * value stored in -16(s0) on entry, and the s0 on return. */ #ifdef HAVE_FUNCTION_GRAPH_FP_TEST mv t6, s0 #endif SAVE_RET_ABI_STATE #ifdef HAVE_FUNCTION_GRAPH_FP_TEST mv a0, t6 #endif call ftrace_return_to_handler mv a2, a0 RESTORE_RET_ABI_STATE jalr a2 ENDPROC(return_to_handler) #endif ftrace_return_to_handler unsigned long ftrace_return_to_handler(unsigned long frame_pointer) { struct ftrace_graph_ret trace; unsigned long ret; ftrace_pop_return_trace(&trace, &ret, frame_pointer); ①与前面的ftrace_push_return_trace对应,将trace相关信息获取出来,如vfs_read的返回地址信息。 trace.rettime = trace_clock_local(); ftrace_graph_return(&trace); ② 调用graph 退出函数,调用trace_graph_return->__trace_graph_return,将信息更新写入ring buffer。 /* * The ftrace_graph_return() may still access the current * ret_stack structure, we need to make sure the update of * curr_ret_stack is after that. */ barrier(); current->curr_ret_stack--; if (unlikely(!ret)) { ftrace_graph_stop(); WARN_ON(1); /* Might as well panic. What else to do? */ ret = (unsigned long)panic; } return ret; }
  • 静态ftrace

    静态ftrace

    上面章节主要描述的是动态ftrace,在早期还有静态ftrace。区别主要如下: - 动态ftrace与静态ftrace在编译参数方面静态编译使用的是参数“-pg”,而动态使用的是fpatchable-function-entry。 - 工具链使能“-pg”参数时,会在每个函数体前面插入_mcount函数。而动态ftrace会在函数入口(函数准备阶段前)插入nop指令。 - 静态ftrace插入的_mcout直到代码运行期间一直存在,而动态ftrace在不使能tracer是nop指令,动态ftrace可以动态的修改代码。 内核编译时,使能CONFIG_FUNCTION_TRACER时会启动该参数编译,在kernel目录下的Makefile可以看到。 # The arch Makefiles can override CC_FLAGS_FTRACE. We may also append it later. ifdef CONFIG_FUNCTION_TRACER CC_FLAGS_FTRACE := -pg endif 基本原理 void ftrace_stub(void) { return; } void mcount(void) { /* save any bare state needed in order to do initial checking */ extern void (*ftrace_trace_function)(unsigned long, unsigned long); if (ftrace_trace_function != ftrace_stub) goto do_trace; ① 如果用户定义了trace函数,那么就跳转到do_trace,执行ftrace_trace_function。否则什么都不做,直接返回。 /* restore any bare state */ return; do_trace: /* save all state needed by the ABI (see paragraph above) */ unsigned long frompc = ...; unsigned long selfpc = <return address> - MCOUNT_INSN_SIZE; ftrace_trace_function(frompc, selfpc); ② 跳转执行ftrace_trace_function /* restore all state needed by the ABI */ } 编译完成插桩点 通过反汇编objdump -D vmlinux > log后查看_mcount被插入到了vfs_read中,插入的位置在函数准备阶段之后,函数体内容之前。系统运行时,可以使用gdb 查看汇编指令,与上面基本一致。 我们接着再查看以下_mcount的实现,如下
  • 动态function tracer原理

    动态function tracer原理

    fpatchable-function-entry选项 编译时指定-fpatchable-function-entry=N[,M],①会在函数入口第一个指令之前插入N个nop,但是会保留M个放到函数入口之前,如果省略M则默认为0;②同时需要一个特殊的-fpatchable-function-entry段来记录所有函数的入口,如下蓝色部分。nop指令保留了额外的空间,可用于在运行时修改nop指令,添加自己想要的桩点,前提是代码段可写的。 echo \'void test(){;}\' > test.c $ riscv64-unknown-linux-gnu-gcc test.c -x c -c -fpatchable-function-entry=3,1 -S -o - riscv64-unknown-linux-gnu-gcc: warning: \'-x c\' after last input file has no effect .file \"test.c\" .option nopic .text .align 1 .globl test .section __patchable_function_entries,\"aw\",@progbits .align 3 .8byte .LPFE1 .text .LPFE1: nop .type test, @function test: nop nop addi sp,sp,-16 sd s0,8(sp) addi s0,sp,16 nop ld s0,8(sp) addi sp,sp,16 jr ra .size test, .-test .ident \"GCC: (Xuantie-900 linux-5.10.4 glibc gcc Toolchain V2.8.1 B-20240115) 10.4.0\" .section .note.GNU-stack,\"\",@progbits risc-v 内核编译与链接 在本文的实验平台的RISC-V架构中,使用编译选项-fpatchable-function-entry进行编译,在内核arch/riscv/Makefile中指定CC_FLAGS_FTRACE:=-fpatchable-function-entry=X来编译内核组件。 添加上面参数后,编译后的目标文件,就会有两个特征: - 每个函数入口,第一条指令前插入nop指令。 - 在__patchable_function_entries段重定位中,记录了当前目标文件所有函数入口地址。 Linux内核最终会链接合并成vmlinux.o,在链接重定位阶段会将所有.o中的__patchable_function_entries段重定位段信息合并起来。具体在链接脚本中include/asm-generic/vmlinux.lds.h中MCOUNT_REC的描述。如上图,nop指令的长度位2字节(16bit,用的是压缩指令c.nop),不管是多少位系统这是默认内核编译nop指令的长度,因此函数入口插入的nop总长度4*2字节=8字节,这8字节的nop会在开启函数跟踪的时候修改位对应长度的跳转指令,在启动过程中或函数跟踪关闭的时候修改位对应长度的nop。 从上可知,可以通过__{start,stop}_mcount_loc符号获取到所有函数入口,同时每个函数入口都会插入nop指令,相当于定位了所有函数的入口在哪,后续就可以对指令进行修改,如下图所示。 为什么要用一个section来记录所有函数入口地址?这是因为记录的函数入口地址,就记录的nop指令的位置,在程序运行过程中才能把nop指令进行修改为指定的跟踪函数。在动态ftrace中,系统启动初始化时会将所有的函数入口地址记录到struct dyn_ftrace结构体中,3.4章节会介绍到。 桩点更新过程概览 接下来我们以函数vfs_read进行实例分析,从编译到系统启动,再到使能function trace这一过程来进行简单分析插装点变化。 编译插桩点 本文的实验平台=-fpatchable-function-entry=4,即编译完成后,需要在函数入口处插入4个nop指令,我们通过riscv64-unknown-linux-gnu-objdump -D vmlinux > log反汇编查看vfs_read如下: ffffffff8039e398 : ffffffff8039e398: 0001 nop ffffffff8039e39a: 0001 nop ffffffff8039e39c: 0001 nop ffffffff8039e39e: 0001 nop ffffffff8039e3a0: 7171 addi sp,sp,-176 ffffffff8039e3a2: f122 sd s0,160(sp) ffffffff8039e3a4: f4de sd s7,104(sp) ffffffff8039e3a6: f506 sd ra,168(sp) ffffffff8039e3a8: ed26 sd s1,152(sp) ffffffff8039e3aa: e94a sd s2,144(sp) ffffffff8039e3ac: e54e sd s3,136(sp) ffffffff8039e3ae: e152 sd s4,128(sp) ffffffff8039e3b0: fcd6 sd s5,120(sp) ffffffff8039e3b2: f8da sd s6,112(sp) ffffffff8039e3b4: f0e2 sd s8,96(sp) ffffffff8039e3b6: 1900 addi s0,sp,176 ffffffff8039e3b8: 021c0b97 auipc s7,0x21c0 ffffffff8039e3bc: d08b8b93 addi s7,s7,-760 # ffffffff8255e0c0 ffffffff8039e3c0: 000bb703 ld a4,0(s7) ffffffff8039e3c4: 497c lw a5,84(a0) ffffffff8039e3c6: fae43423 sd a4,-88(s0) ffffffff8039e3ca: 0017f713 andi a4,a5,1 ...... 启动初始化调整nop指令长度 在系统启动阶段,会调用ftrace_init函数,将所有的入口函数地址记录到struct dyn_frtace实例结构中,然后将4个RV32C压缩指令替换为RV32I模式的nop指令,即原来的4个2字节长度的nop指令,将会拓展为2个4字节的拓展指令。 我们在系统启动时先在ftrace_init地方打断点,先观察vfs_read处的指令情况。disassemble 0xffffffff8039e398,+50查看地址开始的指令。(不能使用disassemble vfs_read,+50查看,这样会把前面的插桩过滤掉,需要使用地址的方式)。 可以看到,跟上一节中我们反汇编看到的指令是一致了,4条nop指令还没有被替换。接着我们使用n继续进行调试运行,当运行完ftrace_process_locs后,我们再来查看一下变化。 我们发现之前4条2字节的nop指令被替换成了2条4字节的nop指令了。为什么要调整nop指令的长度了,个人理解应该是为了兼顾处理器流水线的优化、指令对齐等,比如跳转到指定标签运行是auipc+jalr两条4字节的指令。之所以不在编译时就确定时因为延迟运行调整nop指令的长度,可以更好的平衡系统的兼容性和灵活性。 替换入口函数的nop 当我们使能function tracer后,nop指令就会被替换为ftrace_caller。接下来我们使能 echo function > /sys/kernel/debug/tracing/current_tracer再来看看vfs_read的情况。 从上面可知,之前的2条nop指令就被替换为了auipc+jalr指令,即跳转到ftrace_caller函数。 替换跟踪函数ftrace_stub 执行echo function >current_tracer时,除了函数入口的nop指令会被替换为ftrace_caller外,ftrace_caller的实现中,ftrace_stub也会替换为function_trace_call。更新代码会调用到ftrace_modify_all_code函数,我们对此函数进行断点观察前后变化。 如上图,在还没有执行命令echo function > current_tracer时,ftrace_caller执行的是ftrace_stub,当执行命令后,就变成跳转如下i b。 具体的实例代码如下,切换前: ENTRY(ftrace_caller) SAVE_ABI addi a0, t0, -FENTRY_RA_OFFSET la a1, function_trace_op REG_L a2, 0(a1) mv a1, ra mv a3, sp ftrace_call: .global ftrace_call call ftrace_stub ①未执行echo function > current_tracer RESTORE_ABI jr t0 ENDPROC(ftrace_caller) 执行命令echo function > current_tracer后,ftrace_caller标签处就会变为如下: ENTRY(ftrace_caller) SAVE_ABI addi a0, t0, -FENTRY_RA_OFFSET la a1, function_trace_op REG_L a2, 0(a1) mv a1, ra mv a3, sp ftrace_call: .global ftrace_call call function_trace_call ①执行echo function > current_tracer RESTORE_ABI jr t0 ENDPROC(ftrace_caller) ftrace_caller调用流程 gdb 调试继续跟踪ftrace_caller实现。 (gdb) => 0xffffffff8039e398 : ffc6e297 auipc t0,0xffc6e 0xffffffff8039e39c : 3f4282e7 jalr t0,1012(t0) # 0xffffffff8000c78c ①进入vfs_read函数入口是,跳转到ftrace_caller,t0=PC+4,即0xffffffff8039e3a0 0xffffffff8039e3a0 : addi sp,sp,-176 0xffffffff8039e3a2 : sd s0,160(sp) ..... ftrace_caller () at arch/riscv/kernel/mcount-dyn.S:135 135 SAVE_ABI ②开辟一段栈空间,将a0~a7,t0/ra入栈。 => 0xffffffff8000c78c : 715d addi sp,sp,-80 0xffffffff8000c78e : e02a sd a0,0(sp) 0xffffffff8000c790 : e42e sd a1,8(sp) 0xffffffff8000c792 : e832 sd a2,16(sp) 0xffffffff8000c794 : ec36 sd a3,24(sp) 0xffffffff8000c796 : f03a sd a4,32(sp) 0xffffffff8000c798 : f43e sd a5,40(sp) 0xffffffff8000c79a : f842 sd a6,48(sp) 0xffffffff8000c79c : fc46 sd a7,56(sp) 0xffffffff8000c79e : e096 sd t0,64(sp) 0xffffffff8000c7a0 : e486 sd ra,72(sp) 137 addi a0, t0, -FENTRY_RA_OFFSET ②获取vfs_read的入口地址。 => 0xffffffff8000c7a2 : ff828513 addi a0,t0,-8 138 la a1, function_trace_op ③获取全局变量function_trace_op,这是ftrace的操作集合,包含了ftrace的函数。 => 0xffffffff8000c7a6 : 0254e597 auipc a1,0x254e 0xffffffff8000c7aa : 5f258593 addi a1,a1,1522 # 0xffffffff8255ad98 139 REG_L a2, 0(a1) ④获取ftrace_trace_op地址存储到a2中。 => 0xffffffff8000c7ae : 6190 ld a2,0(a1) 140 mv a1, ra 141 mv a3, sp 145 call ftrace_stub => 0xffffffff8000c7b4 : 00198097 auipc ra,0x198 0xffffffff8000c7b8 : e5a080e7 jalr -422(ra) # 0xffffffff801a460e at kernel/trace/trace_functions.c:175 function_trace_call(unsigned long ip, unsigned long parent_ip,struct ftrace_ops *op, struct ftrace_regs *fregs) ⑤ ip为入口函数vfs_read的地址即a0, parent_ip为vfs_read的父函数,调用vfs_read地址处的下一条指令。op为ftrace_trace_op,fregs为栈地址。 trace_function entry = ring_buffer_event_data(event); entry->ip = ip; entry->parent_ip = parent_ip; ftrace_exports(event, TRACE_EXPORT_FUNCTION); ⑥ 将信息写入到ring buffer中。 while(export) { trace_process_export(export, event, flag); export->write(export, entry, size); } ftrace_caller () at arch/riscv/kernel/mcount-dyn.S:148 148 addi a0, sp, ABI_RA 149 REG_L a1, ABI_T0(sp) 150 addi a1, a1, -FENTRY_RA_OFFSET 152 mv a2, s0 156 call ftrace_stub ⑦对function graph tracer进行处理,当前使能的是function tracer,所以ftrace_stub函数直接直接为ret,如下。 ftrace_stub () at arch/riscv/kernel/mcount.S:55 55 ret => 0xffffffff8000c170 : 8082 ret 0xffffffff8000c172 : 0001 nop ftrace_caller () at arch/riscv/kernel/mcount-dyn.S:158 158 RESTORE_ABI ⑧恢复寄存器,准备返回。 ftrace_caller () at arch/riscv/kernel/mcount-dyn.S:159 159 jr t0 => 0xffffffff8000c7e2 : 8282 jr t0 总结一下: ftrace_caller call ftrace_stub => call function_trace_call trace_function ftrace_exports export->write(export, entry, size) 从上可知,ftrace_stub被赋值为function_trace_call,该函数是什么时候被替换的了?我们留着后续进行3.5章节进行分析。 ftrace_init ftrace_init通过读取__{start,stop}_mcount_loc字段中记录所有的函数入口地址,所有的入口地址被记录到最小的实例struct dyn_ftrace结构体中,这些结构体最终打包形成pg链表节点,首节点为start_pg,遍历start_pg链表执行ftrace_init_nop把4个nop指令。 数据结构 在section中__{start,stop}_mcount_loc字段中记录所有的函数入口地址,每个函数入口地址都有一个struct dyn_ftrace数据结构实例来记录。每个页面(page)可以存放多个struct_ftrace实例,多个页面组成一个groups。每个组使用struct ftrace_pages节点来进行管理,多个struct ftrace_pages组成一个链表,具体的结构如上图所示。 void __init ftrace_init(void) { extern unsigned long __start_mcount_loc[]; extern unsigned long __stop_mcount_loc[]; ① _start_mcount_loc和_stop_mcount_loc分别是所有入口函数段的开始和结束。 unsigned long count, flags; int ret; local_irq_save(flags); ret = ftrace_dyn_arch_init(); local_irq_restore(flags); if (ret) goto failed; count = __stop_mcount_loc - __start_mcount_loc; if (!count) { pr_info(\\\"ftrace: No functions to be traced?\\\\n\\\"); goto failed; } pr_info(\\\"ftrace: allocating %ld entries in %ld pages\\\\n\\\", count, DIV_ROUND_UP(count, ENTRIES_PER_PAGE)); ② count所有的插桩点的总数,DIV_ROUND_UP(count, ENTRIES_PER_PAGE))表示需要分配多少个pages,每个插桩点都使用struct dyn_ftrace来记录。下面是qumu上的打印 [ 0.000000] ftrace: allocating 37736 entries in 148 pages 一共有37736个插桩点,需要148 * 4KB=592KB的内存。 ret = ftrace_process_locs(NULL, __start_mcount_loc, __stop_mcount_loc); if (ret) { pr_warn(\\\"ftrace: failed to allocate entries for functions\\\\n\\\"); goto failed; } ③ 将所有的插桩点地址记录到struct dyn_ftrace实例中,如数据结构图中,每个插桩点都有要给struct dyn_ftrace实例,实例空间分配page,每个page有多个struct dyn_ftrace的实例。然后遍历地址将4条nop指令调整为2条nop指令(本章节的实验)。 pr_info(\\\"ftrace: allocated %ld pages with %ld groups\\\\n\\\", ftrace_number_of_pages, ftrace_number_of_groups); last_ftrace_enabled = ftrace_enabled = 1; ④设置过滤? set_ftrace_early_filters(); return; failed: ftrace_disabled = 1; } 分配数据结构 static int ftrace_process_locs(struct module *mod, unsigned long *start, unsigned long *end) { struct ftrace_page *start_pg; struct ftrace_page *pg; struct dyn_ftrace *rec; unsigned long count; unsigned long *p; unsigned long addr; unsigned long flags = 0; /* Shut up gcc */ int ret = -ENOMEM; count = end - start; if (!count) return 0; start_pg = ftrace_allocate_pages(count); if (!start_pg) return -ENOMEM; ① 分配ftrace page,里面存放的是struct dyn_ftrace,具体结构如3.3.1数据结构图,用于后续存放地址。 ...... } 记录插桩地址 static int ftrace_process_locs(struct module *mod, unsigned long *start, unsigned long *end) { ...... p = start; pg = start_pg; while (p < end) { unsigned long end_offset; addr = ftrace_call_adjust(*p++); /* * Some architecture linkers will pad between * the different mcount_loc sections of different * object files to satisfy alignments. * Skip any NULL pointers. */ if (!addr) continue; end_offset = (pg->index+1) * sizeof(pg->records[0]); if (end_offset > PAGE_SIZE order) { /* We should have allocated enough */ if (WARN_ON(!pg->next)) break; pg = pg->next; } rec = &pg->records[pg->index++]; rec->ip = addr; ② 遍历将所有的插桩点地址存储到struct dyn_ftrace中。 } ...... } 更新插桩指令nop static int ftrace_process_locs(struct module *mod, unsigned long *start, unsigned long *end) { ...... if (!mod) local_irq_save(flags); ftrace_update_code(mod, start_pg); if (!mod) local_irq_restore(flags); ...... } ftrace_update_code(mod, start_pg); for (pg = new_pgs; pg; pg = pg->next) { ftrace_nop_initialize(mod, p) ftrace_init_nop(mod, rec) out = ftrace_make_nop(mod, rec, MCOUNT_ADDR); unsigned int nops[2] = {NOP4, NOP4}; patch_text_nosync((void *)rec->ip, nops, MCOUNT_INSN_SIZE) patch_insn_write(tp, insns, len) addr = patch_map(addr, FIX_TEXT_POKE0); //fixmap FIX_TEXT_POKE0映射地址 ret = copy_to_kernel_nofault(waddr, insn, len); pagefault_disable() //关掉缺页异常 copy_to_kernel_nofault_loop(dst, src, size, u64, Efault) __put_kernel_nofault __put_user_nocheck __put_user_asm(\\\"sw\\\", (x), __gu_ptr, __pu_err) //写内存指令 pagefault_disable() patch_unmap(FIX_TEXT_POKE0); } 入口函数与跟踪函数替换 入口函数:两条nop指令替换为ftrace_caller。 跟踪函数:call ftrace_stub替换为call function_trace_call。 前面描述了使能function tracer后会将nop指令替换为ftrace_caller和将ftrace_stub替换为function_trace_call。当echo function > current_tracer就会通过文件系统调用到tracing_set_trace_write函数,本章节从该函数来具体分析下替换过程。 tracing_set_trace_write(struct file *filp, const char __user *ubuf, size_t cnt, loff_t *ppos) err = tracing_set_tracer(tr, name) for (t = trace_types; t; t = t->next) { if (strcmp(t->name, buf) == 0) break; } ①trace有很多个类型,匹配function类型获取到struct tracer *t。 if (t->init) { ret = tracer_init(t, tr); if (ret) goto out; } ②调用对应tracer的初始化函数,我们这里使能的是function,因此调用的是function_trace_init 每个tracer都有一个对应的实例,对应function类型的tracer实例如下,会调用register_tracer(&function_trace)函数进行注册tracer。 static struct tracer function_trace __tracer_data = { .name = \\\"function\\\", .init = function_trace_init, .reset = function_trace_reset, .start = function_trace_start, .flags = &func_flags, .set_flag = func_set_flag, .allow_instances = true, }; 接下来,接着看看function_trace_init函数实现。 static int function_trace_init(struct trace_array *tr) { ftrace_func_t func; func = select_trace_function(func_flags.val); if (!func) return -EINVAL; ①根据func_flags.val来选择跟踪函数,这里默认选择function_trace_call if (!handle_func_repeats(tr, func_flags.val)) return -ENOMEM; ftrace_init_array_ops(tr, func); ② 设置struct ftrace_ops.func = function_trace_call tr->array_buffer.cpu = raw_smp_processor_id(); tracing_start_cmdline_record(); tracing_start_function_trace(tr); ③ 注册ftrace_function return 0; } 全局ftrace_ops_list 如上图,ftrace_call的地方可以需要trace function,也要用于perf,那么就会再perf和function trace上面再封装一层,把ftrace_stub替换为ftrace_ops_list_func,在系统中ftrace_ops_list_func = arch_ftrace_ops_list_func。 void arch_ftrace_ops_list_func(unsigned long ip, unsigned long parent_ip, struct ftrace_ops *op, struct ftrace_regs *fregs) { __ftrace_ops_list_func(ip, parent_ip, NULL, fregs); } static nokprobe_inline void __ftrace_ops_list_func(unsigned long ip, unsigned long parent_ip, struct ftrace_ops *ignored, struct ftrace_regs *fregs) { struct pt_regs *regs = ftrace_get_regs(fregs); struct ftrace_ops *op; int bit; /* * The ftrace_test_and_set_recursion() will disable preemption, * which is required since some of the ops may be dynamically * allocated, they must be freed after a synchronize_rcu(). */ bit = trace_test_and_set_recursion(ip, parent_ip, TRACE_LIST_START); if (bit < 0) return; ftrace_ops_list是一个struct ftrace_ops类型的链表,每个ftrace_ops代表一个ftrace函数跟踪类型,默认是遍历ftrace_ops_list,调用ops函数 do_for_each_ftrace_op(op, ftrace_ops_list) { /* Stub functions don\\\'t need to be called nor tested */ if (op->flags & FTRACE_OPS_FL_STUB) continue; /* * Check the following for each ops before calling their func: * if RCU flag is set, then rcu_is_watching() must be true * Otherwise test if the ip matches the ops filter * * If any of the above fails then the op->func() is not executed. */ if ((!(op->flags & FTRACE_OPS_FL_RCU) || rcu_is_watching()) && ftrace_ops_test(op, ip, regs)) { if (FTRACE_WARN_ON(!op->func)) { pr_warn(\\\"op=%p %pS\\\\n\\\", op, op); goto out; } op->func(ip, parent_ip, op, fregs); } } while_for_each_ftrace_op(op); out: trace_clear_recursion(bit); } ftrace_ops数据结构: struct ftrace_ops { ftrace_func_t func; //替换ftrace_stub的函数 struct ftrace_ops __rcu *next; unsigned long flags; void *private; ftrace_func_t saved_func; #ifdef CONFIG_DYNAMIC_FTRACE struct ftrace_ops_hash local_hash; struct ftrace_ops_hash *func_hash; struct ftrace_ops_hash old_hash; unsigned long trampoline; unsigned long trampoline_size; struct list_head list; ftrace_ops_func_t ops_func; #endif }; 默认的ftrace_ops为: struct ftrace_ops global_ops = { .func = ftrace_stub, .local_hash.notrace_hash = EMPTY_HASH, .local_hash.filter_hash = EMPTY_HASH, INIT_OPS_HASH(global_ops) .flags = FTRACE_OPS_FL_INITIALIZED | FTRACE_OPS_FL_PID, }; 如果头结点是 ftrace_list_end,表示没有ops注册,代表无需函数跟踪,将 func 设置为空的跟踪函数 ftrace_stub。 如果头结点的下一个结点是 ftrace_list_end,表示只有一个ops注册,且当此ops不是动态ops(比如:livepatch),且架构支持传递 ops 到跟踪函数,则将 func 设置为 ops->func,否则设置为 ftrace_ops_list_func() 如果链表中有不止一个的 ops 注册,则将 func 设置为 ftrace_ops_list_func() ftrace_ops_list_func() 为区别于全局跟踪函数,我们在此称之为列表跟踪函数。此函数在 vmlinux 链接时,指向 arch_ftrace_ops_list_func,执行时会遍历 ftrace_ops_list,结合 ops->func_hash 来判断是否需要对当前 ip 执行 ops->func,也就是说 ftrace_ops_list_func() 不仅会调用多个 ops 的跟踪函数,也会保证 ops 跟踪函数处理的函数是应该被跟踪的。 本实验是将func 设置到 ftrace_trace_function()。当前设置 function tracer 的流程中,ops 就是 global_ops 且 ftrace_ops_list 链表只有 global_ops 这一个注册。 注册ftrace_function int register_ftrace_function(struct ftrace_ops *ops) { ret = register_ftrace_function_nolock(ops); ret = ftrace_startup(ops, 0); } int ftrace_startup(struct ftrace_ops *ops, int command) { int ret; if (unlikely(ftrace_disabled)) return -ENODEV; ret = __register_ftrace_function(ops); if (ret) return ret; ①添加ops(global_ops)到全局ops链表ftrace_ops_list中,并设置全局跟踪函数ftrace_trace_function为ops->func。 ftrace_start_up++; ops->flags |= FTRACE_OPS_FL_ENABLED | FTRACE_OPS_FL_ADDING; ②根据ops->func_hash->filter_hash更新入口函数表中每个函数记录rec的ip modfy位。 ret = ftrace_hash_ipmodify_enable(ops); if (ret < 0) { /* Rollback registration process */ __unregister_ftrace_function(ops); ftrace_start_up--; ops->flags &= ~FTRACE_OPS_FL_ENABLED; if (ops->flags & FTRACE_OPS_FL_DYNAMIC) ftrace_trampoline_free(ops); return ret; } if (ftrace_hash_rec_enable(ops, 1)) command |= FTRACE_UPDATE_CALLS; ③判断是否有函数入口需要更新,如果需要更新则command设置为FTRACE_UPDATE_CALLS。 这里的入口函数就是替换nop指令。入口函数的替换和跟踪函数替换是不一样的,注意区分。 ftrace_startup_enable(command); ④判断报错的跟踪函数saved_ftrace_func与当前跟踪函数ftrace_trace_function是否相同,如果不同则表示需要更新跟踪函数,command设置为FTRADE_UPDATE_TRACE_FUNC,之后执行ftrace_run_update_code进行更新。 /* * If ftrace is in an undefined state, we just remove ops from list * to prevent the NULL pointer, instead of totally rolling it back and * free trampoline, because those actions could cause further damage. */ if (unlikely(ftrace_disabled)) { __unregister_ftrace_function(ops); return -ENODEV; } ops->flags &= ~FTRACE_OPS_FL_ADDING; return 0; } int __register_ftrace_function(struct ftrace_ops *ops) { add_ftrace_ops(&ftrace_ops_list, ops); ① 将目标trace添加到全局链表ftrace_ops_list中。 /* Always save the function, and reset at unregistering */ ops->saved_func = ops->func; ② 保存当前要trace的函数。 if (ftrace_pids_enabled(ops)) ops->func = ftrace_pid_func; ③ 如果设置的特定pid 进行trace,将trace函数更新为 ftrace_pid_func,即ftrace_stub更新为ftrace_pid_func ftrace_update_trampoline(ops); if (ftrace_enabled) update_ftrace_function(); ④ 将当前的trace函数赋值到ftrace_trace_function中,表示当前要修改的目标函数。 return 0; } 函数过滤处理 如果设置了过滤函数不需要进行跟踪,需对相应的桩点实例dyn_ftrace设置标记,FTRACE_FL_DISABLED标志表示不需要更新入口函数,FTRACE_FL_IPMODIFY表示需要更新。需要过滤的函数,统一记录在ops->func_hash->filter_hash表中。 static int __ftrace_hash_update_ipmodify(struct ftrace_ops *ops, struct ftrace_hash *old_hash, struct ftrace_hash *new_hash) { /* Update rec->flags */ do_for_each_ftrace_rec(pg, rec) { 遍历所有插桩点,是否需要过滤掉,打上对应的标记。 } while_for_each_ftrace_rec(); } ftrace modify all code 如果要更新入口函数,标志设置为 FTRACE_UPDATE_CALLS;如果要更新跟踪函数,标志设置为FTRACE_UPDATE_TRACE_FUNC。如果使能了ftrace gragh,则标志设置为FTRACE_START_FUNC_RET。 void ftrace_modify_all_code(int command) { int update = command & FTRACE_UPDATE_TRACE_FUNC; int mod_flags = 0; int err = 0; if (update) { err = update_ftrace_func(ftrace_ops_list_func); if (FTRACE_WARN_ON(err)) return; } ① 先将跟踪函数替换为ftrace_ops_list_func。 if (command & FTRACE_UPDATE_CALLS) ftrace_replace_code(mod_flags | FTRACE_MODIFY_ENABLE_FL); else if (command & FTRACE_DISABLE_CALLS) ftrace_replace_code(mod_flags); ②更新入口函数 if (update && ftrace_trace_function != ftrace_ops_list_func) { function_trace_op = set_function_trace_op; smp_wmb(); /* If irqs are disabled, we are in stop machine */ if (!irqs_disabled()) smp_call_function(ftrace_sync_ipi, NULL, 1); err = update_ftrace_func(ftrace_trace_function); if (FTRACE_WARN_ON(err)) return; } ③ 判断ftrace_trace_function != ftrace_ops_list_func,则重新将跟踪函数更新为ftrace_trace_function 。 if (command & FTRACE_START_FUNC_RET) err = ftrace_enable_ftrace_graph_caller(); else if (command & FTRACE_STOP_FUNC_RET) err = ftrace_disable_ftrace_graph_caller(); 更新跟踪函数 static int update_ftrace_func(ftrace_func_t func) ftrace_update_ftrace_func(ftrace_func_t func) int ret = __ftrace_modify_call((unsigned long)&ftrace_call, (unsigned long)func, true, true); if (!ret) { ret = __ftrace_modify_call((unsigned long)&ftrace_regs_call, (unsigned long)func, true, true); static int __ftrace_modify_call(unsigned long hook_pos, unsigned long target, bool enable, bool ra) { unsigned int call[2]; unsigned int nops[2] = {NOP4, NOP4}; if (ra) make_call_ra(hook_pos, target, call); else make_call_t0(hook_pos, target, call); 计算跟踪函数的指令,修改地址ftrace_call或ftrace_regs_call处的跳转地址,默认是ftrace_stub,即完成了ftrace_call标签处的跳转替换,跟踪函数替换完成。 /* Replace the auipc-jalr pair at once. Return -EPERM on write error. */ if (patch_text_nosync ((void *)hook_pos, enable ? call : nops, MCOUNT_INSN_SIZE)) return -EPERM; patch_text_nosync函数在3.4.4章节有简述,这里就不再重复。 return 0; } 更新入口函数 void __weak ftrace_replace_code(int mod_flags) { struct dyn_ftrace *rec; struct ftrace_page *pg; bool enable = mod_flags & FTRACE_MODIFY_ENABLE_FL; int schedulable = mod_flags & FTRACE_MODIFY_MAY_SLEEP_FL; int failed; if (unlikely(ftrace_disabled)) return; ① 遍历每个入口函数的,获取对应的dyn_ftrace实例。 do_for_each_ftrace_rec(pg, rec) { ② 如果函数入口不需要更新,则循环继续(判断是否设置FTRACE_FL_DISABLED) if (skip_record(rec)) continue; failed = __ftrace_replace_code(rec, enable); ③ 将函数入口地址替换(默认为nop) if (failed) { ftrace_bug(failed, rec); /* Stop processing */ return; } if (schedulable) cond_resched(); } while_for_each_ftrace_rec(); } static int __ftrace_replace_code(struct dyn_ftrace *rec, bool enable) { unsigned long ftrace_old_addr; unsigned long ftrace_addr; int ret; ftrace_addr = ftrace_get_addr_new(rec); ① 获取要在函数入口要插桩点的函数地址。返回结果有有以下几种情况: - FTRACE_FL_DIRECT: 在direct_functions中获取(用户自定义?) - FTRACE_FL_TRAMP: 跳板函数? - FTRACE_FL_REGS:FTRACE_REGS_ADDR,默认为ftrace_regs_caller - 默认: FTRACE_ADDR ,默认为ftrace_caller /* This needs to be done before we call ftrace_update_record */ ftrace_old_addr = ftrace_get_addr_curr(rec); ret = ftrace_update_record(rec, enable); ftrace_bug_type = FTRACE_BUG_UNKNOWN; switch (ret) { case FTRACE_UPDATE_IGNORE: return 0; case FTRACE_UPDATE_MAKE_CALL: ftrace_bug_type = FTRACE_BUG_CALL; return ftrace_make_call(rec, ftrace_addr); case FTRACE_UPDATE_MAKE_NOP: ftrace_bug_type = FTRACE_BUG_NOP; return ftrace_make_nop(NULL, rec, ftrace_old_addr); case FTRACE_UPDATE_MODIFY_CALL: ftrace_bug_type = FTRACE_BUG_UPDATE; return ftrace_modify_call(rec, ftrace_old_addr, ftrace_addr); } ② 将入口函数的桩点替换为指定标签函数。 return -1; /* unknown ftrace bug */ } 总结 本章节,我们重点分析了function tracer使能后的实现过程,分析了如何将函数入口替换为ftrace_caller,分析了ftrace_caller中ftrace_call标签处如何被替换成跳转到ftrace_trace_function。整个ftrace动态过程主要实现了以下功能 - 能够指定内核函数入口进行指令替换,使其跳转到ftrace_caller。 - 能够对跟踪函数进行更新,使指定的跟踪函数能够被调用。 在动态函数的跟踪分析过程中,register_ftrace_function和ftrace_set_filter这两个函数至关重要,这两个函数使能function tracer的时候会调用并触发指令替换和跟踪函数更新动作。同时这两个函数也是接口,用户可以通过调用这两个函数实现自己的tracer。 /** * register_ftrace_function - register a function for profiling * @ops: ops structure that holds the function for profiling. * * Register a function to be called by all functions in the * kernel. * * Note: @ops->func and all the functions it calls must be labeled * with \\\"notrace\\\", otherwise it will go into a * recursive loop. */ int register_ftrace_function(struct ftrace_ops *ops) { int ret; lock_direct_mutex(); ret = prepare_direct_functions_for_ipmodify(ops); if (ret < 0) goto out_unlock; ret = register_ftrace_function_nolock(ops); out_unlock: unlock_direct_mutex(); return ret; } EXPORT_SYMBOL_GPL(register_ftrace_function); register_ftrace_function是一个通用的注册函数,传递的参数struct ftrace_ops *ops即想要在函数入口插入跟踪的函数,无论是function tracer、irqsoff、fprobes、trace_event等函数都是调用该函数进行注册插桩,也可以自定义自己想要插桩的函数。 从原理上来讲,使能了-fpatchable-function-entry编译参数后,入口函数处就占了坑位,默认是先用nop指令填充,那么可以在运行阶段想换成啥就换成啥。
  • ftrace的使用

    ftrace的使用

    tracer irqsoff 当关闭中断时,CPU就无法响应中断了(NMI和SMI除外),无法响应外部事件做出反应。这会阻止定时器触发或鼠标中断触发,导致系统延迟。 irqsoff跟踪器跟踪中断被禁用的时间,当达到新的最大延迟时,跟踪器会保存导致该延迟点的跟踪,一边每次达到新的最大值,旧的保存的跟踪会被丢弃,新的跟踪会被保存。如果要重置最大值,用echo 0写到tracing_max_latency中。 # echo 0 > options/function-trace # echo irqsoff > current_tracer # echo 1 > tracing_on # echo 0 > tracing_max_latency # ls -ltr [...] # echo 0 > tracing_on # cat trace 上图示例可以最大延迟为3603us,在default_idle_call和__do_softirq中禁用了中断,主要看=> started at:default_idle_call和=> ended at: __do_softirq。表示关中断的开始函数和开中断的函数。 上面示例中,将funciton-trace关掉了,没有启用此tracer过程的函数跟踪。如果设置function-trace,就会有很多的打印,会将此过程中的函数执行trace打印出来。echo 1 > options/function-trace。 如果想要以函数图调用的方式打印,那么with echo 1 > options/display-graph。 有时候cat trace是空的,可能设置的追踪阈值太长,可以修改短一点。 echo 5 > tracing_thresh # 设置阈值为 5μs function function为函数跟踪器,可以从调试文件系统启动函数跟踪器,echo function > current_tracer。 # echo function > current_tracer # echo 1 > tracing_on # usleep 1 # echo 0 > tracing_on # cat trace 需要注意的是,function tracer使用环形缓冲区来存储上述数据,最新数据可能会覆盖最旧的数据,有时使用echo 来停止跟踪器是不够的,因为跟踪可能会覆盖您想要记录的数据。因此最好直接从程序中禁用跟踪,允许您在到达你感兴趣的部分时停止跟踪,如果要从C程序禁用跟踪,可以使用类似下面代码; int trace_fd; [...] int main(int argc, char *argv[]) { [...] trace_fd = open(tracing_file("tracing_on"), O_WRONLY); [...] if (condition_hit()) { write(trace_fd, "0", 1); } [...] } 单个线程的跟踪, # cat set_ftrace_pid no pid # echo 3111 > set_ftrace_pid # cat set_ftrace_pid 3111 # echo function > current_tracer # cat trace | head 如果想要trace一个函数在启动运行时,可以使用下面的示例程序。 #include <stdio.h> #include <stdlib.h> #include <sys/types.h> #include <sys/stat.h> #include <fcntl.h> #include <unistd.h> #include <string.h> #define _STR(x) #x #define STR(x) _STR(x) #define MAX_PATH 256 const char *find_tracefs(void) { static char tracefs[MAX_PATH+1]; static int tracefs_found; char type[100]; FILE *fp; if (tracefs_found) return tracefs; if ((fp = fopen("/proc/mounts","r")) == NULL) { perror("/proc/mounts"); return NULL; } while (fscanf(fp, "%*s %" STR(MAX_PATH) "s %99s %*s %*d %*d\\n", tracefs, type) == 2) { if (strcmp(type, "tracefs") == 0) break; } fclose(fp); if (strcmp(type, "tracefs") != 0) { fprintf(stderr, "tracefs not mounted"); return NULL; } strcat(tracefs, "/tracing/"); tracefs_found = 1; return tracefs; } const char *tracing_file(const char *file_name) { static char trace_file[MAX_PATH+1]; snprintf(trace_file, MAX_PATH, "%s/%s", find_tracefs(), file_name); return trace_file; } int main (int argc, char **argv) { if (argc < 1) exit(-1); if (fork() > 0) { int fd, ffd; char line[64]; int s; ffd = open(tracing_file("current_tracer"), O_WRONLY); if (ffd < 0) exit(-1); write(ffd, "nop", 3); fd = open(tracing_file("set_ftrace_pid"), O_WRONLY); s = sprintf(line, "%d\\n", getpid()); write(fd, line, s); write(ffd, "function", 8); close(fd); close(ffd); execvp(argv[1], argv+1); } return 0; } 当然也可以使用简单的脚步来实现 Or this simple script! :: #!/bin/bash tracefs=`sed -ne \'s/^tracefs \\(.*\\) tracefs.*/\\1/p\' /proc/mounts` echo 0 > $tracefs/tracing_on echo $$ > $tracefs/set_ftrace_pid echo function > $tracefs/current_tracer echo 1 > $tracefs/tracing_on exec \"$@\" function graph tracer function graph tracer与function tracer类似,不同之处在于它会在函数进入和退出时对其进行探测,这是通过每个task_struct中使用动态分配的返回地址堆栈来实现的。在函数进入时,跟踪器会覆盖跟踪每个函数的返回地址以设置自定义探测器,因此原始返回地址存储在task_struct中的返回地址堆栈中。在函数两端进行探测可实现特殊功能,例如:测量函数的执行时间,拥有可靠调用堆栈来绘制函数的调用图。这种跟踪器在以下几种情况很有用: 找到奇怪内核行为的原因,详细了解任何区域发生的情况。 遇到奇怪的延迟,但很难找到根源。 快速找到特定函数的调用路径。 窥视正在运行的内核并查看发生了什么。 有几列是可以动态启用和禁止的。 - cpu number是默认会启动函数执行的cpu编号,有时候最好只跟踪一个cpu(tracing_cpu_mask),否则在cpu跟踪是,会看到无须的函数调用。隐藏cpu: echo nofuncgraph-cpu > trace_options。 - duration表示函数执行的时间,会显示在函数结束括号行上。如果是叶函数,则显示在当前函数的同一行。如果要关掉,则echo nofuncgraph-duration > trace_options。 如果函数的开头不在跟踪缓冲区,则函数名称可以显示到函数的右括号后面,可以echo funcgraph-tail > trace_options进行使能。 dynamic ftrace 如果使能了CONFIG_DYNAMIC_FTRACE,则在禁用函数跟踪时,系统将几乎不产生任何开销。其工作原理是使能了gcc的-pg参数会自动在内核的函数开头插桩mcount函数(与架构有关系,gcc 4.6版本开始,x86架构添加mfentry,它调用“fentry”而不是“mcount”)。 在编译时,每个C文件对象通过recordmcount程序(位于脚本目录)运行,该程序将解析C对象的ELF标头,查找.text部分中调用mcount的所有位置。 NOTE:注意的是并非所有的section都被跟踪,可以通过notrace或其他办法来不让其跟踪,并且不会跟踪所有的内联函数,可以cat available_filter_functions节点来查看可以跟踪那些函数。 创建一个“__mcount_loc”的段(section),该段中记录了所有包含在.text中对mcount调用点的引用位置。最后__mcount_loc在链接时统一链接到一个__mcount_loc中。 具体的过程如上图所示,在系统启动时,初始化SMP之前,动态ftrace代码会扫描此表并将所有位置更新为替换为nop指令,同时还会记录位置,这些位置被添加到available_filter_functions表中。在模块加载和执行之前进行处理,卸载模块时,它还会从ftrace函数列表中删除其函数。 在启动动态跟踪后,修改函数跟踪点的过程取决于具体的arch。修改函数跟踪点的方法时要修改位置放置一个断点,同步所有的CPU。接着修改其指令,同步给所有的CPU再把断点移除。通过这样动态的方式,可以做到有选择的跟踪指定函数,其他不想跟踪的函数就的位置执行的是nop指令,不至于影响性能。 内核中使用两个文件用于启动和禁用指定的函数跟踪分别是set_ftrace_filter和set_ftrace_notrace。可以通过available_filter_functions来查看跟踪的函数。 # echo sys_nanosleep hrtimer_interrupt > set_ftrace_filter # echo function > current_tracer # echo 1 > tracing_on # usleep 1 # echo 0 > tracing_on # cat trace 设置set_ftrace_filter可以使用通配符匹配,示例如下: ``<match>*`` :匹配<match>开头的函数 ``*<match>``:匹配<match>结尾的函数 ``*<match>*``:匹配其中包含<match>的函数 ``<match1>*<match2>``:匹配<match1>开头并以<match2>结尾的函数 设置set_ftrace_filter接口支持过滤命令,格式为\:\:\ -mod: 启用每个模块的功能过滤,如只需要ext3模块中的write*功能 echo \'write*:mod:ext3\' > set_ftrace_filter -traceon/traceoff: 指定函数打开和关闭时跟踪,参数确定跟踪系统打开和关闭的次数,如果为指定,则没有限制,例如在前5此遇到错误时禁止跟踪 echo \'__schedule_bug:traceoff:5\' > set_ftrace_filter dynamic ftrace with function graph tracer 上面解释了function tracer和function graph tracer,但有些特殊功能只在function graph tracer中可用。如果跟踪一个函数及其子函数,只需要函数将其名称写到set_graph_function中。 echo function_graph > current_tracer echo __do_fault > set_graph_function echo 1 > tracing_on ... echo 0 > tracing_on other ftrace有一个总开关,/proc/sys/kernel/ftrace_enabled,向其写0或1表示关闭和使能,默认是开启的状态。更多细节参考:Documentation/trace/ftrace.rst。 events使用 sched_switch sched_switch是静态Tracepoint事件追踪,下面是示例 echo 1 > /sys//kernel/debug/tracing/events/sched/sched_switch/enable # 使能sched_switch echo 'prev_pid == 1162 || next_pid == 1244' > /sys/kernel/debug/tracing/events/sched/sched_switch/filter #设置sched_switch 事件的过滤条件,使得只有当进程ID为1162的进程 #切换为进程ID为1244的进程时,才会记录这个事件,否则打印太多了 echo "" > /sys/kernel/debug/tracing/trace # 清除trace buffer echo 1 > /sys/kernel/debug/tracing/tracing_on # 开始tracing cat /sys/kernel/debug/tracing/trace # 查看结果 运行结果如下: # tracer: nop # # nop latency trace v1.1.5 on 5.15.147 # -------------------------------------------------------------------- # latency: 0 us, #15/15, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4) # ----------------- # | task: -0 (uid:0 nice:0 policy:0 rt_prio:0) # ----------------- # # _------=> CPU# # / _-----=> irqs-off # | / _----=> need-resched # || / _---=> hardirq/softirq # ||| / _--=> preempt-depth # |||| / _-=> migrate-disable # ||||| / delay # cmd pid |||||| time | caller # \ / |||||| \ | / <idle>-0 0d..2. 95713us$: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=wpa_supplicant next_pid=1244 next_prio=120 <idle>-0 0d..2. 10104901us$: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=wpa_supplicant next_pid=1244 next_prio=120 <idle>-0 0d..2. 20114087us$: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=wpa_supplicant next_pid=1244 next_prio=120 wifi_dae-1162 2d..2. 25998599us!: sched_switch: prev_comm=wifi_daemon prev_pid=1162 prev_prio=120 prev_state=R+ ==> next_comm=sugov:0 next_pid=88 next_prio=-1 wifi_dae-1162 2d..2. 25999269us!: sched_switch: prev_comm=wifi_daemon prev_pid=1162 prev_prio=120 prev_state=R ==> next_comm=sugov:0 next_pid=88 next_prio=-1 wifi_dae-1162 2d..2. 25999412us!: sched_switch: prev_comm=wifi_daemon prev_pid=1162 prev_prio=120 prev_state=R+ ==> next_comm=sugov:0 next_pid=88 next_prio=-1 <idle>-0 0d..2. 25999584us!: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=wpa_supplicant next_pid=1244 next_prio=120 wifi_dae-1162 3d..2. 26000075us*: sched_switch: prev_comm=wifi_daemon prev_pid=1162 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120 <idle>-0 0d..2. 26012127us!: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=wpa_supplicant next_pid=1244 next_prio=120 <idle>-0 0d..2. 26012552us!: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=wpa_supplicant next_pid=1244 next_prio=120 logread-495 0d..2. 26013054us$: sched_switch: prev_comm=logread prev_pid=495 prev_prio=120 prev_state=S ==> next_comm=wpa_supplicant next_pid=1244 next_prio=120 rcu_pree-14 3d..2. 27564266us#: sched_switch: prev_comm=rcu_preempt prev_pid=14 prev_prio=120 prev_state=I ==> next_comm=wpa_supplicant next_pid=1244 next_prio=120 <...>-1163 3d..2. 27567664us!: sched_switch: prev_comm=wifi_daemon prev_pid=1163 prev_prio=120 prev_state=S ==> next_comm=wpa_supplicant next_pid=1244 next_prio=120 <...>-1163 3d..2. 27568473us$: sched_switch: prev_comm=wifi_daemon prev_pid=1163 prev_prio=120 prev_state=S ==> next_comm=wpa_supplicant next_pid=1244 next_prio=120 <idle>-0 3d..2. 30116102us : sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=wpa_supplicant next_pid=1244 next_prio=120 从上面的打印结果可以看到,只会打印下一个调度进程为next_pid=1244或者上一个调度进程为prev_pid=1162的两个进程。 irq echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/enable echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/enable # 使能最终中断的进入和退出追踪。 echo "irq == 62" > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/filter echo "irq == 62" > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/filter #设置irq的过滤,要过滤的中断号可以通过cat /proc/interrupts获取。 echo "" > /sys/kernel/debug/tracing/trace # 清除trace buffer echo 1 > /sys/kernel/debug/tracing/tracing_on # 开始tracing cat /sys/kernel/debug/tracing/trace # 查看结果 /sys/kernel/debug/tracing# cat trace # tracer: nop # # entries-in-buffer/entries-written: 354/354 #P:4 # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / _-=> migrate-disable # |||| / delay # TASK-PID CPU# ||||| TIMESTAMP FUNCTION # | | | ||||| | | sugov:0-86 [000] d.h.. 1306.666839: irq_handler_entry: irq=62 name=rwnx_hostwake_irq sugov:0-86 [000] d.h.. 1306.666847: irq_handler_exit: irq=62 ret=handled sugov:0-86 [000] d.h.. 1306.667226: irq_handler_entry: irq=62 name=rwnx_hostwake_irq sugov:0-86 [000] d.h.. 1306.667229: irq_handler_exit: irq=62 ret=handled <idle>-0 [000] d.h1. 1306.673856: irq_handler_entry: irq=62 name=rwnx_hostwake_irq <idle>-0 [000] d.h1. 1306.673864: irq_handler_exit: irq=62 ret=handled <idle>-0 [000] d.h1. 1306.722395: irq_handler_entry: irq=62 name=rwnx_hostwake_irq <idle>-0 [000] d.h1. 1306.722414: irq_handler_exit: irq=62 ret=handled <idle>-0 [000] dNh1. 1306.722680: irq_handler_entry: irq=62 name=rwnx_hostwake_irq <idle>-0 [000] dNh1. 1306.722688: irq_handler_exit: irq=62 ret=handled sugov:0-86 [000] d.h1. 1306.722773: irq_handler_entry: irq=62 name=rwnx_hostwake_irq sugov:0-86 [000] d.h1. 1306.722778: irq_handler_exit: irq=62 ret=handled <idle>-0 [000] d.h1. 1306.730310: irq_handler_entry: irq=62 name=rwnx_hostwake_irq <idle>-0 [000] d.h1. 1306.730313: irq_handler_exit: irq=62 ret=handled sugov:0-86 [000] d.h1. 1306.734280: irq_handler_entry: irq=62 name=rwnx_hostwake_irq sugov:0-86 [000] d.h1. 1306.734292: irq_handler_exit: irq=62 ret=handled <idle>-0 [000] d.h1. 1306.734520: irq_handler_entry: irq=62 name=rwnx_hostwake_irq <idle>-0 [000] d.h1. 1306.734526: irq_handler_exit: irq=62 ret=handled <idle>-0 [000] d.h1. 1306.734717: irq_handler_entry: irq=62 name=rwnx_hostwake_irq <idle>-0 [000] d.h1. 1306.734722: irq_handler_exit: irq=62 ret=handled <idle>-0 [000] dNh1. 1306.757440: irq_handler_entry: irq=62 name=rwnx_hostwake_irq <idle>-0 [000] dNh1. 1306.757453: irq_handler_exit: irq=62 ret=handled sugov:0-86 [000] d.h1. 1306.757530: irq_handler_entry: irq=62 name=rwnx_hostwake_irq sugov:0-86 [000] d.h1. 1306.757536: irq_handler_exit: irq=62 ret=handled <idle>-0 [000] d.h1. 1306.792327: irq_handler_entry: irq=62 name=rwnx_hostwake_irq <idle>-0 [000] d.h1. 1306.792340: irq_handler_exit: irq=62 ret=handled <idle>-0 [000] dNh1. 1306.792629: irq_handler_entry: irq=62 name=rwnx_hostwake_irq <idle>-0 [000] dNh1. 1306.792636: irq_handler_exit: irq=62 ret=handled sugov:0-86 [000] d.h.. 1306.792811: irq_handler_entry: irq=62 name=rwnx_hostwake_irq sugov:0-86 [000] d.h.. 1306.792817: irq_handler_exit: irq=62 ret=handled <idle>-0 [000] d.h1. 1306.821387: irq_handler_entry: irq=62 name=rwnx_hostwake_irq <idle>-0 [000] d.h1. 1306.821407: irq_handler_exit: irq=62 ret=handled sugov:0-86 [000] d.h.. 1306.821615: irq_handler_entry: irq=62 name=rwnx_hostwake_irq sugov:0-86 [000] d.h.. 1306.821620: irq_handler_exit: irq=62 ret=handled irqsoff和events/irq有什么区别? irqsoff是统计中断关闭时间,而events/irq是主要用于记录中断处理的活动,包括进入中断、退出中断等等。 小结 # 启动sched_switch追踪可以有一下3种方式。 echo sched:sched_switch >> /sys/kernel/debug/tracing/set_event echo sched_switch >> /sys/kernel/debug/tracing/set_event echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable # 可以通过cat set_event来查看追踪的event cat /sys/kernel/debug/tracing/set_event # 也可以通过设置set_event_pid来过滤进程 echo 1244 > /sys/kernel/debug/tracing/set_event_pid # 可以cat trace_pipe来实时观察追踪信息 cat /sys/kernel/debug/tracing/trace_pipe #如果要清空设置的过滤,写0, echo 0 > /events/irq/irq_handler_exit/filter 总结: tracer有function/graph等追踪器,没有设置过滤的话就是全局的。而event是在特定函数出入口统计跟踪,一般系统有内置的模块比如irq,sched_switch等。 tracing_on是总开关,通过使能1或0来开关。 trace是ftrace跟踪系统的主输出文件,用于记录所有的跟踪事件,但是会保留历史记录信息,不需要的话需要echo "" > trace 清空。trace_pipe是一个实时跟踪输出文件,而不会保存历史数据,它提供了实时的数据流。 event和tracer可以同时使用。
  • ftrace-概述

    ftrace-概述

    ftrace是一个内部跟踪器,用于帮助开发人员查找内核正在发生的事情,它可用于调试或分析用户空间之外发生的延迟和性能问题。ftrace从名称上看是function trace,函数跟踪器,但它实际并不限制函数跟踪,而是多个不同跟踪实用程序的框架。延迟跟踪可以检查在禁用和启用中断之间发生的情况,以及抢占和从唤醒任务到实际运行任务的时间。 ftrace最常见的用途之一是用于事件跟踪(event tracing),整个内核有数百个静态事件点,可以通过tracefs文件系统启用这些事件点,以查看内核某些部分正在发生的事件。 ftrace使用tracefs文件系统来保存控制文件以及显示输出的文件,当tracefs配置到内核中时,将创建目录/sys/kernel/tracing。要挂载此目录,可以将其添加到/etc/fstab文件中。 tracefs /sys/kernel/tracing tracefs defaults 0 0 当然也可以进行命令挂载:mount -t tracefs nodev /sys/kernel/tracing。需要注意的是在4.1内核之前,所有的ftrace跟踪控制文件都在debugfs文件系统中,该文件系统位于/sys/kernel/debug/tracing,因此为了向后兼容,在挂载debugfs文件系统时,tracefs就会自动挂载/sys/kernel/debug/tracing。 挂载tracefs后,可以访问ftrace的控制和输出文件,以下是关键文件节点: current_tracer:用于设置或显示当前配置的跟踪器,更改当前跟踪器会清除环形缓冲区内容。 available_tracers:保存已经编译到内核中的不同类型跟踪器,该类型用于配置上面的current_tracer。 tracing_on:用于设置是否开启对跟踪环形缓冲区的写入(0/1启停),需要注意的时即使禁止环形缓冲区的写入,跟踪开销可能仍然在发生。每次写current_tracer后,tracing_on会默认设置0。 events:这个目录包含了内核中可用的跟踪事件列表。它定义了各种内核事件,比如 sched_switch(任务调度切换)、irq_handler_entry(中断处理入口)等。通过这些事件,可以捕获并分析内核的各种活动。 trace_options:用于控制trace输出文件的显示数据量,还可以更改堆栈跟踪、时间戳等。 options:这是一个目录,包含每个可用跟踪选项的文件,也可以通过具有选项名称的 set_ftrace_filter:用于dynamic ftrace,代码被动态修改(text重写)以禁用对函数分析器(mcount)的调用,这样就可以在几乎不影响性能的情况下配置跟踪。设置函数跟踪过滤后,跟踪器就只会跟踪设置的函数。 set_ftrace_notrace:与set_ftrace_filter相反,添加的函数不会被跟踪。 set_ftrace_pid:函数跟踪器只跟踪PID列再次文件中的线程。如果设置了”function-fork”选项,则当PID列在此文件中的任务分叉时,子任务的PID将自动添加到此文件中,并且函数跟踪器也会跟踪子任务。 set_event_pid:让event只跟踪PID列在此文件的任务。 set_graph_function:此文件中列出的函数将导致函数图跟踪器仅跟踪这些函数及其调用的函数。需要注意的时set_ftrace_filter/set_ftrace_notrace仍然会影响正在跟踪的函数,即function tracer和graph tracer叠加。 available_filter_functions:列出ftrace已处理并可以跟踪的函数。即上面set_ftrace_filter/set_graph_function设置的函数名称。 tracers Tracer是 Ftrace 预设的多种内核行为追踪模块,通过不同 tracer 可观测特定类型的内核事件。列出当前常用的跟踪器,可以通过cat available_tracers获取当前支持那些跟踪器。 function:函数调用跟踪器,用于跟踪所有内核函数。 function_graph:与函数跟踪器类似,不同之处在于函数跟踪器在函数入口出探测函数,而函数图跟踪器在函数入口和出口处跟踪进行跟踪,然后,它能够绘制类似C代码的函数调用图。 blk:块跟踪器,blktrace应用程序使用的跟踪器。 hwlat:硬件延迟跟踪器,用于检测硬件是否产生任何延迟。 irqsoff:跟踪禁用中断区域并保存最大延迟最长的跟踪。当中断被禁止时,系统无法响应外部事件,比如鼠标和键盘,时钟也无法产生tick中断,这也意味着系统响应延迟,irqsoff这个tracer能够跟踪并记录内核中哪些函数禁止了中断,对于其中中断禁止时间最长的,irqsoff将在Log文件中第一行标记出来,从而使开发者可以迅速定位造成响应延迟的罪魁祸首 preemptoff:与irqsoff类型,但跟踪并记录禁用抢占的时间量。 preemptirqsoff:与irqsoff和preemptoff类似,但跟踪并记录禁用irqs或抢占的最大时间。 wakeup:跟踪并记录在唤醒最高优先级任务后对其进展调度所需要的最大延迟。 wakeup_rt:跟踪并记录仅RT任务所需要的最大延迟。 wakeup_dl:跟踪并记录SCHED_DEADLINE任务所需的最大延迟。 nop:不跟踪任务内容。 以下是使用tracer的典型示例,输出格式如下 上面是一个function tracer的输出示例,打印的标题包含跟踪器的名称。在本例中,tracer是function,entries-in-buffer表示缓冲区的事件数,entries-written是写入的数目,差异是由于缓冲区填满而丢失的数据。标题解释了event内容。第一行内容表示Task 为bash,PID为1977,运作在CPU0上,运行的时间戳格式为\.\,表示进入该函数的时间。被跟踪的函数是sys_close,以及调用此函数的父函数为system_call_fastpath。 下面是irqsoff tracer的示例,输出格式如下: 上图表示tracer是irqsoff,给出了irqsoff latency trace的版本为v1.1.5运行待3.8.0内核上。跟踪的条目和总数均为4个,最大的延时是259us。VP,KP,SP,HP始终为0用于后续使用,#P表示当前在线的CPU数量。task是延迟发生时正在运行的进程。导致延迟最大的启动和停止函数(分别禁用和启动中断的函数)是__lock_task_sighand(关中断)和_raw_spin_unlock_irqrestore(开中断)。 下面接着再来解释一条trace的内容。 cmd:跟踪中进程的名称 pid:该进程的pid CPU#:进程正在运行的CPU irq-soff: “d”表示中断被禁用,否则为 “.”。如果架构不支持irq标志变量,这里为打印“X”。 need-resched: “N”表示TIF_NEED_RESCHED和“PREEMPT_NEED_RESCHED”都设置了。“n”仅设置了TIF_NEED_RESCHED,“p”仅设置了PREEMPT_NEED_RESCHED。否则为“.”。 hardirq/softirq:当前是否发生硬件中断、软件中断,“Z”表示NMI发生在hardirq中,“z”表示NMI正在运行,“H”硬件中断发生在软中断中。“h”硬件中断正在运行,“s”软解中断正在运行。“.”正常的上下文。 preempt-depth: 被抢占的调用深度。 time:相对于tracer开始的时间戳,这里是相对时间,表示tracer过程中中断被关闭的时间。 delay:延时的标号,“$”表示大于1S,“@”表示大于100ms,“*”表示大于10ms,“#”表示大于1000us,“!”表示大于100us,“+”表示大于10us,“ ”表示小于等于10us。 events events 是 ftrace 的另一种跟踪机制,允许跟踪内核中的特定事件。Events是基于内核静态埋点(Tracepoints)或动态探针(Kprobes)的细粒度追踪机制。这些事件可以是内核中发生的各种操作,如任务调度、系统调用、内存分配、中断等。与tracer不同,events跟踪的是特定的内核事件。可以通过cat available_events或者ll /sys/kernel/tracing/events查看当前打开了哪些events。 root:/sys/kernel/debug/tracing/events# ls alarmtimer ipi rpm asoc irq rtc block jbd2 sched bridge kmem scsi cfg80211 kyber signal cfg802154 l2tp skb cgroup mac80211 smbus clk mac802154 sock cma migrate spi compaction mmap sunxi_ccu cpuhp mmap_lock sunxi_uart dev mmc sunxi_udc devfreq module swiotlb dma_fence napi syscalls enable neigh task error_report net tcp ext4 netlink thermal fib oom thermal_power_allocator fib6 page_isolation timer filelock pagemap tipc filemap percpu udp ftrace power v4l2 gadget preemptirq vb2 gpio printk vmscan header_event pwm vsock header_page qdisc workqueue i2c raw_syscalls writeback initcall rcu xdp iomap regmap iommu regulator trace_options trace_options文件用户控制trace输出的打印内容,或者控制trace。要查看可用的内容,可以使用cat trace_opstions。 如果要禁用其中一个选项,可以在选项的加上前缀no,如要禁用print-parent,echo noprint-parent > trace_options。如果要重新使能去掉no前缀再写入即可。 print-parent:在珊瑚跟踪过程中,显示调用函数以及被跟踪的函数。 sys-offset:不仅显示函数名称,还要显示函数中的偏移量。 sym-addr:显示函数地址以及函数名称。 irq-info:显示中断、抢占技术、调度的数据。 function-trace:默认启用,表示延迟跟踪器将启用函数跟踪,当禁用此选项是,延迟跟踪器不会跟踪函数。 function-fork:跟踪任务的子任务。 display-gragh:设置后,延迟跟踪器(irqsoff,wakeup等)将使用函数图跟踪而不是函数跟踪。 stacktrace:设置后,在记录任何跟踪事件都会记录堆栈跟踪。 由于function_graph tracer输出略不同,因此它有自己的选项来控制显示内容,在options/目录下。 funcgraph-cpu:设置后,将显示跟踪发生的CPU编号。 funcgragh-irqs:禁用后,不会跟踪中断内部发生的函数。
\t