使用 ftrace 来跟踪系统问题 - ftrace 介绍

虽然之前一直听说过 ftrace,但从来没将它用在实战中,在一次客户排查问题中,遇到了比较奇怪的现象,一位精通内核的朋友建议使用 ftrace 来定位一下。虽然那一次并没有使用 ftrace,但也让我觉得,后面我们势必要提供 ftrace 相关的工具帮助我们在线上定位问题,所以自己也决定重新学习使用下 ftrace,当然也决定写一系列的相关出来,这里就先简单介绍下 ftrace。

什么是 ftrace

首先我们需要知道,什么是 ftrace?根据 Linux Doc 的介绍,ftrace 是一个 Linux 内部的 trace 工具,能够帮助开发者和系统设计者知道内核当前正在干啥,从而更好的去分析性能问题。

Ftrace 能帮我们分析内核特定的事件,譬如调度,中断等,也能帮我们去追踪动态的内核函数,以及这些函数的调用栈还有栈的使用这些。它也能帮我们去追踪延迟,譬如中断被屏蔽,抢占被禁止的时间,以及唤醒一个进程之后多久开始执行的时间。

可以看到,使用 ftrace 真的能做到对系统内核非常系统的剖析,甚至都能通过 ftrace 来学习 Linux 内核,不过在更进一步之前,我们需要学会的是 - 如何使用 ftrace。

如何使用

要使用 ftrace,首先就是需要将系统的 debugfs 或者 tracefs 给挂载到某个地方,幸运的是,几乎所有的 Linux 发行版,都开启了 debugfs/tracefs 的支持,所以我们也没必要去重新编译内核了。

在比较老的内核版本,譬如 CentOS 7 的上面,debugfs 通常被挂载到 /sys/kernel/debug 上面(debug 目录下面有一个 tracing 目录),而比较新的内核,则是将 tracefs 挂载到 /sys/kernel/tracing,无论是什么,我都喜欢将 tracing 目录直接 link 到 /tracing。后面都会假设直接进入了 /tracing 目录,后面,我会使用 Ubuntu 16.04 来举例子,内核版本是 4.13 来举例子。

我们使用 ls 来看看目录下面到底有什么:

README                      current_tracer            hwlat_detector   per_cpu              set_event_pid       snapshot            trace_marker      tracing_max_latency
available_events            dyn_ftrace_total_info     instances        printk_formats       set_ftrace_filter   stack_max_size      trace_marker_raw  tracing_on
available_filter_functions  enabled_functions         kprobe_events    saved_cmdlines       set_ftrace_notrace  stack_trace         trace_options     tracing_thresh
available_tracers           events                    kprobe_profile   saved_cmdlines_size  set_ftrace_pid      stack_trace_filter  trace_pipe        uprobe_events
buffer_size_kb              free_buffer               max_graph_depth  saved_tgids          set_graph_function  trace               trace_stat        uprobe_profile
buffer_total_size_kb        function_profile_enabled  options          set_event            set_graph_notrace   trace_clock         tracing_cpumask

可以看到,里面有非常多的文件和目录,具体的含义,大家可以去详细的看官方文档的解释,后面只会重点介绍一些文件。

Function

我们可以通过 available_tracers 这个文件知道当前 ftrace 支持哪些插件。

cat available_tracers
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop

通常用的最多的就是 functionfunction_graph,当然,如果我们不想 trace 了,可以使用 nop。我们首先打开 function

echo function > current_tracer
cat current_tracer
function

上面我们将 function 写入到了 current_tracer 来开启 function 的 trace,我通常会在 catcurrent_tracer 这个文件,主要是防止自己写错了。

然后 ftrace 就开始工作了,会将相关的 trace 信息放到 trace 文件里面,我们直接读取这个文件就能获取相关的信息。

cat trace | head -n 15
# tracer: function
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
            bash-29409 [002] .... 16158426.215771: mutex_unlock <-tracing_set_tracer
          <idle>-0     [039] d... 16158426.215771: call_cpuidle <-do_idle
          <idle>-0     [039] d... 16158426.215772: cpuidle_enter <-call_cpuidle
          <idle>-0     [039] d... 16158426.215773: cpuidle_enter_state <-cpuidle_enter
            bash-29409 [002] .... 16158426.215773: __fsnotify_parent <-vfs_write
          <idle>-0     [039] d... 16158426.215773: sched_idle_set_state <-cpuidle_enter_state

我们可以设置只跟踪特定的 function

echo schedule > set_ftrace_filter
cat set_ftrace_filter
schedule
cat trace | head -n 15
# tracer: function
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
            bash-29409 [010] .... 16158462.591708: schedule <-schedule_timeout
   kworker/u81:2-29339 [008] .... 16158462.591736: schedule <-worker_thread
            sshd-29395 [012] .... 16158462.591788: schedule <-schedule_hrtimeout_range_clock
       rcu_sched-9     [010] .... 16158462.595475: schedule <-schedule_timeout
            java-23597 [006] .... 16158462.600326: schedule <-futex_wait_queue_me
            java-23624 [020] .... 16158462.600855: schedule <-schedule_hrtimeout_range_clock

当然,如果我们不想 trace schedule 这个函数,也可以这样做:

echo '!schedule' > set_ftrace_filter

或者也可以这样做:

echo schedule > set_ftrace_notrace

Function filter 的设置也支持 *matchmatch**match* 这样的正则表达式,譬如我们可以 echo '*lock*' < set_ftrace_notrace 来禁止跟踪带 lock 的函数,set_ftrace_notrace 文件里面这时候就会显示:

cat set_ftrace_notrace
xen_pte_unlock
read_hv_clock_msr
read_hv_clock_tsc
update_persistent_clock
read_persistent_clock
set_task_blockstep
user_enable_block_step
...

Function Graph

相比于 functionfunction_graph 能让我们更加详细的去知道内核函数的上下文,我们打开 function_graph

echo function_graph > current_tracer
cat trace | head -15
# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 10)   0.085 us    |  sched_idle_set_state();
 10)               |  cpuidle_reflect() {
 10)   0.035 us    |    menu_reflect();
 10)   0.288 us    |  }
 10)               |  rcu_idle_exit() {
 10)   0.034 us    |    rcu_dynticks_eqs_exit();
 10)   0.296 us    |  }
 10)   0.032 us    |  arch_cpu_idle_exit();
 10)               |  tick_nohz_idle_exit() {
 10)   0.073 us    |    ktime_get();
 10)               |    update_ts_time_stats() {

我们也可以只跟踪某一个函数的堆栈

echo kfree > set_graph_function
cat trace | head -n 15
# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 16)               |  kfree() {
 16)   0.147 us    |    __slab_free();
 16)   1.437 us    |  }
 10)   0.162 us    |  kfree();
 17) @ 923817.3 us |          } /* intel_idle */
 17)   0.044 us    |          sched_idle_set_state();
 17)   ==========> |
 17)               |          smp_apic_timer_interrupt() {
 17)               |            irq_enter() {
 17)               |              rcu_irq_enter() {
 17)   0.049 us    |                rcu_dynticks_eqs_exit();

Event

上面提到了 function 的 trace,在 ftrace 里面,另外用的多的就是 event 的 trace,我们可以在 events 目录下面看支持那些事件:

ls events/
alarmtimer  cma         ext4      fs_dax        i2c          kvm      mmc     nmi             printk        regulator  smbus       task                     vmscan     xdp
block       compaction  fib       ftrace        iommu        kvmmmu   module  oom             random        rpm        sock        thermal                  vsyscall   xen
bpf         cpuhp       fib6      gpio          irq          libata   mpx     page_isolation  ras           sched      spi         thermal_power_allocator  wbt        xhci-hcd
btrfs       dma_fence   filelock  header_event  irq_vectors  mce      msr     pagemap         raw_syscalls  scsi       swiotlb     timer                    workqueue
cgroup      enable      filemap   header_page   jbd2         mdio     napi    percpu          rcu           signal     sync_trace  tlb                      writeback
clk         exceptions  fs        huge_memory   kmem         migrate  net     power           regmap        skb        syscalls    udp                      x86_fpu

上面列出来的都是分组的,我们可以继续深入下去,譬如下面是查看 sched 相关的事件:

ls events/sched/
enable                  sched_migrate_task  sched_process_exit  sched_process_wait  sched_stat_sleep  sched_switch                 sched_wakeup_new
filter                  sched_move_numa     sched_process_fork  sched_stat_blocked  sched_stat_wait   sched_wait_task              sched_waking
sched_kthread_stop      sched_pi_setprio    sched_process_free  sched_stat_iowait   sched_stick_numa  sched_wake_idle_without_ipi
sched_kthread_stop_ret  sched_process_exec  sched_process_hang  sched_stat_runtime  sched_swap_numa   sched_wakeup

对于某一个具体的事件,我们也可以查看:

ls events/sched/sched_wakeup
enable  filter  format  hist  id  trigger

不知道大家注意到了没有,上述目录里面,都有一个 enable 的文件,我们只需要往里面写入 1,就可以开始 trace 这个事件。譬如下面就开始 trace sched_wakeup 这个事件:

echo 1 > events/sched/sched_wakeup/enable
cat trace | head -15
# tracer: nop
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
            bash-29409 [012] d... 16158657.832294: sched_wakeup: comm=kworker/u81:1 pid=29359 prio=120 target_cpu=008
   kworker/u81:1-29359 [008] d... 16158657.832321: sched_wakeup: comm=sshd pid=29395 prio=120 target_cpu=010
          <idle>-0     [012] dNs. 16158657.835922: sched_wakeup: comm=rcu_sched pid=9 prio=120 target_cpu=012
          <idle>-0     [024] dNh. 16158657.836908: sched_wakeup: comm=java pid=23632 prio=120 target_cpu=024
          <idle>-0     [022] dNh. 16158657.839921: sched_wakeup: comm=java pid=23624 prio=120 target_cpu=022
          <idle>-0     [016] dNh. 16158657.841866: sched_wakeup: comm=java pid=23629 prio=120 target_cpu=016

我们也可以 trace sched 里面的所有事件:

echo 1 > events/sched/enable
cat trace | head -15
# tracer: nop
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
            bash-29409 [010] d... 16158704.468377: sched_waking: comm=kworker/u81:2 pid=29339 prio=120 target_cpu=008
            bash-29409 [010] d... 16158704.468378: sched_stat_sleep: comm=kworker/u81:2 pid=29339 delay=164314267 [ns]
            bash-29409 [010] d... 16158704.468379: sched_wake_idle_without_ipi: cpu=8
            bash-29409 [010] d... 16158704.468379: sched_wakeup: comm=kworker/u81:2 pid=29339 prio=120 target_cpu=008
            bash-29409 [010] d... 16158704.468382: sched_stat_runtime: comm=bash pid=29409 runtime=360343 [ns] vruntime=131529875864926 [ns]
            bash-29409 [010] d... 16158704.468383: sched_switch: prev_comm=bash prev_pid=29409 prev_prio=120 prev_state=S ==> next_comm=swapper/10 next_pid=0 next_prio=120

当然也可以 trace 所有的事件:

echo 1 > events/enable
cat trace | head -15
# tracer: nop
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
            bash-29409 [010] .... 16158761.584188: writeback_mark_inode_dirty: bdi (unknown): ino=3089 state=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES flags=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES
            bash-29409 [010] .... 16158761.584189: writeback_dirty_inode_start: bdi (unknown): ino=3089 state=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES flags=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES
            bash-29409 [010] .... 16158761.584190: writeback_dirty_inode: bdi (unknown): ino=3089 state=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES flags=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES
            bash-29409 [010] .... 16158761.584193: do_sys_open: "trace" 8241 666
            bash-29409 [010] .... 16158761.584193: kmem_cache_free: call_site=ffffffff8e862614 ptr=ffff91d241fa4000
            bash-29409 [010] .... 16158761.584194: sys_exit: NR 2 = 3

trace-cmd

