泰晓科技 -- 聚焦 Linux - 追本溯源,见微知著!
网站地址:https://tinylab.org

泰晓RISC-V实验箱,转战RISC-V,开箱即用
请稍侯

Ftrace 基本用法

Liu Lichao 创作于 2021/02/24

By 法海 of [TinyLab.org][1] Jan 16, 2021

前言

计划撰写 Ftrace 系列文章,会描述 Ftrace 基本用法,进阶用法,trace-cmd 等前端工具。

本文是 Ftrace 系统文章第一篇: Ftrace 基本用法。

概述

Ftrace 是内核自带的调试工具,从久远的 2.6 内核就支持了,可以辅助定位内核问题。

从名字来看,ftrace = function trace,表示可以进行函数级 trace,随着发展,Ftrace 已经进化成通用的调试框架,可以实现多种 trace 目的。

根据官方文档,目前支持的 trace 类型:

  • function
  • function_graph
  • blk
  • hwlat
  • irqsoff
  • preemptoff
  • preemptirqsoff
  • wakeup
  • wakeup_rt
  • wakeup_dl
  • mmiotrace
  • branch
  • nop

具体每个 trace 类型是做什么的,可以查询 官方文档

Ftrace 最全面的学习文档还是官方文档。

Ftrace 基础用法

内核配置

几乎所有的发行版都自带 ftrace 支持,相关内核配置位于如下目录下:

-> Kernel hacking
   -> Tracers

Ftrace 三板斧

  1. 设置 tracer 类型
  2. 设置 tracer 参数
  3. 使能 tracer

Function trace 实例

下面是跟踪 dev_attrs_show 函数所需要的所有命令,并且有注释。

进入 ftrace 工作目录:

# cd /sys/kernel/debug/tracing

查看系统支持的 tracer 类型:

# cat available_tracers
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop

Disable tracer:

# echo 0 > tracing_on

设置 tracer 类型为 function:

# echo function > current_tracer

set_ftrace_filter 表示要跟踪的函数,这里我们只跟踪 dev_attr_show 函数:

# echo dev_attr_show > set_ftrace_filter

Enable tracer:

# echo 1 > tracing_on

提取 trace 结果:

# cat trace

# tracer: function
#
# entries-in-buffer/entries-written: 3/3   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
        thermald-961   [000] ....   345.540878: dev_attr_show <-sysfs_kf_seq_show
        thermald-961   [000] ....   345.540905: dev_attr_show <-sysfs_kf_seq_show
        thermald-961   [000] ....   345.540927: dev_attr_show <-sysfs_kf_seq_show

从上图可以看到 function trace 一个函数的方法基本就是三板斧:

  1. 设置 current_tracer 为 function
  2. 设置要 trace 的函数
  3. 打开 trace 开关,开始 trace
  4. 提取 trace 结果

从 trace 信息我们可以获取很多重要信息:

  1. 进程信息,TASK-PID
  2. 进程运行的 CPU
  3. 执行函数时的系统状态,包括中断,抢占等状态信息
  4. 执行函数的时间辍

function_graph Trace 实例

与 function tracer 类似,设置 function_graph 的方式如下:

# cat available_tracers
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop

# echo function_graph > current_tracer

set_graph_function 表示要跟踪的函数

# echo dev_attr_show > set_graph_function
# echo 1 > tracing_on

捕捉到的 trace 内容:

# cat trace
# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 0)               |  dev_attr_show() {
 0)               |    energy_uj_show() {
 0)               |      get_energy_counter [intel_rapl_common]() {
 0)               |        cpus_read_lock() {
 0)               |          _cond_resched() {
 0)   0.283 us    |            rcu_all_qs();
 0)   0.880 us    |          }
 0)   1.521 us    |        }
 0)               |        rapl_read_data_raw [intel_rapl_common]() {
 0)               |          rapl_msr_read_raw [intel_rapl_msr]() {
 0)               |            rdmsrl_safe_on_cpu() {
 0)               |              rdmsr_safe_on_cpu() {
 0)   0.271 us    |                __init_waitqueue_head();
 0)               |                smp_call_function_single_async() {
 0)               |                  generic_exec_single() {
 0)               |                    __rdmsr_safe_on_cpu() {
 0)               |                      complete() {
 0)   0.268 us    |                        _raw_spin_lock_irqsave();
 0)               |                        __wake_up_locked() {
 0)   0.298 us    |                          __wake_up_common();
 0)   0.836 us    |                        }
 0)   0.281 us    |                        _raw_spin_unlock_irqrestore();
 0)   2.476 us    |                      }
 0)   3.610 us    |                    }
 0)   4.315 us    |                  }
 0)   4.941 us    |                }
 0)               |                wait_for_completion() {
 0)               |                  _cond_resched() {
 0)   0.270 us    |                    rcu_all_qs();
 0)   0.800 us    |                  }
 0)   0.271 us    |                  _raw_spin_lock_irq();
 0)   1.920 us    |                }
 0)   8.231 us    |              }
 0)   8.824 us    |            }
 0)   9.413 us    |          }
 0) + 10.670 us   |        }
 0)   0.269 us    |        cpus_read_unlock();
 0) + 13.757 us   |      }
 0) + 15.976 us   |    }
 0) + 17.029 us   |  }

