Linux ftrace的使用(1)

作者 by adtxl / 2022-04-28 / 暂无评论 / 439 个足迹

整理自《奔跑吧 Linux内核,张天飞著》

1. 简介

ftrace最早出现在Linux 2.6.27版本中,其设计目标简单,基于静态代码插桩技术,不需要用户通过额外的编程来定义trace行为。静态代码插桩技术比较可靠,不会因为用户的不当使用而导致内核崩溃。ftrace的名字由function trace而来,利用gcc编译器的profile特性在所有函数入口处添加了一段插桩(stub)代码,ftrace重载这段代码来实现trace功能。gcc编译器的"-pg"选项会在每个函数入口处加入mcount的调用代码,原本mcount有libc实现,因为内核不会链接libc库,因此ftrace编写了自己的mcount stub函数。

在使用ftrace前,需要确保内核配置编译了其配置选项。

CONFIG_FTRACE=y
CONFIG_HAVE_FUNCTION_TRACER=y
CONFIG_HAVE_FUNCTION_GRAPH_TRACER=y
CONFIG_HAVE_DYNAMIC_FTRACE=y
CONFIG_FUNCTION_TRACER=y
CONFIG_IRQSOFF_TRACER=y
CONFIG_SCHED_TRACER=y
CONFIG_ENABLE_DEFAULT_TRACERS=y
CONFIG_FTRACE_SYSCALLS=y
CONFIG_PREEMPT_TRACER=y

ftrace相关配置选项比较多,针对不同的跟踪器有各自对应的配置选项。ftrace通过debugfs文件系统向用户空间提供访问接口,因此需要修改系统启动时挂载debugfs,可以修改系统的/etc/fstab文件或手动挂载。

mount -t debugfs debugfs /sys/kernel/debug

在/sys/kernel/debug/tracing目录下提供了各种跟踪器(tracer)和事件(event),一些常用的选项如下:

  • avaliable_tracers: 列出当前系统支持的跟踪器。
  • avalibale_events: 列出当前系统支持的event事件
  • current_tracer: 设置和显示当前正在使用的跟踪器。使用echo命令可以把跟踪器的名字写入该文件,即可以切换不同的跟踪器。默认为nop,即不做任何跟踪操作。
  • trace: 读取跟踪信息。通过cat命令查看ftrace记录下来的跟踪信息。
  • tracing_on: 用于开始或暂停跟踪
  • trace_options: 设置ftrace的一些相关选项

ftrace当前包含多个跟踪器,很方便用户用来跟踪不同类型的信息,例如进程睡眠唤醒、抢占延迟的信息。查看avaliable_tracers可以知道当前系统支持哪些跟踪器,如果系统支持的跟踪器上没有用户想要的,那就必须在配置内核时自行打开,然后重新编译内核。常用的ftrace跟踪器如下:

  • nop:不跟踪任何信息。将nop写入current_tracer文件可以清空之前收集到的跟踪信息。
  • function:跟踪内核函数执行情况。
  • function_graph:可以显示类似C语言的函数调用关系图,比较直观
  • wakeup: 跟踪进程唤醒信息
  • irqsoff:跟踪关闭中断信息,并记录关闭的最长时长
  • preemptoff:跟踪关闭禁止抢占信息,并记录关闭的最长时长
  • preemptirqsoff:综合了irqoff和preemptoff两个功能
  • sched_switch:对内核中的进程调度活动进行跟踪

2. 跟踪器

2.1 irqs跟踪器

当中断被关闭(俗称关中断)了,CPU就不能响应其他的事件,如果这时有一个鼠标中断,要在下一次开中断时才能响应这个鼠标中断,这段延迟称为中断延迟。向current_tracer文件写入irqsoff字符串即可打开irqsoff来跟踪中断延迟。

# cd /sys/kernel/debug/tracing
# echo 0 > options/function-trace       // 关闭function-trace可以减少一些延迟
# echo irqsoff > current_tracer
# echo 1 > tracing_on
[...等一会...]
# echo 0 > tracing_on
# cat trace

下面是输出结果:
文件的开头显示了当前跟踪器为irqsoff,并且显示当前跟踪器的版本信息为v1.1.5,运行的内核版本为4.19.176。
显示当前最大的中断延迟是214微妙,跟踪条目和总共跟踪条目为4条,另外VP、KP、SP、HP值暂时没用,#P:4表示当前系统可用的CPU一共有4
个。
started at和ended at显示发生中断时的开始函数和结束函数。

# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 4.19.176
# --------------------------------------------------------------------
# latency: 214 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
#    -----------------
#    | task: AudioPlayback-2198 (uid:1000 nice:0 policy:0 rt_prio:0)
#    -----------------
#  => started at: schedule
#  => ended at:   finish_task_switch
#
#
#                  _------=> CPU#            
#                 / _-----=> irqs-off        
#                | / _----=> need-resched    
#                || / _---=> hardirq/softirq 
#                ||| / _--=> preempt-depth   
#                |||| /     delay            
#  cmd     pid   ||||| time  |   caller      
#     \   /      |||||  \    |   /         
RenderEn-2191    3d..1    1us!: __schedule <-schedule
AudioPla-2198    3d..2  210us : _raw_spin_unlock_irq <-finish_task_switch
AudioPla-2198    3d..2  217us+: tracer_hardirqs_on <-finish_task_switch
AudioPla-2198    3d..2  229us : <stack trace>
 => finish_task_switch
 => __schedule
 => schedule
 => do_nanosleep
 => hrtimer_nanosleep
 => __arm64_compat_sys_nanosleep
 => el0_svc_common.constprop.0
 => el0_svc_compat_handler
 => el0_svc_compat
  • irqs-off: "d"表示中断已经关闭
  • need_resched: "N"表示进程设置了TIF_NEED_RESCHED和PREEMPT_NEED_RESCHED标志位;"n"表示进程仅设置了TIF_NEED_RESCHED标志位;"p"表示进程仅设置了PREEMPT_NEED_RESCHED标志位
  • hardirq/softirq:"H"表示在一次软中断中发生了一个硬件中断;"h"表示硬件中断发生;"s"表示软中断;"."表示没有中断发生。
  • preempt-depth:表示抢占关闭的嵌套层级
  • time:表示时间戳。如果打开了latency-format选项,表示时间从开始跟踪算起,这是一个相对时间,方便开发者观察,否则使用系统绝对时间。
  • delay:用一些特殊符号来延迟的时间,方便开发者观察。"$"表示大于1秒,"#"表示大于1000微秒,"!"表示大于100微秒,"+"表示大于10微秒。

最后要说明的是,文件最开始显示中断延迟是210微秒。但是在<stack trace>里显示229微秒,这是因为在记录最大延迟信息时需要花费一些时间。

2.2 preemptoff跟踪器

todo

2.3 preemptirqsoff跟踪器

todo

2.4 function跟踪器

function跟踪器会记录当前系统运行过程中所有的函数。如果只想跟踪某个进程,可以使用set_ftrace_pid。

# cd /sys/kernel/debug/tracing
# cat set_ftrace_pid
no pid
# echo 5945 > set_ftrace_pid
# cat set_ftrace_pid
5748
# echo function > current_tracer
# echo 1 > tracing_on
[...等一会...]
# echo 0 > tracing_on
# cat trace

ftrace还支持一种更为直观的跟踪器叫function_graph,使用方法和function跟踪器类似。

# echo function_graph > current_tracer

# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 2)   9.140 us    |    } /* preempt_count_sub */
 2) + 27.300 us   |  } /* _raw_spin_unlock_irq */
 2)               |  _raw_spin_lock_irq() {
 2)               |    preempt_count_add() {
 2)   5.200 us    |      preempt_count_add.part.2();
 2) + 15.100 us   |    }
 2) + 30.160 us   |  }
 2)   4.820 us    |  rcu_jiffies_till_stall_check();
 2)               |  _raw_spin_unlock_irq() {
 2)   9.240 us    |    preempt_count_sub();
 2) + 24.460 us   |  }
 2)               |  _raw_spin_lock() {
 2)               |    preempt_count_add() {
 2)   8.460 us    |      preempt_count_add.part.2();
 2) + 24.640 us   |    }
 2) + 41.080 us   |  }
......

独特见解