从上面的例子可以看到,其实使用 ftrace 并不是那么方便,我们需要手动的去控制多个文件,但幸运的是,我们有 trace-cmd,作为 ftrace 的前端,trace-cmd 能够非常方便的让我们进行 ftrace 的操作,譬如我们可以使用 record 命令来 trace sched 事件:

trace-cmd record -e sched

然后使用 report 命令来查看 trace 的数据:

trace-cmd report | head -10
version = 6
CPU 27 is empty
cpus=40
       trace-cmd-29557 [003] 16159201.985281: sched_waking:         comm=kworker/u82:3 pid=28507 prio=120 target_cpu=037
       trace-cmd-29557 [003] 16159201.985283: sched_migrate_task:   comm=kworker/u82:3 pid=28507 prio=120 orig_cpu=37 dest_cpu=5
       trace-cmd-29557 [003] 16159201.985285: sched_stat_sleep:     comm=kworker/u82:3 pid=28507 delay=137014529 [ns]
       trace-cmd-29585 [023] 16159201.985286: sched_stat_runtime:   comm=trace-cmd pid=29585 runtime=217630 [ns] vruntime=107586626253137 [ns]
       trace-cmd-29557 [003] 16159201.985286: sched_wake_idle_without_ipi: cpu=5
       trace-cmd-29595 [037] 16159201.985286: sched_stat_runtime:   comm=trace-cmd pid=29595 runtime=213227 [ns] vruntime=105364596011783 [ns]
       trace-cmd-29557 [003] 16159201.985287: sched_wakeup:         kworker/u82:3:28507 [120] success=1 CPU:005

当然,在 report 的时候也可以加入自己的 filter 来过滤数据,譬如下面,我们就过滤出 sched_wakeup 事件并且是 success 为 1 的。

trace-cmd report -F 'sched/sched_wakeup: success == 1'  | head -10
version = 6
CPU 27 is empty
cpus=40
       trace-cmd-29557 [003] 16159201.985287: sched_wakeup:         kworker/u82:3:28507 [120] success=1 CPU:005
       trace-cmd-29557 [003] 16159201.985292: sched_wakeup:         trace-cmd:29561 [120] success=1 CPU:007
          <idle>-0     [032] 16159201.985294: sched_wakeup:         qps_json_driver:24669 [120] success=1 CPU:032
          <idle>-0     [032] 16159201.985298: sched_wakeup:         trace-cmd:29590 [120] success=1 CPU:026
          <idle>-0     [010] 16159201.985300: sched_wakeup:         trace-cmd:29563 [120] success=1 CPU:010
       trace-cmd-29597 [037] 16159201.985302: sched_wakeup:         trace-cmd:29595 [120] success=1 CPU:039
          <idle>-0     [010] 16159201.985302: sched_wakeup:         sshd:29395 [120] success=1 CPU:010

大家可以注意下 success == 1,这其实是一个对事件里面 field 进行的表达式运算了,对于不同的事件,我们可以通过查看起 format 来知道它的实际 fields 是怎样的,譬如:

cat events/sched/sched_wakeup/format
name: sched_wakeup
ID: 294
format:
    field:unsigned short common_type;   offset:0;   size:2; signed:0;
    field:unsigned char common_flags;   offset:2;   size:1; signed:0;
    field:unsigned char common_preempt_count;   offset:3;   size:1; signed:0;
    field:int common_pid;   offset:4;   size:4; signed:1;

    field:char comm[16];    offset:8;   size:16;    signed:1;
    field:pid_t pid;    offset:24;  size:4; signed:1;
    field:int prio; offset:28;  size:4; signed:1;
    field:int success;  offset:32;  size:4; signed:1;
    field:int target_cpu;   offset:36;  size:4; signed:1;

print fmt: "comm=%s pid=%d prio=%d target_cpu=%03d", REC->comm, REC->pid, REC->prio, REC->target_cpu

小结

上面只是简单的列出了 ftrace 相关的使用,后续我会在写一些我们或者业界是如何用 ftrace 来解决问题的。另外,我们正在用 ftrace 开发非常多的性能诊断工具,如果你对这一块感兴趣,欢迎联系我 tl@pingcap.com

推荐阅读更多精彩内容