我们跟踪的是 dev_attr_show 函数,但是 function_graph tracer 会跟踪函数内的调用关系和函数执行时间,可以协助我们确定代码执行流程。比如一个函数内部执行了很多函数指针,不能确定到底执行的是什么函数,可以用 function_graph tracer 跟踪一下。

trace event 用法

trace event 简介

trace event 就是利用 ftrace 框架,实现低性能损耗,对执行流无影响的一种信息输出机制。相比 printk,trace event:

  • 不开启没有性能损耗
  • 开启后不影响代码流程
  • 不需要重新编译内核即可获取 debug 信息

系统支持的所有 trace event 都位于 /sys/kernel/debug/tracing/events 目录。

使用实例

  1. 设置需要的 trace event

这里我们打开 sched_switch event。顾名思义,sched_switch 可以监控系统内进程切换事件。

# cd /sys/kernel/debug/tracing/events/sched/sched_switch
# echo 1 > enable
  1. 提取进程切换信息

下面的进程切换信息还是很直观的,看不懂的请私信。:)。

# echo 0 > trace
# cat trace

# tracer: nop
#
# entries-in-buffer/entries-written: 221/221   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
          <idle>-0     [003] d...  3408.075314: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=chrome next_pid=4737 next_prio=120
          chrome-4737  [003] d...  3408.075465: sched_switch: prev_comm=chrome prev_pid=4737 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
          <idle>-0     [003] d...  3408.100181: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=chrome next_pid=4737 next_prio=120
          chrome-4737  [003] d...  3408.100333: sched_switch: prev_comm=chrome prev_pid=4737 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
          <idle>-0     [003] d...  3408.125190: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=chrome next_pid=4737 next_prio=120
          chrome-4737  [003] d...  3408.125339: sched_switch: prev_comm=chrome prev_pid=4737 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
          <idle>-0     [003] d...  3408.150474: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=chrome next_pid=4737 next_prio=120
          chrome-4737  [003] d...  3408.150680: sched_switch: prev_comm=chrome prev_pid=4737 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
          <idle>-0     [003] d...  3408.175599: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=chrome next_pid=4737 next_prio=120
  1. 过滤信息
# cd /sys/kernel/debug/tracing/events/sched/sched_switch
# cat format

name: sched_switch
...
print fmt: "prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%s%s ==> next_comm=%s next_pid=%d next_prio=%d", REC->prev_comm, REC->prev_pid, REC->prev_prio, (REC->prev_state & ((((0x0000 | 0x0001 | 0x0002 | 0x0004 | 0x0008 | 0x0010 | 0x0020 | 0x0040) + 1) << 1) - 1)) ? __print_flags(REC->prev_state & ((((0x0000 | 0x0001 | 0x0002 | 0x0004 | 0x0008 | 0x0010 | 0x0020 | 0x0040) + 1) << 1) - 1), "|", { 0x0001, "S" }, { 0x0002, "D" }, { 0x0004, "T" }, { 0x0008, "t" }, { 0x0010, "X" }, { 0x0020, "Z" }, { 0x0040, "P" }, { 0x0080, "I" }) : "R", REC->prev_state & (((0x0000 | 0x0001 | 0x0002 | 0x0004 | 0x0008 | 0x0010 | 0x0020 | 0x0040) + 1) << 1) ? "+" : "", REC->next_comm, REC->next_pid, REC->next_prio

从上面的 format 信息可以看出 sched_switch 打印的信息格式,基于上面提供的关键字可以实现信息过滤,比如下面的过滤命令可以只显示 chrome 进程的切换信息。

# cd /sys/kernel/debug/tracing/events/sched/sched_switch

# echo "prev_comm == 'chrome' || next_comm == 'chrome'" > filter
  1. 从捕捉信息中过滤

如果事先不知道要过滤什么信息,只能捕获全部信息,然后通过文本分析,过滤有效信息。比如,通过正则表达式过滤并提取每个进程的切换次数。

添加自己的 trace 信息

  1. trace event

    trace event 的添加是有固定范式的,就不贴具体代码了,具体可以参考 samples/trace_events 实现自己的 trace event.

  2. trace_printk

    trace_printk 是一个函数,它的调用方式与 printk 一模一样,只是 trace_printk 输出信息到 trace 文件,而 printk 输出到终端或者其它的缓存 buffer 中。

    trace_printk 延迟更短,几乎不影响原代码流程,而 printk 的延迟要大很多,且它的实现体系中也比 trace_printk 流程长,在中断、调度系统中调用 printk 几乎不可行。

    如果添加 printk 后问题消失了,那么请试试 trace_printk

总结

通过简单的例子,看到了 function/function_graph tracer 的基本用法,但是在实际应用中会有比较棘手的问题和需求。比如:

  • 某个函数被谁调用?调用栈是什么?
  • 如何跟踪某个进程?如何跟踪一个命令,但是这个命令执行时间很短?
  • 用户态的行为轨迹如何与内核中的 trace 联系到一起?
  • 如何跟踪过滤多个进程?多个函数?
  • 如何灵活控制 trace 的开关?

通过本篇文章先初步认识下 ftrace,下一篇文章会介绍上述问题。



Read Album:

Read Related:

Read Latest: