【原创】Ftrace使用及实现机制

Ftrace使用及实现机制

版权声明：本文为本文为博主原创文章，转载请注明出处 https://www.cnblogs.com/wsg1100 如有错误，欢迎指正。

目录

• Ftrace使用及实现机制
  • 一、使用ftrace
    • 1.挂载
    • 2. 关键文件介绍
    • 3.current_tracer列表
    • 4.trace输出示例
      • 4.1 trace输出格式
      • 4.2 Latency trace输出格式
      • 4.3 trace_options
      • 4.4 以下是每个tracer选项
    • 5 示例
      • 5.1 function
      • 5.2 irqsoff
      • 5.3 preemptoff
      • 5.4 preemptirqsoff
      • 5.5 wakeup
      • 5.6 wakeup_rt
      • 5.7 使用event进行延迟trace
      • 5.8 硬件延迟检测器
      • 5.9 trace单线程
      • 5.10 function graph tracer
      • 5.11 动态trace
        • 5.11.1 使用函数图动态trace
        • 5.11.1 ftrace_enable
        • 5.11.1 Filter commands
        • 5.11.1 trace_pipe
        • 5.11.1 trace entries
        • 5.11.1 Snapshot
        • 5.11.1 Instances
        • 5.11.1 Stack trace
  • 二、ftrace实现机制
  • 1. 待补充....

一、使用ftrace

ftrace 即function tracer，最初是用来 trace 内核中的函数，在 2008 年的时候被合入了 Linux 内核，当时的版本是 Linux2.6.x。现在 ftrace 的功能不仅仅是function tracer，更加丰富了，可观测内核很多信息。本文分为两个部分，第一部分介绍ftrace的使用，大部分来源于Linux内核ftrace文档，第二部分介绍ftrace的实现原理。

---

1.挂载

ftrace 的所有操作在 tracefs 这个虚拟文件系统中完成， tracefs 的挂载点在 /sys/kernel/debug/tracing 下：

# cat /proc/mounts | grep tracefs
tracefs /sys/kernel/debug/tracing tracefs rw,relatime 0 0

如果没有自动挂载，则需要手动挂载：

# mount -t tracefs nodev /sys/kernel/debug/tracing

挂载后/sys/kernel/debug/tracing 目录下的文件如下：

# cd /sys/kernel/debug/tracing
# ls
available_events            events                    README                  set_graph_function  trace_marker_raw
available_filter_functions  free_buffer               saved_cmdlines          set_graph_notrace   trace_options
available_tracers           function_profile_enabled  saved_cmdlines_size     snapshot            trace_pipe
buffer_percent              hwlat_detector            saved_tgids             stack_max_size      trace_stat
buffer_size_kb              instances                 set_event               stack_trace         tracing_cpumask
buffer_total_size_kb        kprobe_events             set_event_notrace_pid   stack_trace_filter  tracing_max_latency
current_tracer              kprobe_profile            set_event_pid           synthetic_events    tracing_on
dynamic_events              max_graph_depth           set_ftrace_filter       timestamp_mode      tracing_thresh
dyn_ftrace_total_info       options                   set_ftrace_notrace      trace               uprobe_events
enabled_functions           per_cpu                   set_ftrace_notrace_pid  trace_clock         uprobe_profile
error_log                   printk_formats            set_ftrace_pid          trace_marker

2. 关键文件介绍

tracefs 虚拟文件系统下的文件操作和我们常用的 Linux proc 和 sys 虚拟文件系统的操作差不多。通过对某个文件的 echo 操作，我们可以向内核的 ftrace 系统发送命令，然后 cat 某个文件得到 ftrace 的返回结果。

/sys/kernel/debug/tracing 目录各文件及作用如下，根据具体场景使用：

current_tracer：

设置或显示当前tracer配置。

available_tracers：

内核支持的tracer配置，内核编译时配置，将里面的配置写入current_tracer即设置设置当前trace功能。

tracing_on：

设置是否将trace写入tracer缓冲区，写0到该文件禁用trace写入缓冲区，写1启用，无论写0还是写1，内核trace都在运行，都有trace开销。

trace:

该文件以人类可读的格式保存跟踪的输出。注意，正在读取（打开）此文件时会暂时禁用跟踪。

trace_pipe:

输出与“trace”文件相同，但此文件应使用实时跟踪进行流式处理。从此文件读取将阻塞，直到检索到新数据。 与“trace”文件不同，此文件是消费者。 一旦从该文件读取数据，就会消耗该数据。 “trace”文件是静态的，如果跟踪器没有添加更多数据，则每次读取时都会显示相同的信息。 此文件在读取时不会禁用跟踪。

trace_options:

此文件允许用户控制上述输出文件之一中显示的数据量。

options:

这是一个目录，其中包含每个可用跟踪选项的文件（也在trace_options中）。 也可以通过将“1”或“0”分别写入带有选项名称的相应文件来设置或清除选项。

tracing_max_latency:

一些跟踪器记录了最大延迟。 例如，禁用中断的最长时间。此文件中保存最长时间。 最大跟踪也将得到优化，并通过trace显示。 如果延迟大于此文件中的值（以微秒为单位），则只会记录新的最大跟踪。
通过echo写入一个时间值，除非它大于此文件中的时间，否则不会记录任何延迟。

tracing_thresh:

只要延迟大于此文件中的数字，某些延迟跟踪器就会记录跟踪。仅当文件包含大于0的数字时才有效。（以微秒为单位）

buffer_size_kb：

这将设置或显示每个CPU缓冲区大小。 默认情况下，跟踪缓冲区的大小与每个CPU的大小相同。 显示的数字是CPU缓冲区的大小，而不是所有缓冲区的总大小。 跟踪缓冲区分配在一个内存页面（内核用于分配的内存块，通常为4 KB）。

buffer_total_size_kb:

这将显示所有跟踪缓冲区的总大小。

free_buffer:

用于释放缓冲区，让一个跟踪进程打开这个文件，当进程退出时，该文件的文件描述符将被关闭，这样，环形缓冲区将被“释放”。

tracing_cpumask:

这是一个掩码，用于指定跟踪的CPU。格式是表示CPU的十六进制字符串。

set_ftrace_filter:

set_ftrace_notrace:

这与set_ftrace_filter的效果相反。 此处添加的任何功能都不会被跟踪。 如果set_ftrace_filter和set_ftrace_notrace中都存在函数，则不会跟踪该函数。

set_ftrace_pid:

让函数跟踪器仅跟踪其PID在此文件中列出的线程。如果设置了“function-fork”选项，那么当该文件中列出PID的任务分fork时，子进程的PID将自动添加到该文件中，并且该子进程将被跟踪。 此选项还将导致退出的任务的PID从文件中删除。

set_event_pid:

此文件中列出的需要event跟踪的任务PID。注意，sched_switch和sched_wake_up还将跟踪此文件中列出的事件。如果要跟踪此文件中PID的任务的子进程，还需要启用“event-fork”选项。 任务退出时该文件内的PID将被删除。

set_graph_function:

函数图形跟踪器将跟踪此文件中列出的函数及其调用的函数。 （有关详细信息，请参阅“动态ftrace”部分）。

set_graph_notrace:

与set_graph_function类似，但在函数被命中时将禁用函数图形跟踪，直到它退出函数。这使得可以忽略由特定函数调用的跟踪函数。

max_graph_depth:

与函数图形跟踪器一起使用。 这是它将追溯到函数的最大深度。 将其设置为值1将仅显示从用户空间调用的第一个内核函数。

available_filter_functions:

这列出了ftrace已处理并可跟踪的功能。这些是可以传递给“set_ftrace_filter”或“set_ftrace_notrace”的函数名称。 （有关详细信息，请参阅下面的“动态ftrace”部分。）

dyn_ftrace_total_info:

此文件用于调试目的。 已转换为nops且可以跟踪的函数数。

enabled_functions:

function_profile_enabled:

设置后，它将启用具有功能跟踪器或功能图形跟踪器的所有功能。 它将保留被调用函数数量的直方图，如果配置了函数图形跟踪器，它还将跟踪这些函数所花费的时间。 直方图内容可以显示在文件中： 
trace_stats/function<cpu>（function0，function1等）。

trace_stats:

包含不同跟踪统计信息的目录。

kprobe_events:

启用动态跟踪点。 请参阅kprobetrace.txt。

kprobe_profile:

动态跟踪点统计信息。 请参阅kprobetrace.txt。

printk_formats:

这适用于读取原始格式文件的工具。 如果环形缓冲区中的事件引用了一个字符串，则只有指向该字符串的指针被记录到缓冲区而不是字符串本身。 这可以防止工具知道该字符串是什么。 此文件显示字符串的字符串和地址，允许工具将指针映射到字符串。

saved_cmdlines:

除非事件专门保存任务comm，否则只有任务的pid记录在跟踪事件中。 Ftrace对通信进行pid映射缓存，以尝试显示事件的通信。 如果未列出comm的pid，则输出中将显示“<...>”。
如果选项“record-cmd”设置为“0”，则在录制期间不会保存任务通信。 默认情况下，它启用.

saved_cmdlines_size:

默认情况下，会保存128个通讯（请参阅上面的“saved_cmdlines”）。 要增加或减少缓存的通信量，请将要缓存的通信数回显到此文件中。

saved_tgids:

如果设置了“record-tgid”选项，则在每个调度上下文切换时，任务的任务组ID将保存在将线程的PID映射到其TGID的表中。 默认情况下，禁用“record-tgid”选项。

snapshot:

这将显示“Snapshot”缓冲区，还允许用户拍摄当前运行跟踪的快照。 有关详细信息，请参阅下面的“Snapshot”部分。

stack_max_size:

激活堆栈跟踪器时，将显示它遇到的最大堆栈大小。请参阅下面的“堆栈跟踪”部分。

stack_trace:

这将显示激活堆栈跟踪器时遇到的最大堆栈的堆栈跟踪跟踪。请参阅下面的“堆栈跟踪”部分。

stack_trace_filter:

这与“set_ftrace_filter”类似，但它限制了堆栈跟踪器将检查的功能。

trace_clock:

只要将事件记录到环形缓冲区中，就会添加“timestamp”。这个时间戳来自指定的时钟。默认情况下，ftrace使用“local”时钟。这个时钟非常快且严格按照cpu计算，但在某些系统上，它可能与其他CPU相比不是单调的。换句话说，本地时钟可能与其他CPU上的本地时钟不同步。

通常用于跟踪的时钟如下(带有方括号的时钟是有效的。)：

# cat trace_clock 
[local] global counter uptime perf mono mono_raw boot x86-tsc

local：默认时钟，但可能不在CPU之间同步.

global：此时钟与所有CPU同步，但可能比本地时钟慢一点。

counter：这根本不是时钟，而是一个原子计数器。它逐个计数，但与所有CPU同步。当您需要准确了解不同CPU上相互发生的订单事件时，这非常有用。

uptime 这使用jiffies计数器，时间戳相对于启动后的时间。

perf: 这使得ftrace使用perf使用的相同时钟。最终perf将能够读取ftrace缓冲区，这将有助于交错数据。

x86-tsc:架构可以定义自己的时钟。例如，x86在此使用自己的TSC周期时钟。

ppc-tb:这使用powerpc时基寄存器值。这在CPU之间是同步的，并且如果已知tb_offset，还可以用于跨管理程序/来宾关联事件。

mono:这使用快速单调时钟（CLOCK_MONOTONIC），它是单调递增的，可以进行NTP速率调整。

mono_raw:这是原始的单调时钟（CLOCK_MONOTONIC_RAW），它是单调递增的，但不受任何速率调整和滴答，速率与硬件时钟源相同。

boot:这是启动时钟（CLOCK_BOOTTIME），基于快速单调时钟，但也占用了挂起时间。由于时钟访问被设计用于在挂起路径中进行跟踪，因此如果在更新快速单声道时钟之前计算挂起时间之后访问时钟，则可能产生一些副作用。在这种情况下，时钟更新似乎比通常情况稍早发生。

要设置时钟，只需将时钟名称回显到此文件中即可。

echo global> trace_clock

trace_marker:
这是一个非常有用的文件，用于将用户空间与内核中发生的事件同步。 将字符串写入此文件将写入ftrace缓冲区。在应用程序中，在应用程序启动时打开此文件,并仅引用文件的文件描述符非常有用。

	void trace_write(const char *fmt, ...)
	{
		va_list ap;
		char buf[256];
		int n;

		if (trace_fd < 0)
			return;

		va_start(ap, fmt);
		n = vsnprintf(buf, 256, fmt, ap);
		va_end(ap);

		write(trace_fd, buf, n);
	}

//	开始:
		trace_fd = open("trace_marker", WR_ONLY);

trace_marker_raw:

这与上面的trace_marker类似，但是用于将二进制数据写入其中，其中可以使用工具来解析来自trace_pipe_raw的数据。

uprobe_events:

在程序中添加动态跟踪点。 请参阅uprobetracer.txt

uprobe_profile:

Uprobe统计。 请参阅uprobetrace.txt

instances:

这是一种制作多个跟踪缓冲区的方法，可以在不同的缓冲区中记录不同的事件。 请参阅下面的“实例”部分。

events:

这是跟踪事件目录。 它包含已编译到内核中的事件跟踪点（也称为静态跟踪点）。 它显示了存在哪些事件跟踪点以及它们如何按系统分组。 各种级别都有“启用”文件，可以在写入“1”时启用跟踪点。有关更多信息，请参阅events.txt。

set_event:

通过在事件中回显到此文件，将启用该事件。有关更多信息，请参阅events.txt。

available_events:

可以在跟踪中启用的事件列表,有关更多信息，请参阅events.txt。

hwlat_detector:

硬件延迟检测器的目录。请参阅下面的“硬件延迟检测器”部分。

per_cpu:

这是一个包含跟踪per_cpu信息的目录。

per_cpu/cpu0/buffer_size_kb:

ftrace缓冲区定义为per_cpu。 也就是说，每个CPU都有一个单独的缓冲区，允许以原子方式完成写入，并且不受cache bouncing的影响。 这些缓冲区可能有不同大小的缓冲区 此文件类似于buffer_size_kb文件，但它仅显示或设置特定CPU的缓冲区大小。 （这里是cpu0）。

per_cpu/cpu0/trace:

这类似于“跟踪”文件，但它只显示特定于CPU的数据。 如果写入，它只清除特定的CPU缓冲区。

per_cpu/ CPU0/ trace_pipe

这类似于“trace_pipe”文件，并且是一个消耗读取，但它只显示（和使用）特定于CPU的数据。

per_cpu/ CPU0/ trace_pipe_raw

对于可以解析ftrace环形缓冲区二进制格式的工具，trace_pipe_raw文件可用于直接从环形缓冲区中提取数据。 通过使用splice（）系统调用，缓冲区数据可以快速传输到文件或服务器正在收集数据的网络。与trace_pipe一样，这是一个消费者，其中多次读取将始终产生不同的数据。

per_cpu/ CPU0/snapshot

这类似于主“快照”文件，但只会对当前CPU（如果支持）进行快照。 它仅显示给定CPU的快照内容，如果写入，则仅清除此CPU缓冲区。

per_cpu/cpu0/snapshot_raw:

与trace_pipe_raw类似，但将从给定CPU的快照缓冲区中读取二进制格式。

per_cpu/cpu0/stats:
这会显示有关环形缓冲区的某些统计信息：

entries：仍在缓冲区中的事件数。

overrun: 缓冲区已满时由于覆盖而丢失的事件数。

commit overrun：应该始终为零。
如果在嵌套事件（环形缓冲区重入）中发生了如此多的事件，则它会被设置，它会填充缓冲区并开始丢弃事件。
bytes:字节实际读取（未覆盖）。
oldest event ts:缓冲区中最旧的时间戳
now ts:当前时间戳
dropped events:由于覆盖选项关闭而导致事件丢失。
read events:读取的事件数.

3.current_tracer列表

以下是可配置的current_tracer列表：

function
函数调用跟踪器来跟踪所有内核函数。

**function_graph **
与函数跟踪器类似，除了函数跟踪器探测其条目上的函数，而函数图形跟踪器跟踪函数的进入和退出。 然后它提供了绘制类似于C代码源的函数调用图的能力。

blk
块跟踪器。 blktrace用户应用程序使用的跟踪器。

hwlat
硬件延迟跟踪器用于检测硬件是否产生任何延迟。 请参阅下面的“硬件延迟检测器”部分。

irqsoff
跟踪禁用中断的区域并以最长的最大延迟保存跟踪。请参阅tracing_max_latency。 记录新的最大值时，它将替换旧的迹线。 最好在启用延迟格式选项的情况下查看此跟踪，这在选择跟踪器时会自动发生。

preemptoff
与irqsoff类似，但跟踪并记录禁用抢占的时间。

preemptirqsoff
与irqsoff和preemptoff类似，但跟踪并记录禁用irqs和/或抢占的最大时间。

wakeup
跟踪并记录最高优先级任务在被唤醒后进行调度所需的最大延迟。按照普通开发人员的预期跟踪所有任务。

wakeup_rt
跟踪并记录仅执行RT任务所需的最大延迟（如当前“唤醒”所做的那样）。 这对那些对RT任务的唤醒时间感兴趣的人很有用。

wakeup_dl
跟踪并记录SCHED_DEADLINE任务被唤醒所需的最大延（如wakeup和wakeup_rt）。

mmiotrace
用于跟踪二进制模块的特殊跟踪器。 它将跟踪模块对硬件的所有调用。 它所写的所有内容以及从I / O中读取的内容。

branch
在跟踪内核中可能/不可能的调用时，可以配置此跟踪器。 它将追踪一个可能的和不太可能的分支何时被击中，以及它在预测正确时是否正确。

nop
这是“无痕迹”的示踪剂。 要从跟踪中删除所有跟踪器，只需将“nop”写道到current_tracer。

4.trace输出示例

4.1 trace输出格式

下面简单了解下ftrace的使用。ftrace的输出结果都可以通过 cat trace 这个命令得到，在缺省状态下 ftrace 的 tracer 是 nop，也就是 ftrace 什么都不做。因此，我们从cat trace中也看不到别的，只是显示了 trace 输出格式。

root@work-machine:/sys/kernel/debug/tracing# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 0/0   #P:8
#
#                                _-----=> irqs-off
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |

这里以function tracer为例，function tracer 只是 ftrace 最基本的功能，是我们平常调试 Linux 内核问题时最常用到的功能，执行 echo function > current_tracer 来告诉 ftrace，我要启用 function tracer.

root@work-machine:/sys/kernel/debug/tracing# cat current_tracer
nop
root@work-machine:/sys/kernel/debug/tracing# cat available_tracers
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop
root@work-machine:/sys/kernel/debug/tracing# echo function > current_tracer
root@work-machine:/sys/kernel/debug/tracing# cat current_tracer
function

在启动了 function tracer 之后，我们再查看一下 trace 的输出。这时候我们就会看到大量的输出，每一行的输出就是当前内核中被调用到的内核函数。

root@work-host:/sys/kernel/debug/tracing# cat trace
# tracer: function
#
# entries-in-buffer/entries-written: 358096/10552611   #P:8
#
#                                _-----=> irqs-off
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |
          <idle>-0       [000] *.... 46719.316253: handle_irq_pipelined_prepare <-arch_pipeline_entry
          <idle>-0       [000] *.~.. 46719.316289: arch_handle_irq <-arch_pipeline_entry
          <idle>-0       [000] *.~.. 46719.316289: generic_pipeline_irq_desc <-arch_handle_irq
          <idle>-0       [000] *.~.. 46719.316289: handle_fasteoi_irq <-generic_pipeline_irq_desc
          <idle>-0       [000] *.~.. 46719.316290: irq_may_run <-handle_fasteoi_irq
          <idle>-0       [000] *.~.. 46719.316290: handle_oob_irq <-handle_fasteoi_irq
          <idle>-0       [000] *.~.. 46719.316290: mask_irq.part.0 <-handle_fasteoi_irq
          <idle>-0       [000] *.~.. 46719.316290: mask_ioapic_irq <-mask_irq.part.0
          <idle>-0       [000] *.~.. 46719.316294: io_apic_sync <-mask_ioapic_irq
......

第2行标题及tracer的配置为function (跟踪函数)

第4行 显示缓冲区中的事件数以及写入的条目总数。\(358096/10552611\),由于缓冲区填满而丢失的条目数（\(10552611- 358096=10,194,515\)事件丢失），接着是处理器数量：8

下面是记录的事件的内容：任务名称“",它的PID为：0，运行在”000“号CPU上，后面是延迟的时间戳。格式:<秒>.<微秒>，跟踪到函数handle_irq_pipelined_prepare()及父函数arch_pipeline_entry()，时间戳是进入handle_irq_pipelined_prepare()时的时间。

4.2 Latency trace输出格式

root@work-host:/sys/kernel/debug/tracing# cat trace
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 4.4.182
# --------------------------------------------------------------------
# latency: 2674 us, #28/28, CPU#6 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:8)
#    -----------------
#    | task: compiz-3483 (uid:1000 nice:0 policy:0 rt_prio:0)
#    -----------------
#  => started at: __wake_up
#  => ended at:   __wake_up
#
#
#                  _------=> CPU#            
#                 / _-----=> irqs-off        
#                | / _----=> need-resched    
#                || / _---=> hardirq/softirq 
#                ||| / _--=> preempt-depth   
#                |||| /     delay            
#  cmd     pid   ||||| time  |   caller      
#     \   /      |||||  \    |   /         
  compiz-3483    6d.s1    0us : _raw_spin_lock_irqsave <-__wake_up
  compiz-3483    6d.s1    0us : preempt_count_add <-_raw_spin_lock_irqsave
	......
  compiz-3483    6d.s3    8us#: __x2apic_send_IPI_mask <-x2apic_send_IPI_mask
  compiz-3483    6d.s3 2669us : ttwu_stat <-try_to_wake_up
  compiz-3483    6d.s3 2671us : __rcu_read_lock <-ttwu_stat
  compiz-3483    6d.s3 2671us : __rcu_read_unlock <-ttwu_stat
  compiz-3483    6d.s3 2672us : _raw_spin_unlock_irqrestore <-try_to_wake_up
  compiz-3483    6d.s3 2673us : preempt_count_sub <-_raw_spin_unlock_irqrestore
  compiz-3483    6d.s2 2674us : _raw_spin_unlock_irqrestore <-__wake_up
  compiz-3483    6d.s2 2674us : _raw_spin_unlock_irqrestore <-__wake_up
  compiz-3483    6d.s2 2675us+: trace_hardirqs_on <-__wake_up
  compiz-3483    6d.s2 2727us : <stack trace>
 => rcu_gp_kthread_wake
 => note_gp_changes
 => rcu_process_callbacks
 => __do_softirq
 => irq_exit
 => smp_apic_timer_interrupt
 => apic_timer_interrupt
 => __wake_up_sync_key
 => sock_def_readable
 => unix_stream_sendmsg
 => sock_sendmsg
 => sock_write_iter
 => do_iter_readv_writev
 => do_readv_writev
 => vfs_writev
 => SyS_writev
 => entry_SYSCALL_64_fastpat

第2行tracer的配置为irqsoff，tracer版本以及内核版本
下面一行给出最大延迟latency：2674us, 跟踪条目和总数\(28/28\)，VP，KP，SP和HP始终为零，保留供以后使用。#P是在线CPU的数量（#P：8）。

延迟发生时运行的任务：compiz，任务PID：3483
分别禁用和启用中断导致延迟的：开始位置：__wake_up； 结束位置：__wake_up

内容及含义：

cmd：跟踪中进程的名称

pid:该进程的PID

CPU#:这个进程运行在这个CPU上

irq-off:
'd'中断禁用，'.'其它。注意：如果架构不支持某种方式读取irq标志变量，在这里会打印'X'

need-resched:

'N' TIF_NEED_RESCHED 和 PREEMPT_NEED_RESCHED两者都置位

'n' 只有TIF_NEED_RESCHED设置

'p' 只有PREEMPT_NEED_RESCHED设置

'.' 其它

hardirq/softirq:

'Z' --NMI发生在硬件中断内部

'z' --NMI运行

**'H' **--在一个softirq内发生了硬件中断。

**'h' **--硬中断运行

**'s' **--软中断运行

'.'- -正常上下文

preempt-depth:
preempt_disable的级别
以上内容对内核开发人员来说最有意义。

time:
启用 latency-format 选项时，跟踪文件输出包括相对于跟踪开始的时间戳。 这与禁用延迟格式时的输出不同，后者包括绝对时间戳。

delay:

不同时间戳前后的差异，主要为了容易找到前后时间差大的。
'$' - 超过1秒

'@' - 大于100ms

'*' - 大于10ms

'#' - 大于1000us

'!' - 大于100us

'+' - 大于10us

' ' - 小于等于10us

其余部分与'trace'文件相同（4.1 trace输出格式）。
请注意，延迟跟踪器通常以反向跟踪结束，以便轻松找到延迟发生的位置。

4.3 trace_options

trace_options文件（或options目录）用于控制在跟踪输出中打印的内容，要查看哪些有效，cat这个文件：

root@work-host:/sys/kernel/debug/tracing# cat trace_options
print-parent
nosym-offset
nosym-addr
noverbose
noraw
nohex
nobin
noblock
trace_printk
annotate
nouserstacktrace
nosym-userobj
noprintk-msg-only
context-info
nolatency-format
record-cmd
norecord-tgid
overwrite
nodisable_on_free
irq-info
markers
noevent-fork
nopause-on-trace
hash-ptr
function-trace
nofunction-fork
nodisplay-graph
nostacktrace
notest_nop_accept
notest_nop_refuse

要禁用某一个options，将这这一项前添加no,然后echo到trace_options：

echo noprint-parent > trace_options

启用options：

echo sym-offset > trace_options

以下是可用options及含义：

• print-parent: 在函数跟踪上，显示调用（父）函数以及正在跟踪的函数，如。

#echo print-parent > trace_options
	bash-4000  [01]  1477.606694: simple_strtoul <-kstrtoul
#echo noprint-parent > trace_options
   	bash-4000  [01]  1477.606694: simple_strtoul

• sym-offset:不仅显示函数名称，还显示函数中的偏移量:

#echo sym-offset > trace_options
	<idle>-0       [000] d.h.. 50029.070372: irq_to_desc+0x0/0x20 <-do_irq_inband+0x10/0x30
#echo nosym-offset > trace_options
	<idle>-0       [000] d.h.. 50029.070372: irq_to_desc <-do_irq_inband

• sym-addr: 这也将显示函数地址和函数名称，地址是个准确的地址。

#echo sym-addr > trace_options
<idle>-0       [001] d.h.. 50064.441407: irq_to_desc <ffffffff8db023e0> <-do_irq_inband <ffffffff8da6fc00>
#echo nosym-addr > trace_options
<idle>-0       [000] d.h.. 50029.070372: irq_to_desc <-do_irq_inband

• verbose: 这将在启用延迟格式选项时处理跟踪文件。

	 bash  4000 1 0 00000000 00010a95 [58127d26] 1720.415ms (+0.000ms): simple_strtoul (kstrtoul)

• raw:这将显示原始数字。 此选项最适用于可以比原始数据更好地转换原始数据的用户应用
  程序。
• hex: 与raw类似，但数字将采用十六进制格式。
• bin: 这将打印出原始二进制格式。
• block: 设置后，读取trace_pipe将不会在轮询时阻塞
• trace_printk: 可以禁止trace_printk()写入缓冲区。
• annotate: 当CPU缓冲区已满并且一个CPU缓冲区最近有很多事件时，有时会让人感到困惑，因此更短的时间框架，另一个CPU可能只有一些事件，这使得它具有较旧的事件。 报告跟踪时，它首先显示最早的事件，并且可能看起来只有一个CPU运行（具有最早事件的CPU）。 设置annotate选项后，将在新的CPU缓冲区启动时显示：

	<idle>-0     [001] dNs4 21169.031481: wake_up_idle_cpu <-add_timer_on
	<idle>-0     [001] dNs4 21169.031482: _raw_spin_unlock_irqrestore <-add_timer_on
	<idle>-0     [001] .Ns4 21169.031484: sub_preempt_count <-_raw_spin_unlock_irqrestore
##### CPU 2 buffer started ####
	<idle>-0     [002] .N.1 21169.031484: rcu_idle_exit <-cpu_idle
	<idle>-0     [001] .Ns3 21169.031484: _raw_spin_unlock <-clocksource_watchdog
	<idle>-0     [001] .Ns3 21169.031485: sub_preempt_count <-_raw_spin_unlock

• userstacktrace: 此选项可更改跟踪。 它在每个跟踪事件之后记录当前用户空间线程的堆栈跟踪。

• sym-userobj： 启用用户堆栈跟踪时，查找该地址所属的对象，并打印相对地址。 这在ASLR打开时特别有用，不然在应用程序不运行后，就没有机会将地址解析为object/file/line
  读取trace，trace_pipe时执行查找。 例：

a.out-1623  [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]

• printk-msg-only ： 设置后，trace_printk()将仅显示格式而不显示其参数（如果使用trace_bprintk（）或trace_bputs（）来保存trace_printk（））。

• context-info-- 仅显示事件数据。 隐藏通信，PID，时间戳，CPU和其他有用数据。

• latency-format： 此选项可更改跟踪输出。 启用后，跟踪会显示有关延迟的其他信息，如“延迟跟踪格式”中所述。

• record-cmd： 启用任何事件或跟踪器后，将在sched_switch跟踪点中启用挂钩，以使用映射的pids和comms填充comm缓存。 但这可能会导致一些开销，如果您只关心pid而不关心任务的名称，则禁用此选项可以降低跟踪的影响。 请参阅“saved_cmdlines”。

• record-tgid:`启用任何事件或跟踪器时，将在sched_switch跟踪点中启用hook，以填充映射到pids的映射线程组ID（TGID）的缓存。 请参阅“saved_tgids”。

• overwrite:这可以控制跟踪缓冲区已满时发生的情况。 如果为“1”（默认值），则丢弃并覆盖最旧的事件。 如果为“0”，则丢弃最新事件。 （有关溢出和丢弃的信息，请参阅per_cpu/cpu0/stats）

• disable_on_free 当free_buffer关闭时，跟踪将停止（tracing_on设置为0）。

• irq-info 显示中断，抢占计数，需要重新设置数据。 禁用时，trace如下所示：

# tracer: function
#
# entries-in-buffer/entries-written: 144405/9452052   #P:4
#
#           TASK-PID   CPU#      TIMESTAMP  FUNCTION
#              | |       |          |         |
          <idle>-0     [002]  23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up
          <idle>-0     [002]  23636.756054: activate_task <-ttwu_do_activate.constprop.89
          <idle>-0     [002]  23636.756055: enqueue_task <-activate_task

• markers 设置后，trace_marker是可写的（仅限root）。 禁用时，trace_marker将在写入时出现EINVAL错误。
• event-fork 设置后，具有set_event_pid中列出的PID的任务将在这些任务fork时将其子进程的PID添加到set_event_pid。 此外，当set_event_pid中具有PID的任务退出时，它们的PID将从文件中删除。
• function-trace 如果启用此选项，则latency跟踪器将启用函数跟踪（默认）。 禁用时，latency跟踪器不跟踪函数。 这样可以在执行延迟测试时降低跟踪器的开销。
• function-fork函数跟踪时跟踪子进程。
• display-graph latency后，延迟跟踪器（irqsoff，wakeup等）将使用函数图形跟踪而不是函数跟踪。`
• stacktrace 设置后，在记录任何跟踪事件后记录堆栈跟踪`
• branch 使用跟踪器启用分支跟踪。这使分支跟踪器与当前设置的跟踪器一起使用。 使用nop跟踪器启用此功能与启用branch跟踪器相同。

注意：某些跟踪器有自己的选项。 它们仅在trace处于活动状态时出现在此文件中。 它们始终显示在options目录中。

4.4 以下是每个tracer选项

1.function tracer的选项：

func_stack_trace--设置后，记录的每个功能之后记录堆栈跟踪。 注意！ 在启用此功能之前限制记录的函数，使用“set_ftrace_filter”否则系统性能将严重降低。 记住在清除功能过滤器之前禁用此选项。

2.function_graph tracer的选项:
由于function_graph跟踪器的输出略有不同，因此它有自己的选项来控制显示的内容。

funcgraph-overrun-- 设置后，在跟踪每个函数后图形显示堆栈的“溢出”。溢出是指调用的堆栈深度大于为每个任务保留的堆栈深度。
每个任务都有一个固定的函数数组，可以在调用图中进行跟踪。如果调用的深度超过该值，则不会跟踪该函数。溢出是由于超过此阵列而错过的功能数。

funcgraph-cpu-- 设置时，显示发生跟踪的CPU的CPU编号。

funcgraph-overhead-- 设置时，如果函数花费的时间超过一定量，则会显示延迟标记。

funcgraph-proc--与其他跟踪器不同，默认情况下不显示进程的命令行，而是仅在上下文切换期间跟踪和执行任务时。启用此选项后，每行都会显示每个进程的命令。

funcgraph-duration-- 在每个函数的末尾（返回），函数中的时间持续时间以微秒为单位显示。

funcgraph-abstime-- 设置后，每行显示时间戳。

funcgraph-irqs-- 禁用时，不会跟踪中断内发生的函数。

funcgraph-tail--设置后，return事件将包含它所代表的函数。默认情况下，这是关闭的，只显示一个结束的大括号“}”以返回一个函数。

sleep-time-- 运行函数图形跟踪器时，包括任务在其函数中计划的时间。启用后，它将计算任务作为函数调用的一部分进行计划的时间。

graph-time-- 使用函数图形跟踪器运行函数分析器时，包括调用嵌套函数的时间。如果未设置此项，则为函数报告的时间将仅包括函数本身执行的时间，而不是其调用的函数的时间。

3.blk tracer的选项：

blk_classic--显示更简约的输出。

5 示例

5.1 function

4.1 trace输出格式已经使用了function tracer, 使用ftrace前，确保设置了ftrace_enabled; 否则是一个nop。

root@work-machine:/sys/kernel/debug/tracing#sysctl kernel.ftrace_enabled=1  #启用ftrace
root@work-machine:/sys/kernel/debug/tracing#echo function > current_tracer
root@work-machine:/sys/kernel/debug/tracing#echo 1 > tracing_on
root@work-machine:/sys/kernel/debug/tracing#usleep 1
root@work-machine:/sys/kernel/debug/tracing#echo 0 > tracing_on
root@work-machine:/sys/kernel/debug/tracing#cat trace

注意：function tracer使用环形缓冲区来存储trace条目。 最新数据可能会覆盖最旧的数据。 使用echo来停止跟踪是不够的，可能会覆盖要记录的数据。 因此，有时最好直接从程序中禁用跟踪。 可以在感兴趣的部分终止trace,要直接从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);
	}
	[...]
}

你肯定会觉得function trace 输出的函数太多了，查看起来太困难了。别担心，下面我给你说个技巧，我们可以利用 ftrace 里的 filter 参数做筛选，详见[5.11.1 Filter commands](5.11.1 Filter commands)。

5.2 irqsoff

当中断禁用时，CPU无法对其他外部事件作出反应（除了NMI和SMI），irqsoff 能够跟踪禁用中断的时间。 当达到新的最大延迟时，跟踪器会保存导致该延迟点的trace，以便每次达到新的最大值时，将丢弃旧的已保存trace并保存新的trace。要重置最大值，echo 0到tracing_max_latency文件。

root@work-machine:/sys/kernel/debug/tracing#echo 0 > options/function-trace #设置本次trace 不跟踪函数
root@work-machine:/sys/kernel/debug/tracing#echo irqsoff > current_tracer	#设置本次trace为irqsoff
root@work-machine:/sys/kernel/debug/tracing#echo 1 > tracing_on				#开始记录到缓冲区
root@work-machine:/sys/kernel/debug/tracing#echo 0 > tracing_max_latency	#重置延迟最大值
#测试内容
root@work-machine:/sys/kernel/debug/tracing#echo 0 > tracing_on		#停止写入缓冲区
root@work-machine:/sys/kernel/debug/tracing#cat trace		#查看trace

上面没有设置函数跟踪，如果需要设置函数跟踪,这样可以看到那段时间所有函数调用(启用函数跟踪会产生额外的开销)：

root@work-machine:/sys/kernel/debug/tracing#echo 1 > options/function-trace	 #本次trace 设置函数跟踪

5.3 preemptoff

禁用抢占时，我们可能会收到中断，但任务无法抢占，优先级较高的任务必须等待抢占启用才能抢占优先级较低的任务。
preemptoff tracer跟踪禁用抢占的位置。 它记录了抢占被禁用的最大延迟。操作与上面类似。

root@work:/sys/kernel/debug/tracing#echo 0 > options/function-trace
root@work:/sys/kernel/debug/tracing#echo preemptoff > current_tracer
root@work:/sys/kernel/debug/tracing#echo 1 > tracing_on
root@work:/sys/kernel/debug/tracing#echo 0 > tracing_max_latency
#跟踪过程中执行操作
root@work:/sys/kernel/debug/tracing#echo 0 > tracing_on
root@work:/sys/kernel/debug/tracing#cat trace

同样，上面没有设置函数跟踪，如果需要设置函数跟踪,这样可以看到那段时间所有函数调用(启用函数跟踪会产生额外的开销)：

root@work:/sys/kernel/debug/tracing#echo 1 > options/function-trace	 #本次trace 设置函数跟踪

5.4 preemptirqsoff

知道禁用中断的位置或禁用抢占的最长时间是有帮助的。 但有时我们想知道何时禁用抢占 中断。
考虑以下代码：

local_irq_disable();
call_function_with_irqs_off();
preempt_disable();
call_function_with_irqs_and_preemption_off();
local_irq_enable();
call_function_with_preemption_off();
preempt_enable();

irqsoff tracer将记录call_function_with_irqs_off（）和call_function_with_irqs_and_preemption_off（）的总长度。
preemptoff tracer将记录call_function_with_irqs_and_preemption_off（）和call_function_with_preemption_off（）的总长度。

但是，两者都不会跟踪禁用中断 或 抢占的时间。 这个总时间是我们无法安排的时间。 要记录此时间，使用preemptirqsoff跟踪器。

root@work:/sys/kernel/debug/tracing#echo 0 > options/function-trace
root@work:/sys/kernel/debug/tracing#echo preemptirqsoff > current_tracer
root@work:/sys/kernel/debug/tracing#echo 1 > tracing_on
root@work:/sys/kernel/debug/tracing#echo 0 > tracing_max_latency
#跟踪过程中的操作
root@work:/sys/kernel/debug/tracing#echo 0 > tracing_on
root@work:/sys/kernel/debug/tracing#cat trace

5.5 wakeup

非实时任务唤醒时，实际唤醒的任务所花费的时间。

root@work:/sys/kernel/debug/tracing#echo 0 > options/function-trace
root@work:/sys/kernel/debug/tracing#echo wakeup > current_tracer
root@work:/sys/kernel/debug/tracing#echo 1 > tracing_on
root@work:/sys/kernel/debug/tracing#echo 0 > tracing_max_latency
root@work:/sys/kernel/debug/tracing#chrt -f 5 sleep 1   #模拟睡眠唤醒
root@work:/sys/kernel/debug/tracing#echo 0 > tracing_on
root@work:/sys/kernel/debug/tracing#cat trace

5.6 wakeup_rt

在实时环境中，了解唤醒最高优先级任务所需的唤醒时间非常重要。这也称为“调度延迟”。
实时环境对最坏情况的延迟感兴趣。wakeup_rt跟踪器只记录RT任务的最坏唤醒情况。不记录非RT任务，因为跟踪器仅记录一个最坏的情况，并且跟踪不可预测的非RT任务，将覆盖RT任务的最坏情况延迟。

root@work:/sys/kernel/debug/tracing#echo 0 > options/function-trace
root@work:/sys/kernel/debug/tracing#echo wakeup_rt > current_tracer
root@work:/sys/kernel/debug/tracing#echo 1 > tracing_on
root@work:/sys/kernel/debug/tracing#echo 0 > tracing_max_latency
root@work:/sys/kernel/debug/tracing#chrt -f 5 sleep 1   #模拟RT任务睡眠
root@work:/sys/kernel/debug/tracing#echo 0 > tracing_on
root@work:/sys/kernel/debug/tracing#cat trace

注意：trace数据显示的是内部优先级（99-rtprio）
如：<idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep

0:120:R表示空闲任务PID：0，正在以优先级级0(120-120)运行'R',sleep任务的优先级是RT优先级5(99-5=94),也是运行状态'R'.

如果需要设置函数跟踪,这样可以看到那段时间所有函数调用(启用函数跟踪会产生额外的开销)：

root@work:/sys/kernel/debug/tracing#echo 1 > options/function-trace	 #本次trace 设置函数跟踪

5.7 使用event进行延迟trace

由于函数跟踪会导致更大的延迟，但不使用函数跟踪，就看不到延迟内发生时的情况，很难知道导致它的原因。 有另外的方法，那就是启用events。

root@work:/sys/kernel/debug/tracing#echo 0 > options/function-trace
root@work:/sys/kernel/debug/tracing#echo wakeup_rt > current_tracer
root@work:/sys/kernel/debug/tracing#echo 1 > events/enable	#启用events
root@work:/sys/kernel/debug/tracing#echo 1 > tracing_on
root@work:/sys/kernel/debug/tracing#echo 0 > tracing_max_latency
root@work:/sys/kernel/debug/tracing#chrt -f 5 sleep 1  #模拟实时任务
root@work:/sys/kernel/debug/tracing#echo 0 > tracing_on
root@work:/sys/kernel/debug/tracing#cat trace

5.8 硬件延迟检测器

通过启用“hwlat”跟踪器来执行硬件延迟trace。
注意，此“hwlat”将影响系统的性能，因为它会定期使CPU始终忙于禁用中断。

root@work:/sys/kernel/debug/tracing#echo hwlat > current_tracer
root@work:/sys/kernel/debug/tracing#sleep 100
root@work:/sys/kernel/debug/tracing#cat trace

5.9 trace单线程

通过写入set_ftrace_pid，来跟踪单个线程。 例如：

root@work:/sys/kernel/debug/tracing#echo 3111 > set_ftrace_pid
root@work:/sys/kernel/debug/tracing#cat set_ftrace_pid  	#查看trace的线程pid
	3111
root@work:/sys/kernel/debug/tracing#echo function > current_tracer
root@work:/sys/kernel/debug/tracing#cat trace | head

如果要在执行时跟踪函数，可以使用类似这样的简单程序：

#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;
}

或者使用脚本：

#!/bin/bash

tracefs=`sed -ne 's/^tracefs \(.*\) tracefs.*/\1/p' /proc/mounts`
echo nop > $tracefs/tracing/current_tracer
echo 0 > $tracefs/tracing/tracing_on
echo $$ > $tracefs/tracing/set_ftrace_pid
echo function > $tracefs/tracing/current_tracer
echo 1 > $tracefs/tracing/tracing_on
exec "$@"

5.10 function graph tracer

类似于函数跟踪器，它在函数调用出入口上插入probe函数。 这是通过在每个task_struct中使用动态分配的返回地址堆栈来完成的。 在函数入口上，跟踪器会覆盖每个跟踪的函数的返回地址以设置自定义probe。 因此，原始返回地址存储在task_struct中的返回地址堆栈中。
两端的probe函数的有特殊功能，例如：

• 衡量一个函数的执行时间
• 具有可靠的调用堆栈来绘制函数调用图

函数图trace在以下几种情况下很有用：

• 想要找到奇怪的内核行为的原因，并且需要查看在任何区域（或特定区域）上发生的详细情况。
• 遇到了奇怪的延迟，但很难找到它的起源。
• 希望快速找到特定函数的执行路径
• 你只是想窥探一个正在运行的内核，并想看看那里发生了什么。

# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |

 0)               |  sys_open() {
 0)               |    do_sys_open() {
 0)               |      getname() {
 0)               |        kmem_cache_alloc() {
 0)   1.382 us    |          __might_sleep();
 0)   2.478 us    |        }
 0)               |        strncpy_from_user() {
 0)               |          might_fault() {
 0)   1.389 us    |            __might_sleep();
 0)   2.553 us    |          }
 0)   3.807 us    |        }
 0)   7.876 us    |      }
 0)               |      alloc_fd() {
 0)   0.668 us    |        _spin_lock();
 0)   0.570 us    |        expand_files();
 0)   0.586 us    |        _spin_unlock();

有几列可以动态 启用或禁用。 可以根据需要将几个选项组合。

• 默认启用显示执行该功能的cpu编号。 有时最好只跟踪一个cpu（请参阅tracing_cpu_mask文件），否则可能会在跟踪切换cpu时看到无序函数调用。

  • hide：echo nofuncgraph-cpu> trace_options
  • show：echo funcgraph-cpu> trace_options

• 在函数的结束括号行上显示函数的执行时间，或者在叶子的情况下显示在当前函数的同一行上。 它是默认启用的。

  • hide：echo nofuncgraph-duration> trace_options
  • show：echo funcgraph-duration> trace_options

• 函数执行花费的时间超过一定量，则会显示延迟标记

  • hide：echo nofuncgraph-overhead> trace_options
  • show：echo funcgraph-overhead> trace_options

取决于：funcgraph-duration，如：

  3) # 1837.709 us |          } /* __switch_to */
  3)               |          finish_task_switch() {
  3)   0.313 us    |            _raw_spin_unlock_irq();
  3)   3.177 us    |          }
  3) # 1889.063 us |        } /* __schedule */
  3) ! 140.417 us  |      } /* __schedule */
  3) # 2034.948 us |    } /* schedule */
  3) * 33998.59 us |  } /* schedule_preempt_disabled */

  [...]

  1)   0.260 us    |              msecs_to_jiffies();
  1)   0.313 us    |              __rcu_read_unlock();
  1) + 61.770 us   |            }
  1) + 64.479 us   |          }
  1)   0.313 us    |          rcu_bh_qs();
  1)   0.313 us    |          __local_bh_enable();
  1) ! 217.240 us  |        }
  1)   0.365 us    |        idle_cpu();
  1)               |        rcu_irq_exit() {
  1)   0.417 us    |          rcu_eqs_enter_common.isra.47();
  1)   3.125 us    |        }
  1) ! 227.812 us  |      }
  1) ! 457.395 us  |    }
  1) @ 119760.2 us |  }

  [...]

  2)               |    handle_IPI() {
  1)   6.979 us    |                  }
  2)   0.417 us    |      scheduler_ipi();
  1)   9.791 us    |                }
  1) + 12.917 us   |              }
  2)   3.490 us    |    }
  1) + 15.729 us   |            }
  1) + 18.542 us   |          }
  2) $ 3594274 us  |  }

+ 表示该函数执行时间超过10us。

! 表示该函数执行时间超过100us。

#表示该函数执行时间超过1000us。

*** **表示该函数执行时间超过10ms。

@表示该函数执行时间超过100ms。

$表示该函数执行时间超过1s。

• task / pid字段显示执行该功能的命令行和PID。 它是默认禁用的。

hide：echo nofuncgraph-proc> trace_options
show：echo funcgraph-proc> trace_options
例如：

  # tracer: function_graph
  #
  # CPU  TASK/PID        DURATION                  FUNCTION CALLS
  # |    |    |           |   |                     |   |   |   |
  0)    sh-4802     |               |                  d_free() {
  0)    sh-4802     |               |                    call_rcu() {
  0)    sh-4802     |               |                      __call_rcu() {
  0)    sh-4802     |   0.616 us    |                        rcu_process_gp_end();
  0)    sh-4802     |   2.899 us    |                      }
  0)    sh-4802     |   4.040 us    |                    }
  0)    sh-4802     |   5.151 us    |                  }
  0)    sh-4802     | + 49.370 us   |                }

• 显示系统自启动以来的绝对时间戳。 每次进入/退出函数时都会给出此时间的快照。
  • hide：echo nofuncgraph-abstime> trace_options
  • show：echo funcgraph-abstime> trace_options

  #
  #      TIME       CPU  DURATION                  FUNCTION CALLS
  #       |         |     |   |                     |   |   |   |
  360.774522 |   1)   0.541 us    |                     }
  360.774522 |   1)   4.663 us    |                   }
  360.774523 |   1)   0.541 us    |                   __wake_up_bit();
  360.774524 |   1)   6.796 us    |                 }
  360.774524 |   1)   7.952 us    |               }
  360.774525 |   1)   9.063 us    |             }
  360.774525 |   1)   0.615 us    |             journal_mark_dirty();
  360.774527 |   1)   0.578 us    |             __brelse();
  360.774528 |   1)               |             reiserfs_prepare_for_journal() {
  360.774528 |   1)               |               unlock_buffer() {
  360.774529 |   1)               |                 wake_up_bit() {
  360.774529 |   1)               |                   bit_waitqueue() {
  360.774530 |   1)   0.594 us    |                     __phys_addr();

如果该函数的起始不在跟踪缓冲区中，则函数名称始终显示在函数的右括号之后。

• 可以启用右括号后的函数名称显示，从而更轻松地使用grep搜索函数执行时间。 它是默认禁用的。
  • hide:echo nofuncgraph-tail > trace_options
  • show:echo funcgraph-tail > trace_options

 Example with nofuncgraph-tail (default):
  0)               |      putname() {
  0)               |        kmem_cache_free() {
  0)   0.518 us    |          __phys_addr();
  0)   1.757 us    |        }
  0)   2.861 us    |      }

  Example with funcgraph-tail:
  0)               |      putname() {
  0)               |        kmem_cache_free() {
  0)   0.518 us    |          __phys_addr();
  0)   1.757 us    |        } /* kmem_cache_free() */
  0)   2.861 us    |      } /* putname() */

可以使用trace_printk()对特定函数进行一些注释。例如，如果要在__might_sleep（）函数中放置注释，则只需要包含<linux/ftrace.h>并在__might_sleep()中调用trace_printk()

trace_printk("I'm a comment!\n")

5.11 动态trace

如果内核配置了CONFIG_DYNAMIC_FTRACE，则在禁用函数跟踪时，系统将几乎不会有任何开销。它的工作方式是mcount函数调用（放置在每个内核函数的开头，由gcc中的-pg产生），开始指向一个简单的返回。 （启用FTRACE将在编译内核时包含-pg。）

在编译时，每个C文件对象都通过recordmcount程序运行（位于scripts目录中）。该程序将解析C对象中的ELF头，以查找代码段.text中调用mcount的所有位置。从gcc 4.6版本开始，为x86添加了-mfentry，它调用了“__fentry__”而不是“mcount”。在创建堆栈帧之前调用。

请注意，并非所有跟踪部分。可以通过notrace阻止它们，查看available_filter_functions文件以查看可以跟踪的功能。

创建了一个名为“__mcount_loc”的部分，其中包含对代码段.text中所有mcount/fentry调用点的引用。 recordmcount程序将此部分重新链接回原始对象。内核的最后链接阶段将所有这些引用添加到单个表中。

在启动时，在初始化SMP之前，动态ftrace代码扫描此表并将所有位置更新为nops。它还会记录添加到available_filter_functions列表中的位置。模块在加载时和执行之前进行处理。卸载模块时，它还会从ftrace功能列表中删除其功能。这在模块卸载代码中是自动的，模块作者不需要担心它。

启用跟踪时，修改功能跟踪点的过程取决于体系结构。旧方法是使用kstop_machine来防止执行代码的CPU被修改（这可能导致CPU执行不需要的操作，特别是如果修改的代码跨越缓存（或页面）边界），并且将nops修补回调用。但这一次，他们不会调用mcount（这只是一个函数存根）。他们现在调用ftrace基础。

修改函数跟踪点的新方法是在要修改的位置放置断点，同步所有CPU，修改断点未覆盖的其余指令。再次同步所有CPU，然后将带有完成版本的断点删除到ftrace调用站点。

有些arch甚至不需要同步，并且只需将新代码打到旧代码之上，而其他CPU同时执行它们没有任何问题。记录被跟踪函数的一个特殊副作用是我们现在可以有选择地选择我们希望跟踪的函数以及我们希望mcount调用保留为nops的函数。

使用两个文件，一个用于启用对指定函数跟踪，另一个用于对指定函数禁用跟踪。 他们是： set_ftrace_filter和 set_ftrace_notrace 可以添加到这些文件的可用函数列表列在：

available_filter_functions

root@work:/sys/kernel/debug/tracing#cat available_filter_functions | more
run_init_process
try_to_run_init_process
do_one_initcall
match_dev_by_uuid
name_to_dev_t
rootfs_mount
rootfs_mount
calibration_delay_done
calibrate_delay
do_audit_syscall_entry
exit_to_usermode_loop
syscall_slow_exit_work
syscall_trace_enter_phase1
syscall_trace_enter_phase2
syscall_trace_enter
do_syscall_32_irqs_off
do_fast_syscall_32
vgetcpu_cpu_init
map_vdso
vgetcpu_cpu_notifier
arch_setup_additional_pages
compat_arch_setup_additional_pages
update_vsyscall_tz
.......

如果只对sys_nanosleep 和 hrtimer_interrupt两个函数感兴趣：

root@work:/sys/kernel/debug/tracing#echo sys_nanosleep hrtimer_interrupt > set_ftrace_filter
root@work:/sys/kernel/debug/tracing#echo function > current_tracer
root@work:/sys/kernel/debug/tracing#echo 1 > tracing_on
root@work:/sys/kernel/debug/tracing#usleep 1  #跟踪过程操作
root@work:/sys/kernel/debug/tracing#echo 0 > tracing_on
root@work:/sys/kernel/debug/tracing#cat trace

要查看正在跟踪哪些函数：

root@work:/sys/kernel/debug/tracing#cat set_ftrace_filter

过滤器还允许通配符匹配。
<match>* - 将匹配以<match>开头的函数
*<match> - 将匹配以<match>结尾的函数
*<match>* - 将匹配其中包含<match>的函数
<match1>*<match2> - 将匹配以<match1>开头并以<match2>结束的函

注意：最好使用引号括起通配符，否则shell可能会将参数扩展为本地目录中的文件名。

root@work:/sys/kernel/debug/tracing#echo 'hrtimer_*' > set_ftrace_filter

重置过滤器使用>，要追加则使用>>，和普通bash操作一样。

5.11.1 使用函数图动态trace

如果只想跟踪一个函数及其所有子函数，则只需将其名称echo到set_graph_function：

root@work:/sys/kernel/debug/tracing#echo __do_fault > set_graph_function

将生成以下__do_fault（）的“扩展”跟踪：

 0)               |  __do_fault() {
 0)               |    filemap_fault() {
 0)               |      find_lock_page() {
 0)   0.804 us    |        find_get_page();
 0)               |        __might_sleep() {
 0)   1.329 us    |        }
 0)   3.904 us    |      }
 0)   4.979 us    |    }
 0)   0.653 us    |    _spin_lock();
 0)   0.578 us    |    page_add_file_rmap();
 0)   0.525 us    |    native_set_pte_at();
 0)   0.585 us    |    _spin_unlock();
 0)               |    unlock_page() {
 0)   0.541 us    |      page_waitqueue();
 0)   0.639 us    |      __wake_up_bit();
 0)   2.786 us    |    }
 0) + 14.237 us   |  }
 0)               |  __do_fault() {
 0)               |    filemap_fault() {
 0)               |      find_lock_page() {
 0)   0.698 us    |        find_get_page();
 0)               |        __might_sleep() {
 0)   1.412 us    |        }
 0)   3.950 us    |      }
 0)   5.098 us    |    }
 0)   0.631 us    |    _spin_lock();
 0)   0.571 us    |    page_add_file_rmap();
 0)   0.526 us    |    native_set_pte_at();
 0)   0.586 us    |    _spin_unlock();
 0)               |    unlock_page() {
 0)   0.533 us    |      page_waitqueue();
 0)   0.638 us    |      __wake_up_bit();
 0)   2.793 us    |    }
 0) + 14.012 us   |  }

5.11.1 ftrace_enable

/proc/sysctl/ftrace_enable是函数跟踪器的一个开关。 默认情况下启用它（在内核中启用函数跟踪时）。 如果禁用，则禁用所有函数跟踪。 这不仅用于ftrace的函数跟踪器，还有其他用途（perf，kprobes，堆栈跟踪、profiling等）。这可以通过以下方式禁用和启用：

root@work:/sys/kernel/debug/tracing#sysctl kernel.ftrace_enabled = 0
root@work:/sys/kernel/debug/tracing#sysctl kernel.ftrace_enabled = 1

或

root@work:/sys/kernel/debug/tracing#echo 0> / proc / sys / kernel / ftrace_enabled
root@work:/sys/kernel/debug/tracing#echo 1> / proc / sys / kernel / ftrace_enabled

5.11.1 Filter commands

set_ftrace_filter接口支持一些命令，命令具有以下格式：
::
支持以下command：

• mod
  此命令启用每个模块的函数过滤。该参数定义了模块。例如，如果只想跟踪ext3模块中的write*函数，运行：

echo 'write*:mod:ext3' > set_ftrace_filter

通过>>追加到过滤器文件来添加更多不同模块的函数。通过添加！来删除特定的模块函数：

echo '!writeback*:mod:ext3' >> set_ftrace_filter

Mod命令支持模块通配。禁用除特定模块以外的所有函数的跟踪：

echo '!*:mod:!ext3' >> set_ftrace_filter

禁用所有模块的跟踪，但仍跟踪内核：

echo '!*:mod:*' >> set_ftrace_filter

仅为内核启用过滤器：

echo '*write*:mod:!*' >> set_ftrace_filter

为通配模块启用过滤器：

echo '*write*:mod:*snd*' >> set_ftrace_filter

• traceon/traceoff
  当命中指定的函数时，这些命令会打开和关闭跟踪。该参数确定跟踪系统打开和关闭的次数。如果未指定，则没有限制。 例如，要在前5次遇到__schedule_bug时禁用跟踪：

echo '__schedule_bug:traceoff:5' > set_ftrace_filter

要在命中__schedule_bug时始终禁用跟踪：

echo '__schedule_bug:traceoff' > set_ftrace_filter

无论它们是否追加到set_ftrace_filter，这些命令都是累积的。 要删除命令，请在！前面加上它。 并删除参数：

echo '!__schedule_bug:traceoff:0' > set_ftrace_filter

上面删除了具有计数器的__schedule_bug的traceoff命令。删除没有设定计数的命令：

echo '!__schedule_bug:traceoff' > set_ftrace_filter

• snapshot
  将在命中函数时触发快照。

echo 'native_flush_tlb_others:snapshot' > set_ftrace_filter

仅快照一次：

echo 'native_flush_tlb_others:snapshot:1' > set_ftrace_filter

要删除上述命令：

echo '!native_flush_tlb_others:snapshot' > set_ftrace_filter
echo '!native_flush_tlb_others:snapshot:0' > set_ftrace_filter

• enable_event/disable_event
  这些命令可以启用或禁用跟踪事件。 注意，因为函数跟踪回调非常敏感，所以当注册这些命令时，跟踪点被激活，但在“软”模式下被禁用。也就是说，将调用跟踪点，但不会跟踪。只要有触发它的命令，事件跟踪点就会保持此模式。

echo 'try_to_wake_up:enable_event:sched:sched_switch:2' >  set_ftrace_filter

格式为：

<function>:enable_event:<system>:<event>[:count]
<function>:disable_event:<system>:<event>[:count]

要删除事件命令：

echo '!try_to_wake_up:enable_event:sched:sched_switch:0' >  set_ftrace_filter
echo '!schedule:disable_event:sched:sched_switch' >  set_ftrace_filter

• dump
  当命中该函数时，它会将ftrace环形缓冲区的内容转储到控制台。如果您需要调试某些内容，并希望在某个函数被命中时转储跟踪，这将非常有用。 也许它是一个在tripple故障发生之前被调用的函数，并且不允许你获得常规转储。

• cpudump
  当命中该函数时，它会将当前CPU的ftrace环形缓冲区的内容转储到控制台。 与“dump”不同，它仅为CPU已执行这个函数才触发打印出环形缓冲区的内容。

5.11.1 trace_pipe

trace_pipe输出与跟踪文件相同的内容，但对跟踪的影响不同。 每次从trace_pipe读取都会被消耗掉。 意味着再次读写会不同， 跟踪是实时的。

root@work:/sys/kernel/debug/tracing#echo function > current_tracer
root@work:/sys/kernel/debug/tracing#cat trace_pipe > /tmp/trace.out &     #后台运行
root@work:/sys/kernel/debug/tracing#echo 1 > tracing_on
root@work:/sys/kernel/debug/tracing#usleep 1
root@work:/sys/kernel/debug/tracing#echo 0 > tracing_on
root@work:/sys/kernel/debug/tracing#cat trace         #无输出

注意，读取trace_pipe文件将阻塞，直到添加更多输入。

5.11.1 trace entries

在诊断内核中的问题时，拥有太多或不足够的数据都会很麻烦。 文件buffer_size_kb用于修改内部跟踪缓冲区的大小。 列出的数字是每个CPU可以记录的条目数。 要知道总大小，将可能的CPU数乘以条目数。如果分配太多，可能会导致触发Out-Of-Memory。
per_cpu缓冲区可以单独更改：

root@work:/sys/kernel/debug/tracing#echo 10000 > per_cpu/cpu0/buffer_size_kb
root@work:/sys/kernel/debug/tracing#echo 100 > per_cpu/cpu1/buffer_size_kb

当per_cpu缓冲区不相同时，顶层的buffer_size_kb将只显示一个X.

root@work:/sys/kernel/debug/tracing#cat buffer_size_kb
X.

这是buffer_total_size_kb有用的地方：

root@work:/sys/kernel/debug/tracing#cat buffer_total_size_kb 12916

写入顶级buffer_size_kb会将所有缓冲区重置为相同。

5.11.1 Snapshot

CONFIG_TRACER_SNAPSHOT使所有非延迟跟踪器都可以使用通用快照功能。 （记录最大延迟的延迟跟踪器，例如“irqsoff”或“wakeup”无法使用此功能，因为这些功能已在内部使用快照机制。）

快照在特定时间点保留当前跟踪缓冲区而不停止跟踪。 Ftrace使用备用缓冲区交换当前缓冲区，并在新的缓冲区中继续跟踪。“跟踪”中的以下tracefs文件与此功能相关：

snapshot:

这用于拍摄快照并读取快照的输出。 echo 1到此文件中以分配备用缓冲区并拍摄快照（交换），然后以与“跟踪”相同的格式从该文件中读取快照（如上文“文件系统”一节所述）。 两者都读取快照和跟踪可并行执行。 分配备用缓冲区时，echoing 0释放它，并且回显其他（正）值清除快照内容。
更多细节显示在下表中。

status\input	0	1	else
not allocated	(do nothing)	alloc+swap	(do nothing)
allocated	free	swap	clear

以下是使用快照功能的示例。

root@work:/sys/kernel/debug/tracing#echo 1 > events/sched/enable
root@work:/sys/kernel/debug/tracing#echo 1 > snapshot
root@work:/sys/kernel/debug/tracing#cat snapshot
# tracer: nop
#
# entries-in-buffer/entries-written: 71/71   #P:8
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
          <idle>-0     [005] d...  2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=snapshot-test-2 next_pid=2242 next_prio=120
           sleep-2242  [005] d...  2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_prio=120 prev_state=R ==> next_comm=kworker/5:1 next_pid=60 next_prio=120
[...]
          <idle>-0     [002] d...  2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=snapshot-test-2 next_pid=2229 next_prio=120
          
          
root@work:/sys/kernel/debug/tracing#cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 77/77   #P:8
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
          <idle>-0     [007] d...  2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=snapshot-test-2 next_pid=2243 next_prio=120
 snapshot-test-2-2229  [002] d...  2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=2229 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
[...]

如果在当前跟踪器是latency跟踪器之一时尝试使用此快照功能，则会得到以下结果。

root@work:/sys/kernel/debug/tracing#echo wakeup > current_tracer
root@work:/sys/kernel/debug/tracing#echo 1 > snapshot
	bash: echo: write error: Device or resource busy
root@work:/sys/kernel/debug/tracing#cat snapshot
	cat: snapshot: Device or resource busy

5.11.1 Instances

在tracefs中，跟踪目录是一个名为“instances”的目录。该目录可以使用mkdir在其中创建新目录，并使用rmdir删除目录。 在此目录中使用mkdir创建的目录在创建后已包含文件和其他目录。

root@work:/sys/kernel/debug/tracing# mkdir instances/foo
root@work:/sys/kernel/debug/tracing# ls instances/foo
buffer_size_kb  buffer_total_size_kb  events  free_buffer  per_cpu
set_event  snapshot  trace  trace_clock  trace_marker  trace_options
trace_pipe  tracing_on

可以看到，新目录看起来与traceing目录本身类似。 它非常相似，只是缓冲区和事件或创建的任何其他实例与主目录无关。

新目录中的文件就像traceing目录中具有相同名称的文件一样，除了使用的缓冲区是一个单独的新缓冲区。 这些文件会影响该缓冲区，但不影响主缓冲区，但trace_options除外。 目前，trace_options影响所有实例，顶级缓冲区影响相同，但在将来的版本中可能会更改。 也就是说，选项可能变得特定于它们所驻留的实例。

请注意，没有 function tracer文件，current_tracer和available_tracers也没有。 这是因为缓冲区当前只能为它们启用事件。

mkdir instances/foo
mkdir instances/bar
mkdir instances/zoot
echo 100000 > buffer_size_kb
echo 1000 > instances/foo/buffer_size_kb
echo 5000 > instances/bar/per_cpu/cpu1/buffer_size_kb
echo function > current_trace
echo 1 > instances/foo/events/sched/sched_wakeup/enable
echo 1 > instances/foo/events/sched/sched_wakeup_new/enable
echo 1 > instances/foo/events/sched/sched_switch/enable
echo 1 > instances/bar/events/irq/enable
echo 1 > instances/zoot/events/syscalls/enable

root@work:/sys/kernel/debug/tracing#cat trace_pipe
CPU:2 [LOST 11745 EVENTS]
            bash-2044  [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist
            bash-2044  [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave
            bash-2044  [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist
            bash-2044  [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist
            bash-2044  [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock
            bash-2044  [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype
            bash-2044  [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist
            bash-2044  [002] d... 10594.481034: zone_statistics <-get_page_from_freelist
            bash-2044  [002] d... 10594.481034: __inc_zone_state <-zone_statistics
            bash-2044  [002] d... 10594.481034: __inc_zone_state <-zone_statistics
            bash-2044  [002] .... 10594.481035: arch_dup_task_struct <-copy_process
[...]

root@work:/sys/kernel/debug/tracing#cat instances/foo/trace_pipe
            bash-1998  [000] d..4   136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 target_cpu=000
            bash-1998  [000] dN.4   136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu=000
          <idle>-0     [003] d.h3   136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 target_cpu=003
          <idle>-0     [003] d..3   136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=rcu_preempt next_pid=9 next_prio=120
     rcu_preempt-9     [003] d..3   136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
            bash-1998  [000] d..4   136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 target_cpu=000
            bash-1998  [000] dN.4   136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu=000
            bash-1998  [000] d..3   136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_state=R+ ==> next_comm=kworker/0:1 next_pid=59 next_prio=120
     kworker/0:1-59    [000] d..4   136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 target_cpu=001
     kworker/0:1-59    [000] d..3   136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_prio=120 prev_state=S ==> next_comm=bash next_pid=1998 next_prio=120
[...]

root@work:/sys/kernel/debug/tracing#cat instances/bar/trace_pipe
     migration/1-14    [001] d.h3   138.732674: softirq_raise: vec=3 [action=NET_RX]
          <idle>-0     [001] dNh3   138.732725: softirq_raise: vec=3 [action=NET_RX]
            bash-1998  [000] d.h1   138.733101: softirq_raise: vec=1 [action=TIMER]
            bash-1998  [000] d.h1   138.733102: softirq_raise: vec=9 [action=RCU]
            bash-1998  [000] ..s2   138.733105: softirq_entry: vec=1 [action=TIMER]
            bash-1998  [000] ..s2   138.733106: softirq_exit: vec=1 [action=TIMER]
            bash-1998  [000] ..s2   138.733106: softirq_entry: vec=9 [action=RCU]
            bash-1998  [000] ..s2   138.733109: softirq_exit: vec=9 [action=RCU]
            sshd-1995  [001] d.h1   138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4
            sshd-1995  [001] d.h1   138.733280: irq_handler_exit: irq=21 ret=unhandled
            sshd-1995  [001] d.h1   138.733281: irq_handler_entry: irq=21 name=eth0
            sshd-1995  [001] d.h1   138.733283: irq_handler_exit: irq=21 ret=handled
[...]

root@work:/sys/kernel/debug/tracing#cat instances/zoot/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 18996/18996   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
            bash-1998  [000] d...   140.733501: sys_write -> 0x2
            bash-1998  [000] d...   140.733504: sys_dup2(oldfd: a, newfd: 1)
            bash-1998  [000] d...   140.733506: sys_dup2 -> 0x1
            bash-1998  [000] d...   140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0)
            bash-1998  [000] d...   140.733509: sys_fcntl -> 0x1
            bash-1998  [000] d...   140.733510: sys_close(fd: a)
            bash-1998  [000] d...   140.733510: sys_close -> 0x0
            bash-1998  [000] d...   140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: 8)
            bash-1998  [000] d...   140.733515: sys_rt_sigprocmask -> 0x0
            bash-1998  [000] d...   140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650, sigsetsize: 8)
            bash-1998  [000] d...   140.733516: sys_rt_sigaction -> 0x0

您可以看到最顶层跟踪缓冲区的跟踪仅显示函数跟踪。 foo实例显示唤醒和任务切换。

要删除实例，只需删除它们的目录：

root@work:/sys/kernel/debug/tracing#rmdir instances/foo
root@work:/sys/kernel/debug/tracing#rmdir instances/bar
root@work:/sys/kernel/debug/tracing#rmdir instances/zoot

请注意，如果进程在其中一个实例目录中打开了跟踪文件，则rmdir将失败并显示EBUSY。

5.11.1 Stack trace

由于内核具有固定大小的堆栈，因此不要将其浪费在函数中。内核开发人员必须熟悉他们在堆栈上分配的内容。如果它们添加太多，系统可能存在堆栈溢出的危险，并且会发生损坏，通常会导致系统崩溃。

有一些工具可以检查这一点，通常中断定期检查使用情况。但是，如果您可以在每个函数调用中执行检查，这将非常有用。由于ftrace提供了一个函数跟踪器，因此可以方便地在每次函数调用时检查堆栈大小。这是通过堆栈跟踪器启用的。

CONFIG_STACK_TRACER启用ftrace堆栈跟踪功能。
要启用它，请在/proc/sys/kernel/stack_tracer_enabled中写入'1'。

root@work:/sys/kernel/debug/tracing#echo 1 > /proc/sys/kernel/stack_tracer_enabled

您还可以通过在内核命令行中启用它来在启动期间跟踪内核的堆栈大小，方法是在内核命令行参数中添加“stacktrace”。

运行几分钟后，输出如下：

root@work:/sys/kernel/debug/tracing#cat stack_max_size
2928
root@work:/sys/kernel/debug/tracing#cat stack_trace
        Depth    Size   Location    (18 entries)
        -----    ----   --------
  0)     2928     224   update_sd_lb_stats+0xbc/0x4ac
  1)     2704     160   find_busiest_group+0x31/0x1f1
  2)     2544     256   load_balance+0xd9/0x662
  3)     2288      80   idle_balance+0xbb/0x130
  4)     2208     128   __schedule+0x26e/0x5b9
  5)     2080      16   schedule+0x64/0x66
  6)     2064     128   schedule_timeout+0x34/0xe0
  7)     1936     112   wait_for_common+0x97/0xf1
  8)     1824      16   wait_for_completion+0x1d/0x1f
  9)     1808     128   flush_work+0xfe/0x119
 10)     1680      16   tty_flush_to_ldisc+0x1e/0x20
 11)     1664      48   input_available_p+0x1d/0x5c
 12)     1616      48   n_tty_poll+0x6d/0x134
 13)     1568      64   tty_poll+0x64/0x7f
 14)     1504     880   do_select+0x31e/0x511
 15)      624     400   core_sys_select+0x177/0x216
 16)      224      96   sys_select+0x91/0xb9
 17)      128     128   system_call_fastpath+0x16/0x1b

注意，如果gcc正在使用-mfentry，则在设置堆栈帧之前会跟踪函数。 这意味着当使用-mfentry时，堆栈跟踪器不会测试叶级函数。

目前，-mfentry仅在x86上由gcc 4.6.0及更高版本使用。

---

二、ftrace实现机制

1. 待补充....

start_kernel(void)
    ftrace_init();