ftrace - 函数追踪器¶
版权所有 2008 Red Hat Inc.
- 作者:
Steven Rostedt <srostedt@redhat.com>
- 许可:
GNU 自由文档许可证，版本 1.2 (双重许可在 GPL v2 下)
- 原始审查者:
Elias Oltmanns, Randy Dunlap, Andrew Morton, John Kacur, 和 David Teigland。
为以下版本编写: 2.6.28-rc2
为以下版本更新: 3.10
为以下版本更新: 4.13 - 版权所有 2017 VMware Inc. Steven Rostedt
转换为 rst 格式 - Changbin Du <changbin.du@intel.com>
简介¶
Ftrace 是一个内部追踪器，旨在帮助系统开发人员和设计人员找到内核内部发生的情况。它可以用于调试或分析发生在用户空间之外的延迟和性能问题。
虽然 ftrace 通常被认为是函数追踪器，但它实际上是一个由几个不同的追踪实用程序组成的框架。 有延迟追踪来检查中断禁用和启用之间发生的情况，以及抢占和从任务被唤醒到任务实际被调度进来的时间。
ftrace 最常见的用途之一是事件追踪。 在内核中存在数百个静态事件点，可以通过 tracefs 文件系统启用这些事件点，以查看内核某些部分中发生的情况。
有关更多信息，请参阅 事件追踪。
实现细节¶
有关 arch 移植者等的详细信息，请参阅 函数追踪器设计。
文件系统¶
Ftrace 使用 tracefs 文件系统来保存控制文件以及显示输出的文件。
当 tracefs 配置到内核中时 (选择任何 ftrace 选项都会这样做)，将创建目录 /sys/kernel/tracing。 要挂载此目录，您可以将其添加到您的 /etc/fstab 文件中
tracefs /sys/kernel/tracing tracefs defaults 0 0
或者您可以在运行时使用以下命令挂载它
mount -t tracefs nodev /sys/kernel/tracing
为了更快地访问该目录，您可能需要创建一个指向它的软链接
ln -s /sys/kernel/tracing /tracing
注意
在 4.1 之前，所有 ftrace 追踪控制文件都位于 debugfs 文件系统中，该文件系统通常位于 /sys/kernel/debug/tracing。 为了向后兼容，当挂载 debugfs 文件系统时，tracefs 文件系统将自动挂载到
/sys/kernel/debug/tracing
位于 tracefs 文件系统中的所有文件也将位于该 debugfs 文件系统目录中。
注意
任何选定的 ftrace 选项也将创建 tracefs 文件系统。 文档的其余部分将假设您位于 ftrace 目录中 (cd /sys/kernel/tracing)，并且只会专注于该目录中的文件，而不会因扩展的 “/sys/kernel/tracing” 路径名而分散内容。
就是这样! (假设您已将 ftrace 配置到您的内核中)
挂载 tracefs 后，您将可以访问 ftrace 的控制和输出文件。 以下是一些关键文件的列表
注意: 所有时间值均以微秒为单位。
current_tracer
用于设置或显示已配置的当前追踪器。 更改当前追踪器会清除环形缓冲区内容以及 “snapshot” 缓冲区。
available_tracers
保存已编译到内核中的不同类型的追踪器。 可以通过将其名称回显到 current_tracer 中来配置此处列出的追踪器。
tracing_on
设置或显示是否启用写入追踪环形缓冲区。 将 0 回显到此文件中以禁用追踪器，或将 1 回显到此文件中以启用追踪器。 注意，这只会禁用写入环形缓冲区，追踪开销可能仍在发生。
内核函数 tracing_off() 可以在内核中使用以禁用写入环形缓冲区，这将此文件设置为 “0”。 用户空间可以通过将 “1” 回显到该文件中来重新启用追踪。
注意，函数和事件触发器 “traceoff” 也会将此文件设置为零并停止追踪。 用户空间也可以使用此文件重新启用它。
trace
此文件以人类可读的格式保存追踪的输出 (如下所述)。 使用 O_TRUNC 标志打开此文件进行写入会清除环形缓冲区内容。 注意，此文件不是一个消费者。 如果追踪已关闭 (没有追踪器运行，或 tracing_on 为零)，则每次读取时它都会产生相同的输出。 当追踪开启时，它可能会产生不一致的结果，因为它试图读取整个缓冲区而不消耗它。
trace_pipe
输出与 “trace” 文件相同，但此文件旨在用于实时追踪。 从此文件的读取将阻塞，直到检索到新数据。 与 “trace” 文件不同，此文件是一个消费者。 这意味着从此文件的读取会导致顺序读取以显示更多当前数据。 从此文件读取数据后，它将被消耗，并且不会通过顺序读取再次读取。 “trace” 文件是静态的，如果追踪器没有添加更多数据，则每次读取时它都会显示相同的信息。
trace_options
此文件允许用户控制在上述输出文件之一中显示的数据量。 还存在一些选项可以修改追踪器或事件的工作方式 (堆栈追踪、时间戳等)。
options
这是一个目录，其中包含每个可用追踪选项的文件 (也在 trace_options 中)。 也可以通过将 “1” 或 “0” 分别写入具有选项名称的相应文件中来设置或清除选项。
tracing_max_latency
一些追踪器会记录最大延迟。 例如，中断禁用的最大时间。 最大时间保存在此文件中。 也会存储最大追踪，并通过 “trace” 显示。 仅当延迟大于此文件中的值 (以微秒为单位) 时，才会记录新的最大追踪。
通过将时间回显到此文件中，除非延迟大于此文件中的时间，否则不会记录任何延迟。
tracing_thresh
每当延迟大于此文件中的数字时，某些延迟追踪器将记录追踪。 仅当文件包含大于 0 的数字时才处于活动状态。 (以微秒为单位)
buffer_percent
这是环形缓冲区需要在唤醒等待者之前填充的水印。 也就是说，如果应用程序在每个 CPU 的 trace_pipe_raw 文件之一上调用阻塞读取 syscall，它将阻塞，直到缓冲区百分比指定的给定数据量在环形缓冲区中，然后它才会唤醒读取器。 这也控制了 splice 系统调用在此文件上的阻塞方式
0 - means to wake up as soon as there is any data in the ring buffer. 50 - means to wake up when roughly half of the ring buffer sub-buffers are full. 100 - means to block until the ring buffer is totally full and is about to start overwriting the older data.buffer_size_kb
设置或显示每个 CPU 缓冲区保存的千字节数。 默认情况下，每个 CPU 的追踪缓冲区大小相同。 显示的数字是 CPU 缓冲区的大小，而不是所有缓冲区的总大小。 追踪缓冲区以页面 (内核用于分配的内存块，通常为 4 KB 大小) 分配。 可能会分配一些额外的页面以容纳缓冲区管理元数据。 如果分配的最后一个页面有空间容纳比请求的更多字节，则将使用页面的其余部分，从而使实际分配大于请求或显示的大小。 (注意，由于缓冲区管理元数据，大小可能不是页面大小的倍数。)
各个 CPU 的缓冲区大小可能会有所不同 (请参阅下面的 “per_cpu/cpu0/buffer_size_kb”)，如果它们确实不同，则此文件将显示 “X”。
buffer_total_size_kb
显示所有追踪缓冲区的总组合大小。
buffer_subbuf_size_kb
设置或显示子缓冲区大小。 环形缓冲区被分成几个相同大小的 “子缓冲区”。 事件的大小不能大于子缓冲区的大小。 通常，子缓冲区的大小是架构的页面大小 (在 x86 上为 4K)。 子缓冲区还在开始时包含元数据，这也限制了事件的大小。 这意味着当子缓冲区为页面大小时，没有事件可以大于页面大小减去子缓冲区元数据。
注意，buffer_subbuf_size_kb 是用户指定子缓冲区最小大小的一种方式。 由于实现细节，内核可能会使其更大，或者如果内核无法处理该请求，则只需使操作失败。
更改子缓冲区大小允许事件大于页面大小。
注意: 更改子缓冲区大小时，将停止追踪，并且环形缓冲区和快照缓冲区中的任何数据都将被丢弃。
free_buffer
如果一个进程正在执行追踪，并且当进程完成时，即使它被信号杀死，环形缓冲区也应该缩小 “释放”，则可以使用此文件来实现该目的。 关闭此文件时，环形缓冲区将调整为其最小大小。 让一个正在追踪的进程也打开此文件，当进程退出时，此文件的文件描述符将被关闭，这样做，环形缓冲区将被 “释放”。
如果设置了 disable_on_free 选项，它也可能会停止追踪。
tracing_cpumask
这是一个掩码，允许用户仅在指定的 CPU 上进行追踪。 格式是一个表示 CPU 的十六进制字符串。
set_ftrace_filter
当配置了动态 ftrace 时 (请参阅下面的 “动态 ftrace” 部分)，代码会被动态修改 (代码文本重写) 以禁用函数分析器 (mcount) 的调用。 这使得可以配置追踪，而几乎没有性能开销。 这也具有启用或禁用要追踪的特定函数的副作用。 将函数名称回显到此文件中会将追踪限制为仅这些函数。 这会影响追踪器 “function” 和 “function_graph”，因此也会影响函数分析 (请参阅 “function_profile_enabled”)。
“available_filter_functions” 中列出的函数是可以写入此文件的函数。
此接口还允许使用命令。 有关更多详细信息，请参阅 “过滤器命令” 部分。
为了加快速度，由于处理字符串可能非常昂贵，并且需要检查所有已注册到追踪的函数，因此可以将索引写入此文件中。 写入的数字 (以 “1” 开头) 将改为选择 “available_filter_functions” 文件中相同行位置的相应值。
set_ftrace_notrace
这具有与 set_ftrace_filter 相反的效果。 此处添加的任何函数都不会被追踪。 如果一个函数同时存在于 set_ftrace_filter 和 set_ftrace_notrace 中，则该函数将 _不_ 被追踪。
set_ftrace_pid
使函数追踪器仅追踪在此文件中列出的 PID 的线程。
如果设置了 “function-fork” 选项，则当 PID 在此文件中的任务 fork 时，子任务的 PID 将自动添加到此文件中，并且该子任务也将被函数追踪器追踪。 此选项还将导致退出任务的 PID 从文件中删除。
set_ftrace_notrace_pid
使函数追踪器忽略在此文件中列出的 PID 的线程。
如果设置了 “function-fork” 选项，则当 PID 在此文件中的任务 fork 时，子任务的 PID 将自动添加到此文件中，并且该子任务也不会被函数追踪器追踪。 此选项还将导致退出任务的 PID 从文件中删除。
如果一个 PID 同时存在于此文件和 “set_ftrace_pid” 中，则此文件优先，并且该线程不会被追踪。
set_event_pid
使事件仅追踪在此文件中列出的 PID 的任务。 注意，sched_switch 和 sched_wake_up 也会追踪此文件中列出的事件。
要在 fork 时添加 PID 在此文件中的任务的子任务的 PID，请启用 “event-fork” 选项。 该选项还将导致当任务退出时，任务的 PID 从此文件中删除。
set_event_notrace_pid
使事件不追踪在此文件中列出的 PID 的任务。 注意，sched_switch 和 sched_wakeup 将追踪未在此文件中列出的线程，即使线程的 PID 在文件中，如果 sched_switch 或 sched_wakeup 事件也追踪应该被追踪的线程。
要在 fork 时添加 PID 在此文件中的任务的子任务的 PID，请启用 “event-fork” 选项。 该选项还将导致当任务退出时，任务的 PID 从此文件中删除。
set_graph_function
在此文件中列出的函数将导致函数图追踪器仅追踪这些函数以及它们调用的函数。 (有关更多详细信息，请参阅 “动态 ftrace” 部分)。 注意，set_ftrace_filter 和 set_ftrace_notrace 仍然会影响正在追踪的函数。
set_graph_notrace
与 set_graph_function 类似，但是当函数被命中时，它将禁用函数图追踪，直到它退出该函数。 这使得可以忽略由特定函数调用的追踪函数。
available_filter_functions
列出 ftrace 已处理并可以追踪的函数。 这些是您可以传递给 “set_ftrace_filter”、“set_ftrace_notrace”、“set_graph_function” 或 “set_graph_notrace” 的函数名称。 (有关更多详细信息，请参阅下面的 “动态 ftrace” 部分。)
available_filter_functions_addrs
与 available_filter_functions 类似，但显示每个函数的地址。 显示的地址是补丁站点地址，可能与 /proc/kallsyms 地址不同。
dyn_ftrace_total_info
此文件用于调试目的。 已转换为 nop 并且可用于追踪的函数数量。
enabled_functions
此文件更多的是用于调试 ftrace，但也可以用于查看是否有任何函数附加了回调。 不仅追踪基础设施使用 ftrace 函数追踪实用程序，而且其他子系统也可能使用。 此文件显示所有附加了回调的函数以及已附加的回调数量。 注意，回调也可能调用多个函数，这些函数不会在此计数中列出。
如果回调注册为由具有 “save regs” 属性 (因此开销更大) 的函数追踪，则将在返回寄存器的函数的同一行上显示 “R”。
如果回调注册为由具有 “ip modify” 属性 (因此可以更改 regs->ip) 的函数追踪，则将在可以被覆盖的函数的同一行上显示 “I”。
如果附加了非 ftrace 蹦床 (BPF)，则将显示 “D”。 注意，也可以附加正常的 ftrace 蹦床，但是一次只能将一个 “direct” 蹦床附加到给定的函数。
某些架构无法调用直接蹦床，而是将 ftrace ops 函数位于函数入口点上方。 在这种情况下，将显示 “O”。
如果一个函数过去曾通过 “ip modify” 或直接蹦床附加到它，则将显示 “M”。 此标志永远不会清除。 它用于了解一个函数是否曾经被 ftrace 基础设施修改过，并且可以用于调试。
如果架构支持它，它还会显示该函数正在直接调用哪个回调。 如果计数大于 1，则很可能是 ftrace_ops_list_func()。
如果一个函数的回调跳转到一个特定于回调而不是标准蹦床的蹦床，则将打印其地址以及蹦床调用的函数。
touched_functions
此文件包含所有曾经通过 ftrace 基础设施对其进行函数回调的函数。 它具有与 enabled_functions 相同的格式，但显示所有曾经被追踪的函数。
要查看任何曾经被 “ip modify” 或直接蹦床修改的函数，可以执行以下命令
grep ‘ M ‘ /sys/kernel/tracing/touched_functions
function_profile_enabled
设置后，它将启用函数追踪器或如果已配置，则启用函数图追踪器的所有函数。 它将保留已调用函数数量的直方图，并且如果已配置函数图追踪器，它还将跟踪在这些函数中花费的时间。 直方图内容可以在文件中显示
trace_stat/function<cpu> ( function0, function1, 等等).
trace_stat
一个包含不同追踪统计信息的目录。
kprobe_events
启用动态追踪点。 请参阅 基于 Kprobe 的事件追踪。
kprobe_profile
动态追踪点统计信息。 请参阅 基于 Kprobe 的事件追踪。
max_graph_depth
与函数图追踪器一起使用。 这是它将追踪到函数中的最大深度。 将此值设置为 1 将仅显示从用户空间调用的第一个内核函数。
printk_formats
这适用于读取原始格式文件的工具。 如果环形缓冲区中的事件引用一个字符串，则仅将指向该字符串的指针记录到缓冲区中，而不记录字符串本身。 这会阻止工具知道该字符串是什么。 此文件显示字符串和字符串的地址，允许工具将指针映射到字符串是什么。
saved_cmdlines
除非事件专门保存任务 comm，否则仅任务的 pid 记录在追踪事件中。 Ftrace 制作 pid 到 comms 的映射缓存，以尝试显示事件的 comms。 如果未列出 comm 的 pid，则在输出中显示 “<...>”。
如果选项 “record-cmd” 设置为 “0”，则在记录期间不会保存任务的 comms。 默认情况下，它是启用的。
saved_cmdlines_size
默认情况下，保存 128 个 comms (请参阅上面的 “saved_cmdlines”)。 要增加或减少缓存的 comms 数量，请将要缓存的 comms 数量回显到此文件中。
saved_tgids
如果设置了选项 “record-tgid”，则在每次调度上下文切换时，任务的任务组 ID 都保存在一个表中，该表将线程的 PID 映射到其 TGID。 默认情况下，禁用 “record-tgid” 选项。
snapshot
显示 “snapshot” 缓冲区，并允许用户获取当前正在运行的追踪的快照。 有关更多详细信息，请参阅下面的 “快照” 部分。
stack_max_size
当堆栈追踪器被激活时，它将显示它遇到的最大堆栈大小。 请参阅下面的 “堆栈追踪” 部分。
stack_trace
当堆栈追踪器被激活时，它将显示遇到的最大堆栈的堆栈回溯。 请参阅下面的 “堆栈追踪” 部分。
stack_trace_filter
这类似于 “set_ftrace_filter”，但它限制了堆栈追踪器将检查的函数。
trace_clock
每当一个事件被记录到环形缓冲区中时，都会添加一个 “时间戳”。 这个戳记来自指定时钟。 默认情况下，ftrace 使用 “local” 时钟。 这个时钟非常快并且严格按 CPU 计算，但在某些系统上，它可能与其他 CPU 不单调。 换句话说，本地时钟可能与其他 CPU 上的本地时钟不同步。
用于追踪的常用时钟
# cat trace_clock [local] global counter 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)，它基于快速单调时钟，但也考虑了暂停期间花费的时间。 由于时钟访问被设计用于暂停路径中的追踪，因此如果在暂停时间计算完成后，在快速单声道时钟更新之前访问时钟，则可能会出现一些副作用。 在这种情况下，时钟更新的发生似乎比正常情况略早。 此外，在 32 位系统上，64 位启动偏移量可能会看到部分更新。 这些影响很少见，并且后期处理应该能够处理它们。 有关更多信息，请参阅
ktime_get_boot_fast_ns()函数中的注释。- tai
这是 tai 时钟 (CLOCK_TAI)，它源自挂钟时间。 但是，此时钟不会遇到因 NTP 插入闰秒而导致的不连续性和向后跳转。 由于时钟访问被设计用于追踪，因此可能会出现副作用。 如果内部 TAI 偏移量已更新，例如，由设置系统时间或使用带偏移量的 adjtimex() 引起，则时钟访问可能会产生错误的读数。 这些影响很少见，并且后期处理应该能够处理它们。 有关更多信息，请参阅
ktime_get_tai_fast_ns()函数中的注释。要设置时钟，只需将时钟名称回显到此文件中
# 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", O_WRONLY);trace_marker_raw
这类似于上面的 trace_marker，但旨在将二进制数据写入其中，其中可以使用一个工具从 trace_pipe_raw 中解析数据。
uprobe_events
在程序中添加动态追踪点。 请参阅 Uprobe-tracer: 基于 Uprobe 的事件追踪
uprobe_profile
Uprobe 统计信息。 请参阅 uprobetrace.txt
instances
这是一种创建多个追踪缓冲区的方法，其中不同的事件可以记录在不同的缓冲区中。 请参阅下面的 “实例” 部分。
events
这是追踪事件目录。 它保存已编译到内核中的事件追踪点 (也称为静态追踪点)。 它显示了存在的事件追踪点以及它们如何按系统分组。 在各个级别都有 “enable” 文件，当向其中写入 “1” 时，可以启用这些追踪点。
有关更多信息，请参阅 事件追踪。
set_event
通过将事件回显到此文件中，将启用该事件。
有关更多信息，请参阅 事件追踪。
available_events
可以在追踪中启用的事件列表。
有关更多信息，请参阅 事件追踪。
timestamp_mode
某些追踪器可能会更改在将追踪事件记录到事件缓冲区时使用的时间戳模式。 具有不同模式的事件可以共存于一个缓冲区中，但记录事件时生效的模式确定用于该事件的时间戳模式。 默认时间戳模式为 “delta”。
用于追踪的常用时间戳模式
# cat timestamp_mode [delta] absolute
用方括号括起来的时间戳模式是有效的模式。
- delta: 默认时间戳模式 - 时间戳是针对每个缓冲区时间戳的增量。
每个缓冲区时间戳。
- absolute: 时间戳是一个完整的时间戳，而不是针对其他某个值的增量。
针对其他某个值。 因此，它占用更多空间并且效率较低。
hwlat_detector
硬件延迟检测器的目录。 请参阅下面的“硬件延迟检测器”部分。
per_cpu
这是一个包含每个 CPU 跟踪信息的目录。
per_cpu/cpu0/buffer_size_kb
ftrace 缓冲区是按 CPU 定义的。 也就是说，每个 CPU 都有一个单独的缓冲区，以允许原子地完成写入，并且免受缓存抖动的影响。 这些缓冲区可能具有不同的大小。 此文件类似于 buffer_size_kb 文件，但它仅显示或设置特定 CPU（此处为 cpu0）的缓冲区大小。
per_cpu/cpu0/trace
这类似于“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
这类似于主“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
已读取的事件数量。
跟踪器¶
这是当前可以配置的跟踪器的列表。
“function”
函数调用跟踪器，用于跟踪所有内核函数。
“function_graph”
与函数跟踪器类似，不同之处在于函数跟踪器探测函数是在其入口处，而函数图跟踪器在函数的入口和出口处都进行跟踪。 然后，它提供了绘制类似于 C 代码源的函数调用图的能力。
请注意，函数图计算函数内部开始和返回的时间，以及每个实例的时间。 如果有两个实例运行函数图跟踪器并跟踪相同的函数，则时间长度可能会略有偏差，因为每个实例单独读取时间戳，而不是同时读取。
“blk”
块跟踪器。 blktrace 用户应用程序使用的跟踪器。
“hwlat”
硬件延迟跟踪器用于检测硬件是否产生任何延迟。 请参阅下面的“硬件延迟检测器”部分。
“irqsoff”
跟踪禁用中断的区域，并保存具有最长最大延迟的跟踪。 请参阅 tracing_max_latency。 当记录一个新的最大值时，它会替换旧的跟踪。 最好使用启用延迟格式选项来查看此跟踪，当选择跟踪器时会自动启用此选项。
“preemptoff”
与 irqsoff 类似，但跟踪和记录禁用抢占的时间量。
“preemptirqsoff”
与 irqsoff 和 preemptoff 类似，但跟踪和记录禁用 irq 和/或抢占的最长时间。
“wakeup”
跟踪并记录最高优先级任务在被唤醒后被调度所需的最大延迟。 以普通开发人员期望的方式跟踪所有任务。
“wakeup_rt”
跟踪并记录仅 RT 任务（如当前的“wakeup”所做的那样）被唤醒所需的最大延迟。 这对于那些对 RT 任务的唤醒时间感兴趣的人很有用。
“wakeup_dl”
跟踪并记录 SCHED_DEADLINE 任务被唤醒所需的最大延迟（如“wakeup”和“wakeup_rt”所做的那样）。
“mmiotrace”
一个特殊的跟踪器，用于跟踪二进制模块。 它将跟踪模块对硬件进行的所有调用。 以及它写入和读取 I/O 的所有内容。
“branch”
当跟踪内核中的 likely/unlikely 调用时，可以配置此跟踪器。 它将跟踪何时命中 likely 和 unlikely 分支，以及它对其正确预测的正确性。
“nop”
这是“不跟踪任何内容”的跟踪器。 要从跟踪中删除所有跟踪器，只需将“nop”回显到 current_tracer 中。
错误条件¶
对于大多数 ftrace 命令，故障模式很明显，并使用标准返回码进行通信。
对于其他更复杂的命令，可以通过 tracing/error_log 文件获得扩展的错误信息。 对于支持它的命令，在出错后读取 tracing/error_log 文件将显示关于出错原因的更详细信息（如果可用）。 tracing/error_log 文件是一个循环错误日志，显示最后 (8) 个失败命令的少量（目前为 8 个）ftrace 错误。
扩展错误信息和用法采用此示例中显示的形式
# echo xxx > /sys/kernel/tracing/events/sched/sched_wakeup/trigger echo: write error: Invalid argument # cat /sys/kernel/tracing/error_log [ 5348.887237] location: error: Couldn't yyy: zzz Command: xxx ^ [ 7517.023364] location: error: Bad rrr: sss Command: ppp qqq ^要清除错误日志，请将空字符串回显到其中
# echo > /sys/kernel/tracing/error_log
使用跟踪器的示例¶
以下是一些典型的示例，说明了仅使用 tracefs 接口（不使用任何用户空间实用程序）控制跟踪器时如何使用它们。
输出格式：¶
这是文件“trace”的输出格式示例
# tracer: function
#
# entries-in-buffer/entries-written: 140080/250280 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
bash-1977 [000] .... 17284.993652: sys_close <-system_call_fastpath
bash-1977 [000] .... 17284.993653: __close_fd <-sys_close
bash-1977 [000] .... 17284.993653: _raw_spin_lock <-__close_fd
sshd-1974 [003] .... 17284.993653: __srcu_read_unlock <-fsnotify
bash-1977 [000] .... 17284.993654: add_preempt_count <-_raw_spin_lock
bash-1977 [000] ...1 17284.993655: _raw_spin_unlock <-__close_fd
bash-1977 [000] ...1 17284.993656: sub_preempt_count <-_raw_spin_unlock
bash-1977 [000] .... 17284.993657: filp_close <-__close_fd
bash-1977 [000] .... 17284.993657: dnotify_flush <-filp_close
sshd-1974 [003] .... 17284.993658: sys_select <-system_call_fastpath
....
标头与由跟踪表示的跟踪器名称一起打印。 在这种情况下，跟踪器是“function”。 然后，它显示缓冲区中的事件数以及写入的总条目数。 差异是由于缓冲区已满而丢失的条目数（250280 - 140080 = 丢失了 110200 个事件）。
标头解释了事件的内容。 任务名称“bash”，任务 PID“1977”，它正在运行的 CPU“000”，延迟格式（如下所述），<secs>.<usecs> 格式的时间戳，被跟踪的函数名称“sys_close”以及调用此函数的父函数“system_call_fastpath”。 时间戳是进入函数的时间。
延迟跟踪格式¶
当启用 latency-format 选项或设置其中一个延迟跟踪器时，跟踪文件会提供更多信息来了解为什么发生延迟。 这是一个典型的跟踪
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 259 us, #4/4, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: ps-6143 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: __lock_task_sighand
# => ended at: _raw_spin_unlock_irqrestore
#
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
ps-6143 2d... 0us!: trace_hardirqs_off <-__lock_task_sighand
ps-6143 2d..1 259us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore
ps-6143 2d..1 263us+: time_hardirqs_on <-_raw_spin_unlock_irqrestore
ps-6143 2d..1 306us : <stack trace>
=> trace_hardirqs_on_caller
=> trace_hardirqs_on
=> _raw_spin_unlock_irqrestore
=> do_task_stat
=> proc_tgid_stat
=> proc_single_show
=> seq_read
=> vfs_read
=> sys_read
=> system_call_fastpath
这表明当前跟踪器是“irqsoff”，跟踪禁用中断的时间。 它给出了跟踪版本（永远不会改变）和执行它的内核版本 (3.8)。 然后，它以微秒为单位显示最大延迟 (259 us)。 显示的跟踪条目数和总数（均为 4：#4/4）。 VP、KP、SP 和 HP 始终为零，保留供以后使用。 #P 是在线 CPU 的数量 (#P:4)。
任务是发生延迟时正在运行的进程。 (ps pid: 6143)。
导致延迟的开始和停止（禁用和启用中断的函数）
__lock_task_sighand 是禁用中断的地方。
_raw_spin_unlock_irqrestore 是再次启用中断的地方。
标头之后的下一行是跟踪本身。 标头解释了哪个是哪个。
cmd：跟踪中进程的名称。
pid：该进程的 PID。
CPU#：该进程正在其上运行的 CPU。
irqs-off：'d' 中断被禁用。 否则为“.”。
- need-resched
“B”所有，设置了 TIF_NEED_RESCHED、PREEMPT_NEED_RESCHED 和 TIF_RESCHED_LAZY，
“N”同时设置了 TIF_NEED_RESCHED 和 PREEMPT_NEED_RESCHED，
“n”仅设置了 TIF_NEED_RESCHED，
“p”仅设置了 PREEMPT_NEED_RESCHED，
“L”同时设置了 PREEMPT_NEED_RESCHED 和 TIF_RESCHED_LAZY，
“b”同时设置了 TIF_NEED_RESCHED 和 TIF_RESCHED_LAZY，
“l”仅设置了 TIF_RESCHED_LAZY
否则为“.”。
- hardirq/softirq
“Z” - NMI 发生在 hardirq 内部
“z” - NMI 正在运行
“H” - hard irq 发生在 softirq 内部。
“h” - hard irq 正在运行
“s” - soft irq 正在运行
“.” - 正常上下文。
preempt-depth：preempt_disabled 的级别
以上内容主要对内核开发人员有意义。
- time
启用 latency-format 选项后，跟踪文件输出包括相对于跟踪开始的时间戳。 这与禁用 latency-format 时的输出不同，后者包括绝对时间戳。
- delay
这只是为了更好地引起您的注意。 并且需要修复为仅相对于同一 CPU。 标记由当前跟踪和下一个跟踪之间的差异决定。
“$” - 大于 1 秒
“@” - 大于 100 毫秒
“*” - 大于 10 毫秒
“#” - 大于 1000 微秒
“!” - 大于 100 微秒
“+” - 大于 10 微秒
“ ” - 小于或等于 10 微秒。
其余与“trace”文件相同。
请注意，延迟跟踪器通常以回溯结束，以便轻松找到延迟发生的位置。
trace_options¶
trace_options 文件（或 options 目录）用于控制在跟踪输出中打印的内容，或操作跟踪器。 要查看可用的内容，只需 cat 该文件
cat trace_options
print-parent
nosym-offset
nosym-addr
noverbose
noraw
nohex
nobin
noblock
nofields
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
function-trace
nofunction-fork
nodisplay-graph
nostacktrace
nobranch
要禁用其中一个选项，请回显以“no”开头的选项
echo noprint-parent > trace_options
要启用一个选项，请省略“no”
echo sym-offset > trace_options
以下是可用选项
- print-parent
在函数跟踪上，显示调用（父）函数以及被跟踪的函数。
print-parent: bash-4000 [01] 1477.606694: simple_strtoul <-kstrtoul noprint-parent: bash-4000 [01] 1477.606694: simple_strtoul- sym-offset
不仅显示函数名称，还显示函数中的偏移量。 例如，您将看到“ktime_get+0xb/0x20”，而不是只看到“ktime_get”。
sym-offset: bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0- sym-addr
这还将显示函数地址以及函数名称。
sym-addr: bash-4000 [01] 1477.606694: simple_strtoul <c0339346>- verbose
这处理启用了 latency-format 选项时的跟踪文件。
bash 4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \ (+0.000ms): simple_strtoul (kstrtoul)- raw
这将显示原始数字。 此选项最适合与用户应用程序一起使用，这些应用程序可以比在内核中更好地转换原始数字。
- hex
与 raw 类似，但数字将采用十六进制格式。
- bin
这将以原始二进制形式打印格式。
- block
设置后，轮询时读取 trace_pipe 不会阻塞。
- fields
按照它们的类型描述的方式打印字段。 这比使用十六进制、二进制或原始格式更好，因为它能更好地解析事件的内容。
- trace_printk
可以禁用
trace_printk()写入缓冲区。- trace_printk_dest
设置为使
trace_printk()和类似的内部跟踪函数写入此实例。 请注意，只有一个跟踪实例可以设置此项。 通过设置此标志，它会清除先前设置它的实例的 trace_printk_dest 标志。 默认情况下，顶级跟踪设置了此项，如果另一个实例设置了此项然后清除了它，则将再次设置此项。此标志无法由顶级实例清除，因为它是一个默认实例。 顶级实例清除此标志的唯一方法是在另一个实例中设置它。
- copy_trace_marker
如果有些应用程序硬编码写入顶级 trace_marker 文件 (/sys/kernel/tracing/trace_marker 或 trace_marker_raw)，并且该工具希望它进入一个实例，则可以使用此选项。 创建一个实例并设置此选项，然后对顶级 trace_marker 文件的所有写入也将重定向到此实例。
请注意，默认情况下，顶级实例设置了此选项。 如果禁用它，则对 trace_marker 或 trace_marker_raw 文件的写入将不会写入顶级文件。 如果没有实例设置此选项，则写入将出错，错误代码为 ENODEV。
- annotate
当 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 启用时，这尤其有用，否则，在应用程序不再运行后，您将无法将地址解析为对象/文件/行
查找在您读取 trace,trace_pipe 时执行。 示例
a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0 x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]- printk-msg-only
设置后，
trace_printk()s 将仅显示格式而不显示其参数（如果使用 trace_bprintk() 或 trace_bputs() 保存trace_printk()）。- context-info
仅显示事件数据。 隐藏 comm、PID、时间戳、CPU 和其他有用的数据。
- latency-format
此选项更改跟踪输出。 启用后，跟踪将显示有关延迟的其他信息，如“延迟跟踪格式”中所述。
- pause-on-trace
设置后，打开跟踪文件进行读取将暂停写入环形缓冲区（就像将 tracing_on 设置为零一样）。 这模拟了跟踪文件的原始行为。 关闭文件后，将再次启用跟踪。
- hash-ptr
设置后，事件 printk 格式中的“%p”将显示哈希指针值而不是实际地址。 如果您想找出哪个哈希值对应于跟踪日志中的实际值，这将很有用。
- record-cmd
当启用任何事件或跟踪器时，会在 sched_switch 跟踪点中启用一个钩子，以使用映射的 pid 和 comm 填充 comm 缓存。 但这可能会导致一些开销，如果您只关心 pid，而不关心任务的名称，则禁用此选项可以降低跟踪的影响。 请参阅“saved_cmdlines”。
- record-tgid
当启用任何事件或跟踪器时，会在 sched_switch 跟踪点中启用一个钩子，以填充映射的线程组 ID (TGID) 映射到 pid 的缓存。 请参阅“saved_tgids”。
- overwrite
这控制着当跟踪缓冲区已满时会发生什么。 如果为“1”（默认），则最旧的事件将被丢弃和覆盖。 如果为“0”，则最新的事件将被丢弃。（请参阅 per_cpu/cpu0/stats 中的 overrun 和 dropped）
- disable_on_free
当 free_buffer 关闭时，跟踪将停止（tracing_on 设置为 0）。
- irq-info
显示中断、抢占计数、need resched 数据。 禁用后，跟踪看起来像
# 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
设置后，当那些任务 fork 时，set_event_pid 中列出的具有 PID 的任务的子任务的 PID 将添加到 set_event_pid 中。 此外，当 set_event_pid 中的 PID 的任务退出时，它们的 PID 将从文件中删除。
这也影响 set_event_notrace_pid 中列出的 PID。
- function-trace
如果启用此选项（默认情况下已启用），延迟跟踪器将启用函数跟踪。 禁用后，延迟跟踪器不会跟踪函数。 这会在执行延迟测试时降低跟踪器的开销。
- function-fork
设置后，当那些任务 fork 时，set_ftrace_pid 中列出的具有 PID 的任务的子任务的 PID 将添加到 set_ftrace_pid 中。 此外，当 set_ftrace_pid 中的 PID 的任务退出时，它们的 PID 将从文件中删除。
这也影响 set_ftrace_notrace_pid 中的 PID。
- display-graph
设置后，延迟跟踪器（irqsoff、wakeup 等）将使用函数图跟踪而不是函数跟踪。
- stacktrace
设置后，在记录任何跟踪事件后，都会记录堆栈跟踪。
- branch
使用跟踪器启用分支跟踪。 这会启用分支跟踪器以及当前设置的跟踪器。 使用“nop”跟踪器启用此项与仅启用“branch”跟踪器相同。
提示
某些跟踪器有自己的选项。 它们仅在跟踪器处于活动状态时才会出现在此文件中。 它们始终出现在 options 目录中。
以下是每个跟踪器的选项
函数跟踪器的选项
- func_stack_trace
设置后，在记录的每个函数之后都会记录堆栈跟踪。 注意！ 在启用此选项之前，请使用“set_ftrace_filter”限制记录的函数，否则系统性能将严重下降。 在清除函数过滤器之前，请记住禁用此选项。
function_graph 跟踪器的选项
由于 function_graph 跟踪器的输出略有不同，因此它有自己的选项来控制显示的内容。
- funcgraph-overrun
设置后，每次跟踪函数后都会显示图堆栈的“overrun”。 overrun 是调用堆栈的深度大于为每个任务保留的深度时。 每个任务都有一个固定的函数数组来跟踪调用图。 如果调用的深度超过了该深度，则不会跟踪该函数。 overrun 是由于超过此数组而错过的函数数。
- funcgraph-cpu
设置后，将显示发生跟踪的 CPU 的 CPU 编号。
- funcgraph-overhead
设置后，如果函数花费的时间超过一定量，则会显示一个延迟标记。 请参阅上面的“delay”，在标头描述下。
- funcgraph-proc
与其他跟踪器不同，默认情况下不显示进程的命令行，而是仅在上下文切换期间跟踪任务进出时才显示。 启用此选项会在每行显示每个进程的命令。
- funcgraph-duration
在每个函数的末尾（返回），以微秒为单位显示函数中的时间量。
- funcgraph-abstime
设置后，时间戳将在每行显示。
- funcgraph-irqs
禁用后，发生在中断内部的函数将不会被跟踪。
- funcgraph-tail
设置后，返回事件将包括它所代表的函数。 默认情况下，这是关闭的，并且仅为函数的返回显示一个结束花括号“}”。
- funcgraph-retval
设置后，每个跟踪函数的返回值将在等号“=”后打印。 默认情况下，这是关闭的。
- funcgraph-retval-hex
设置后，返回值将始终以十六进制格式打印。 如果未设置该选项并且返回值是错误代码，则将以有符号十进制格式打印；否则，它也将以十六进制格式打印。 默认情况下，此选项是关闭的。
- sleep-time
运行函数图跟踪器时，包括任务在其函数中调度的out时间。 启用后，它将把任务调度的out时间计为函数调用的一部分。
- graph-time
在使用函数图跟踪器运行函数分析器时，包括调用嵌套函数的时间。 如果未设置此项，则报告的函数时间将仅包括函数自身执行的时间，不包括它调用的函数的时间。
blk 跟踪器的选项
- blk_classic
显示更简约的输出。
irqsoff¶
当中断被禁用时，CPU 无法对任何其他外部事件做出反应（除了 NMI 和 SMI）。 这会阻止定时器中断触发或鼠标中断让内核知道新的鼠标事件。 结果是反应时间的延迟。
irqsoff 跟踪器跟踪禁用中断的时间。 当达到新的最大延迟时，跟踪器会保存导致该延迟点的跟踪，以便每次达到新的最大值时，旧的保存跟踪将被丢弃，并保存新的跟踪。
要重置最大值，请将 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
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 16 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: run_timer_softirq
# => ended at: run_timer_softirq
#
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
<idle>-0 0d.s2 0us+: _raw_spin_lock_irq <-run_timer_softirq
<idle>-0 0dNs3 17us : _raw_spin_unlock_irq <-run_timer_softirq
<idle>-0 0dNs3 17us+: trace_hardirqs_on <-run_timer_softirq
<idle>-0 0dNs3 25us : <stack trace>
=> _raw_spin_unlock_irq
=> run_timer_softirq
=> __do_softirq
=> call_softirq
=> do_softirq
=> irq_exit
=> smp_apic_timer_interrupt
=> apic_timer_interrupt
=> rcu_idle_exit
=> cpu_idle
=> rest_init
=> start_kernel
=> x86_64_start_reservations
=> x86_64_start_kernel
在这里，我们看到我们有 16 微秒的延迟（非常好）。 run_timer_softirq 中的 _raw_spin_lock_irq 禁用了中断。 16 和显示的时间戳 25us 之间的差异是因为在记录最大延迟的时间和记录具有该延迟的函数的时间之间时钟增加了。
请注意，上面的示例未设置 function-trace。 如果我们设置 function-trace，我们将获得更大的输出
with echo 1 > options/function-trace
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 71 us, #168/168, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: ata_scsi_queuecmd
# => ended at: ata_scsi_queuecmd
#
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
bash-2042 3d... 0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd
bash-2042 3d... 0us : add_preempt_count <-_raw_spin_lock_irqsave
bash-2042 3d..1 1us : ata_scsi_find_dev <-ata_scsi_queuecmd
bash-2042 3d..1 1us : __ata_scsi_find_dev <-ata_scsi_find_dev
bash-2042 3d..1 2us : ata_find_dev.part.14 <-__ata_scsi_find_dev
bash-2042 3d..1 2us : ata_qc_new_init <-__ata_scsi_queuecmd
bash-2042 3d..1 3us : ata_sg_init <-__ata_scsi_queuecmd
bash-2042 3d..1 4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd
bash-2042 3d..1 4us : ata_build_rw_tf <-ata_scsi_rw_xlat
[...]
bash-2042 3d..1 67us : delay_tsc <-__delay
bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
bash-2042 3d..2 67us : sub_preempt_count <-delay_tsc
bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
bash-2042 3d..2 68us : sub_preempt_count <-delay_tsc
bash-2042 3d..1 68us+: ata_bmdma_start <-ata_bmdma_qc_issue
bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
bash-2042 3d..1 72us+: trace_hardirqs_on <-ata_scsi_queuecmd
bash-2042 3d..1 120us : <stack trace>
=> _raw_spin_unlock_irqrestore
=> ata_scsi_queuecmd
=> scsi_dispatch_cmd
=> scsi_request_fn
=> __blk_run_queue_uncond
=> __blk_run_queue
=> blk_queue_bio
=> submit_bio_noacct
=> submit_bio
=> submit_bh
=> __ext3_get_inode_loc
=> ext3_iget
=> ext3_lookup
=> lookup_real
=> __lookup_hash
=> walk_component
=> lookup_last
=> path_lookupat
=> filename_lookup
=> user_path_at_empty
=> user_path_at
=> vfs_fstatat
=> vfs_stat
=> sys_newstat
=> system_call_fastpath
在这里，我们跟踪了 71 微秒的延迟。 但我们也看到了在那段时间内调用的所有函数。 请注意，通过启用函数跟踪，我们会产生额外的开销。 此开销可能会延长延迟时间。 但无论如何，此跟踪提供了一些非常有用的调试信息。
如果我们更喜欢函数图输出而不是函数输出，我们可以设置 display-graph 选项
with echo 1 > options/display-graph
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 4.20.0-rc6+
# --------------------------------------------------------------------
# latency: 3751 us, #274/274, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: bash-1507 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: free_debug_processing
# => ended at: return_to_handler
#
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| /
# REL TIME CPU TASK/PID |||| DURATION FUNCTION CALLS
# | | | | |||| | | | | | |
0 us | 0) bash-1507 | d... | 0.000 us | _raw_spin_lock_irqsave();
0 us | 0) bash-1507 | d..1 | 0.378 us | do_raw_spin_trylock();
1 us | 0) bash-1507 | d..2 | | set_track() {
2 us | 0) bash-1507 | d..2 | | save_stack_trace() {
2 us | 0) bash-1507 | d..2 | | __save_stack_trace() {
3 us | 0) bash-1507 | d..2 | | __unwind_start() {
3 us | 0) bash-1507 | d..2 | | get_stack_info() {
3 us | 0) bash-1507 | d..2 | 0.351 us | in_task_stack();
4 us | 0) bash-1507 | d..2 | 1.107 us | }
[...]
3750 us | 0) bash-1507 | d..1 | 0.516 us | do_raw_spin_unlock();
3750 us | 0) bash-1507 | d..1 | 0.000 us | _raw_spin_unlock_irqrestore();
3764 us | 0) bash-1507 | d..1 | 0.000 us | tracer_hardirqs_on();
bash-1507 0d..1 3792us : <stack trace>
=> free_debug_processing
=> __slab_free
=> kmem_cache_free
=> vm_area_free
=> remove_vma
=> exit_mmap
=> mmput
=> begin_new_exec
=> load_elf_binary
=> search_binary_handler
=> __do_execve_file.isra.32
=> __x64_sys_execve
=> do_syscall_64
=> entry_SYSCALL_64_after_hwframe
preemptoff¶
当禁用抢占时，我们可能能够接收中断，但无法抢占该任务，并且优先级更高的任务必须等待再次启用抢占后才能抢占优先级较低的任务。
preemptoff 跟踪器跟踪禁用抢占的位置。 与 irqsoff 跟踪器一样，它记录禁用抢占的最大延迟。 preemptoff 跟踪器的控制与 irqsoff 跟踪器非常相似。
# echo 0 > options/function-trace
# echo preemptoff > current_tracer
# echo 1 > tracing_on
# echo 0 > tracing_max_latency
# ls -ltr
[...]
# echo 0 > tracing_on
# cat trace
# tracer: preemptoff
#
# preemptoff latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 46 us, #4/4, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: do_IRQ
# => ended at: do_IRQ
#
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
sshd-1991 1d.h. 0us+: irq_enter <-do_IRQ
sshd-1991 1d..1 46us : irq_exit <-do_IRQ
sshd-1991 1d..1 47us+: trace_preempt_on <-do_IRQ
sshd-1991 1d..1 52us : <stack trace>
=> sub_preempt_count
=> irq_exit
=> do_IRQ
=> ret_from_intr
这有一些更多的变化。 当中断进入时（注意“h”），抢占被禁用，并且在退出时启用。 但我们也看到，在进入和离开抢占关闭部分时，中断已被禁用（“d”）。 我们不知道中断是否在此期间或之后不久被启用。
# tracer: preemptoff
#
# preemptoff latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 83 us, #241/241, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: wake_up_new_task
# => ended at: task_rq_unlock
#
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
bash-1994 1d..1 0us : _raw_spin_lock_irqsave <-wake_up_new_task
bash-1994 1d..1 0us : select_task_rq_fair <-select_task_rq
bash-1994 1d..1 1us : __rcu_read_lock <-select_task_rq_fair
bash-1994 1d..1 1us : source_load <-select_task_rq_fair
bash-1994 1d..1 1us : source_load <-select_task_rq_fair
[...]
bash-1994 1d..1 12us : irq_enter <-smp_apic_timer_interrupt
bash-1994 1d..1 12us : rcu_irq_enter <-irq_enter
bash-1994 1d..1 13us : add_preempt_count <-irq_enter
bash-1994 1d.h1 13us : exit_idle <-smp_apic_timer_interrupt
bash-1994 1d.h1 13us : hrtimer_interrupt <-smp_apic_timer_interrupt
bash-1994 1d.h1 13us : _raw_spin_lock <-hrtimer_interrupt
bash-1994 1d.h1 14us : add_preempt_count <-_raw_spin_lock
bash-1994 1d.h2 14us : ktime_get_update_offsets <-hrtimer_interrupt
[...]
bash-1994 1d.h1 35us : lapic_next_event <-clockevents_program_event
bash-1994 1d.h1 35us : irq_exit <-smp_apic_timer_interrupt
bash-1994 1d.h1 36us : sub_preempt_count <-irq_exit
bash-1994 1d..2 36us : do_softirq <-irq_exit
bash-1994 1d..2 36us : __do_softirq <-call_softirq
bash-1994 1d..2 36us : __local_bh_disable <-__do_softirq
bash-1994 1d.s2 37us : add_preempt_count <-_raw_spin_lock_irq
bash-1994 1d.s3 38us : _raw_spin_unlock <-run_timer_softirq
bash-1994 1d.s3 39us : sub_preempt_count <-_raw_spin_unlock
bash-1994 1d.s2 39us : call_timer_fn <-run_timer_softirq
[...]
bash-1994 1dNs2 81us : cpu_needs_another_gp <-rcu_process_callbacks
bash-1994 1dNs2 82us : __local_bh_enable <-__do_softirq
bash-1994 1dNs2 82us : sub_preempt_count <-__local_bh_enable
bash-1994 1dN.2 82us : idle_cpu <-irq_exit
bash-1994 1dN.2 83us : rcu_irq_exit <-irq_exit
bash-1994 1dN.2 83us : sub_preempt_count <-irq_exit
bash-1994 1.N.1 84us : _raw_spin_unlock_irqrestore <-task_rq_unlock
bash-1994 1.N.1 84us+: trace_preempt_on <-task_rq_unlock
bash-1994 1.N.1 104us : <stack trace>
=> sub_preempt_count
=> _raw_spin_unlock_irqrestore
=> task_rq_unlock
=> wake_up_new_task
=> do_fork
=> sys_clone
=> stub_clone
以上是设置了 function-trace 的 preemptoff 跟踪的示例。 在这里，我们看到中断不是在整个时间内都禁用的。 irq_enter 代码让我们知道我们进入了一个中断“h”。 在此之前，被跟踪的函数仍然表明它不在中断中，但我们可以从函数本身看到情况并非如此。
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 跟踪器将记录 call_function_with_irqs_off() 和 call_function_with_irqs_and_preemption_off() 的总长度。
preemptoff 跟踪器将记录 call_function_with_irqs_and_preemption_off() 和 call_function_with_preemption_off() 的总长度。
但是，两者都不会跟踪中断和/或抢占被禁用的时间。 此总时间是我们无法调度的时间。 要记录此时间，请使用 preemptirqsoff 跟踪器。
同样，使用此跟踪与 irqsoff 和 preemptoff 跟踪器非常相似。
# echo 0 > options/function-trace
# echo preemptirqsoff > current_tracer
# echo 1 > tracing_on
# echo 0 > tracing_max_latency
# ls -ltr
[...]
# echo 0 > tracing_on
# cat trace
# tracer: preemptirqsoff
#
# preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 100 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: ata_scsi_queuecmd
# => ended at: ata_scsi_queuecmd
#
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
ls-2230 3d... 0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd
ls-2230 3...1 100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
ls-2230 3...1 101us+: trace_preempt_on <-ata_scsi_queuecmd
ls-2230 3...1 111us : <stack trace>
=> sub_preempt_count
=> _raw_spin_unlock_irqrestore
=> ata_scsi_queuecmd
=> scsi_dispatch_cmd
=> scsi_request_fn
=> __blk_run_queue_uncond
=> __blk_run_queue
=> blk_queue_bio
=> submit_bio_noacct
=> submit_bio
=> submit_bh
=> ext3_bread
=> ext3_dir_bread
=> htree_dirblock_to_tree
=> ext3_htree_fill_tree
=> ext3_readdir
=> vfs_readdir
=> sys_getdents
=> system_call_fastpath
当在汇编代码中禁用中断时，trace_hardirqs_off_thunk 从 x86 上的汇编中调用。 如果没有函数跟踪，我们不知道中断是否在抢占点内被启用。 我们确实看到它以启用抢占开始。
这是设置了 function-trace 的跟踪
# tracer: preemptirqsoff
#
# preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 161 us, #339/339, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: schedule
# => ended at: mutex_unlock
#
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
kworker/-59 3...1 0us : __schedule <-schedule
kworker/-59 3d..1 0us : rcu_preempt_qs <-rcu_note_context_switch
kworker/-59 3d..1 1us : add_preempt_count <-_raw_spin_lock_irq
kworker/-59 3d..2 1us : deactivate_task <-__schedule
kworker/-59 3d..2 1us : dequeue_task <-deactivate_task
kworker/-59 3d..2 2us : update_rq_clock <-dequeue_task
kworker/-59 3d..2 2us : dequeue_task_fair <-dequeue_task
kworker/-59 3d..2 2us : update_curr <-dequeue_task_fair
kworker/-59 3d..2 2us : update_min_vruntime <-update_curr
kworker/-59 3d..2 3us : cpuacct_charge <-update_curr
kworker/-59 3d..2 3us : __rcu_read_lock <-cpuacct_charge
kworker/-59 3d..2 3us : __rcu_read_unlock <-cpuacct_charge
kworker/-59 3d..2 3us : update_cfs_rq_blocked_load <-dequeue_task_fair
kworker/-59 3d..2 4us : clear_buddies <-dequeue_task_fair
kworker/-59 3d..2 4us : account_entity_dequeue <-dequeue_task_fair
kworker/-59 3d..2 4us : update_min_vruntime <-dequeue_task_fair
kworker/-59 3d..2 4us : update_cfs_shares <-dequeue_task_fair
kworker/-59 3d..2 5us : hrtick_update <-dequeue_task_fair
kworker/-59 3d..2 5us : wq_worker_sleeping <-__schedule
kworker/-59 3d..2 5us : kthread_data <-wq_worker_sleeping
kworker/-59 3d..2 5us : put_prev_task_fair <-__schedule
kworker/-59 3d..2 6us : pick_next_task_fair <-pick_next_task
kworker/-59 3d..2 6us : clear_buddies <-pick_next_task_fair
kworker/-59 3d..2 6us : set_next_entity <-pick_next_task_fair
kworker/-59 3d..2 6us : update_stats_wait_end <-set_next_entity
ls-2269 3d..2 7us : finish_task_switch <-__schedule
ls-2269 3d..2 7us : _raw_spin_unlock_irq <-finish_task_switch
ls-2269 3d..2 8us : do_IRQ <-ret_from_intr
ls-2269 3d..2 8us : irq_enter <-do_IRQ
ls-2269 3d..2 8us : rcu_irq_enter <-irq_enter
ls-2269 3d..2 9us : add_preempt_count <-irq_enter
ls-2269 3d.h2 9us : exit_idle <-do_IRQ
[...]
ls-2269 3d.h3 20us : sub_preempt_count <-_raw_spin_unlock
ls-2269 3d.h2 20us : irq_exit <-do_IRQ
ls-2269 3d.h2 21us : sub_preempt_count <-irq_exit
ls-2269 3d..3 21us : do_softirq <-irq_exit
ls-2269 3d..3 21us : __do_softirq <-call_softirq
ls-2269 3d..3 21us+: __local_bh_disable <-__do_softirq
ls-2269 3d.s4 29us : sub_preempt_count <-_local_bh_enable_ip
ls-2269 3d.s5 29us : sub_preempt_count <-_local_bh_enable_ip
ls-2269 3d.s5 31us : do_IRQ <-ret_from_intr
ls-2269 3d.s5 31us : irq_enter <-do_IRQ
ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
[...]
ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
ls-2269 3d.s5 32us : add_preempt_count <-irq_enter
ls-2269 3d.H5 32us : exit_idle <-do_IRQ
ls-2269 3d.H5 32us : handle_irq <-do_IRQ
ls-2269 3d.H5 32us : irq_to_desc <-handle_irq
ls-2269 3d.H5 33us : handle_fasteoi_irq <-handle_irq
[...]
ls-2269 3d.s5 158us : _raw_spin_unlock_irqrestore <-rtl8139_poll
ls-2269 3d.s3 158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action
ls-2269 3d.s3 159us : __local_bh_enable <-__do_softirq
ls-2269 3d.s3 159us : sub_preempt_count <-__local_bh_enable
ls-2269 3d..3 159us : idle_cpu <-irq_exit
ls-2269 3d..3 159us : rcu_irq_exit <-irq_exit
ls-2269 3d..3 160us : sub_preempt_count <-irq_exit
ls-2269 3d... 161us : __mutex_unlock_slowpath <-mutex_unlock
ls-2269 3d... 162us+: trace_hardirqs_on <-mutex_unlock
ls-2269 3d... 186us : <stack trace>
=> __mutex_unlock_slowpath
=> mutex_unlock
=> process_output
=> n_tty_write
=> tty_write
=> vfs_write
=> sys_write
=> system_call_fastpath
这是一个有趣的跟踪。 它以 kworker 运行并调度 out 和 ls 接管开始。 但是，一旦 ls 释放了 rq 锁并启用了中断（但未启用抢占），就会触发一个中断。 中断完成后，它开始运行 softirq。 当中断在 softirq 内部运行时，注释为“H”。
wakeup¶
人们感兴趣的常见情况之一是跟踪一个被唤醒的任务实际唤醒所需的时间。 现在，对于非实时任务，这可以是任意的。 但无论如何，跟踪它可能很有趣。
没有函数跟踪
# echo 0 > options/function-trace
# echo wakeup > current_tracer
# echo 1 > tracing_on
# echo 0 > tracing_max_latency
# chrt -f 5 sleep 1
# echo 0 > tracing_on
# cat trace
# tracer: wakeup
#
# wakeup latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 15 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
<idle>-0 3dNs7 0us : 0:120:R + [003] 312:100:R kworker/3:1H
<idle>-0 3dNs7 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
<idle>-0 3d..3 15us : __schedule <-schedule
<idle>-0 3d..3 15us : 0:120:R ==> [003] 312:100:R kworker/3:1H
跟踪器只跟踪系统中优先级最高的任务，以避免跟踪正常情况。在这里，我们可以看到nice优先级为-20（不是很好）的kworker，从唤醒到运行仅花费了15微秒。
非实时任务不是那么有趣。更有趣的跟踪是只专注于实时任务。
wakeup_rt¶
在实时环境中，知道优先级最高的任务从唤醒到执行所花费的唤醒时间非常重要。 这也称为“调度延迟”。我强调这一点是关于RT任务的。了解非RT任务的调度延迟也很重要，但平均调度延迟更适合非RT任务。像LatencyTop这样的工具更适合进行此类测量。
实时环境关注的是最坏情况下的延迟。即发生某件事所花费的最长延迟，而不是平均延迟。我们可以有一个非常快速的调度程序，可能偶尔才会有很大的延迟，但这对于实时任务来说效果不好。 wakeup_rt跟踪器旨在记录RT任务的最坏情况唤醒。 不会记录非RT任务，因为跟踪器只记录一个最坏情况，并且跟踪不可预测的非RT任务会覆盖RT任务的最坏情况延迟（只需运行普通的wakeup跟踪器一段时间即可看到该效果）。
由于此跟踪器仅处理RT任务，因此我们将以与之前跟踪器略有不同的方式运行它。我们将在“chrt”下运行“sleep 1”，而不是执行“ls”，这会更改任务的优先级。
# echo 0 > options/function-trace
# echo wakeup_rt > current_tracer
# echo 1 > tracing_on
# echo 0 > tracing_max_latency
# chrt -f 5 sleep 1
# echo 0 > tracing_on
# cat trace
# tracer: wakeup
#
# tracer: wakeup_rt
#
# wakeup_rt latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 5 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
<idle>-0 3d.h4 0us : 0:120:R + [003] 2389: 94:R sleep
<idle>-0 3d.h4 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
<idle>-0 3d..3 5us : __schedule <-schedule
<idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
在空闲系统上运行它，我们看到执行任务切换仅花费了5微秒。请注意，由于调度中的跟踪点位于实际“切换”之前，因此当记录的任务即将调度时，我们停止跟踪。如果我们调度程序的末尾添加新的标记，这可能会改变。
请注意，记录的任务是PID为2389的“sleep”，其rt_prio为5。此优先级是用户空间优先级，而不是内部内核优先级。策略1表示SCHED_FIFO，2表示SCHED_RR。
请注意，跟踪数据显示了内部优先级（99 - rtprio）。
<idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
0:120:R表示idle以nice优先级0（120 - 120）运行，并且处于运行状态“R”。 sleep任务以2389: 94:R调度进入。也就是说，优先级是内核rtprio（99 - 5 = 94），并且它也处于运行状态。
使用chrt -r 5并设置function-trace执行相同的操作。
echo 1 > options/function-trace
# tracer: wakeup_rt
#
# wakeup_rt latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 29 us, #85/85, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: sleep-2448 (uid:0 nice:0 policy:1 rt_prio:5)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
<idle>-0 3d.h4 1us+: 0:120:R + [003] 2448: 94:R sleep
<idle>-0 3d.h4 2us : ttwu_do_activate.constprop.87 <-try_to_wake_up
<idle>-0 3d.h3 3us : check_preempt_curr <-ttwu_do_wakeup
<idle>-0 3d.h3 3us : resched_curr <-check_preempt_curr
<idle>-0 3dNh3 4us : task_woken_rt <-ttwu_do_wakeup
<idle>-0 3dNh3 4us : _raw_spin_unlock <-try_to_wake_up
<idle>-0 3dNh3 4us : sub_preempt_count <-_raw_spin_unlock
<idle>-0 3dNh2 5us : ttwu_stat <-try_to_wake_up
<idle>-0 3dNh2 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
<idle>-0 3dNh2 6us : sub_preempt_count <-_raw_spin_unlock_irqrestore
<idle>-0 3dNh1 6us : _raw_spin_lock <-__run_hrtimer
<idle>-0 3dNh1 6us : add_preempt_count <-_raw_spin_lock
<idle>-0 3dNh2 7us : _raw_spin_unlock <-hrtimer_interrupt
<idle>-0 3dNh2 7us : sub_preempt_count <-_raw_spin_unlock
<idle>-0 3dNh1 7us : tick_program_event <-hrtimer_interrupt
<idle>-0 3dNh1 7us : clockevents_program_event <-tick_program_event
<idle>-0 3dNh1 8us : ktime_get <-clockevents_program_event
<idle>-0 3dNh1 8us : lapic_next_event <-clockevents_program_event
<idle>-0 3dNh1 8us : irq_exit <-smp_apic_timer_interrupt
<idle>-0 3dNh1 9us : sub_preempt_count <-irq_exit
<idle>-0 3dN.2 9us : idle_cpu <-irq_exit
<idle>-0 3dN.2 9us : rcu_irq_exit <-irq_exit
<idle>-0 3dN.2 10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit
<idle>-0 3dN.2 10us : sub_preempt_count <-irq_exit
<idle>-0 3.N.1 11us : rcu_idle_exit <-cpu_idle
<idle>-0 3dN.1 11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit
<idle>-0 3.N.1 11us : tick_nohz_idle_exit <-cpu_idle
<idle>-0 3dN.1 12us : menu_hrtimer_cancel <-tick_nohz_idle_exit
<idle>-0 3dN.1 12us : ktime_get <-tick_nohz_idle_exit
<idle>-0 3dN.1 12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit
<idle>-0 3dN.1 13us : cpu_load_update_nohz <-tick_nohz_idle_exit
<idle>-0 3dN.1 13us : _raw_spin_lock <-cpu_load_update_nohz
<idle>-0 3dN.1 13us : add_preempt_count <-_raw_spin_lock
<idle>-0 3dN.2 13us : __cpu_load_update <-cpu_load_update_nohz
<idle>-0 3dN.2 14us : sched_avg_update <-__cpu_load_update
<idle>-0 3dN.2 14us : _raw_spin_unlock <-cpu_load_update_nohz
<idle>-0 3dN.2 14us : sub_preempt_count <-_raw_spin_unlock
<idle>-0 3dN.1 15us : calc_load_nohz_stop <-tick_nohz_idle_exit
<idle>-0 3dN.1 15us : touch_softlockup_watchdog <-tick_nohz_idle_exit
<idle>-0 3dN.1 15us : hrtimer_cancel <-tick_nohz_idle_exit
<idle>-0 3dN.1 15us : hrtimer_try_to_cancel <-hrtimer_cancel
<idle>-0 3dN.1 16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel
<idle>-0 3dN.1 16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
<idle>-0 3dN.1 16us : add_preempt_count <-_raw_spin_lock_irqsave
<idle>-0 3dN.2 17us : __remove_hrtimer <-remove_hrtimer.part.16
<idle>-0 3dN.2 17us : hrtimer_force_reprogram <-__remove_hrtimer
<idle>-0 3dN.2 17us : tick_program_event <-hrtimer_force_reprogram
<idle>-0 3dN.2 18us : clockevents_program_event <-tick_program_event
<idle>-0 3dN.2 18us : ktime_get <-clockevents_program_event
<idle>-0 3dN.2 18us : lapic_next_event <-clockevents_program_event
<idle>-0 3dN.2 19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
<idle>-0 3dN.2 19us : sub_preempt_count <-_raw_spin_unlock_irqrestore
<idle>-0 3dN.1 19us : hrtimer_forward <-tick_nohz_idle_exit
<idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
<idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
<idle>-0 3dN.1 20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
<idle>-0 3dN.1 20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns
<idle>-0 3dN.1 21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns
<idle>-0 3dN.1 21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
<idle>-0 3dN.1 21us : add_preempt_count <-_raw_spin_lock_irqsave
<idle>-0 3dN.2 22us : ktime_add_safe <-__hrtimer_start_range_ns
<idle>-0 3dN.2 22us : enqueue_hrtimer <-__hrtimer_start_range_ns
<idle>-0 3dN.2 22us : tick_program_event <-__hrtimer_start_range_ns
<idle>-0 3dN.2 23us : clockevents_program_event <-tick_program_event
<idle>-0 3dN.2 23us : ktime_get <-clockevents_program_event
<idle>-0 3dN.2 23us : lapic_next_event <-clockevents_program_event
<idle>-0 3dN.2 24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns
<idle>-0 3dN.2 24us : sub_preempt_count <-_raw_spin_unlock_irqrestore
<idle>-0 3dN.1 24us : account_idle_ticks <-tick_nohz_idle_exit
<idle>-0 3dN.1 24us : account_idle_time <-account_idle_ticks
<idle>-0 3.N.1 25us : sub_preempt_count <-cpu_idle
<idle>-0 3.N.. 25us : schedule <-cpu_idle
<idle>-0 3.N.. 25us : __schedule <-preempt_schedule
<idle>-0 3.N.. 26us : add_preempt_count <-__schedule
<idle>-0 3.N.1 26us : rcu_note_context_switch <-__schedule
<idle>-0 3.N.1 26us : rcu_sched_qs <-rcu_note_context_switch
<idle>-0 3dN.1 27us : rcu_preempt_qs <-rcu_note_context_switch
<idle>-0 3.N.1 27us : _raw_spin_lock_irq <-__schedule
<idle>-0 3dN.1 27us : add_preempt_count <-_raw_spin_lock_irq
<idle>-0 3dN.2 28us : put_prev_task_idle <-__schedule
<idle>-0 3dN.2 28us : pick_next_task_stop <-pick_next_task
<idle>-0 3dN.2 28us : pick_next_task_rt <-pick_next_task
<idle>-0 3dN.2 29us : dequeue_pushable_task <-pick_next_task_rt
<idle>-0 3d..3 29us : __schedule <-preempt_schedule
<idle>-0 3d..3 30us : 0:120:R ==> [003] 2448: 94:R sleep
即使启用了函数跟踪，这也不是很大的跟踪，所以我包含了整个跟踪。
当系统空闲时，中断被关闭。在调用task_woken_rt()之前，NEED_RESCHED标志已设置，这由“N”标志的首次出现表示。
延迟跟踪和事件¶
由于函数跟踪可能会导致更大的延迟，但是如果不了解延迟内部发生的情况，很难知道导致延迟的原因。有一种折衷方案，那就是启用事件。
# echo 0 > options/function-trace
# echo wakeup_rt > current_tracer
# echo 1 > events/enable
# echo 1 > tracing_on
# echo 0 > tracing_max_latency
# chrt -f 5 sleep 1
# echo 0 > tracing_on
# cat trace
# tracer: wakeup_rt
#
# wakeup_rt latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 6 us, #12/12, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
<idle>-0 2d.h4 0us : 0:120:R + [002] 5882: 94:R sleep
<idle>-0 2d.h4 0us : ttwu_do_activate.constprop.87 <-try_to_wake_up
<idle>-0 2d.h4 1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002
<idle>-0 2dNh2 1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8
<idle>-0 2.N.2 2us : power_end: cpu_id=2
<idle>-0 2.N.2 3us : cpu_idle: state=4294967295 cpu_id=2
<idle>-0 2dN.3 4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0
<idle>-0 2dN.3 4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer expires=34311211000000 softexpires=34311211000000
<idle>-0 2.N.2 5us : rcu_utilization: Start context switch
<idle>-0 2.N.2 5us : rcu_utilization: End context switch
<idle>-0 2d..3 6us : __schedule <-schedule
<idle>-0 2d..3 6us : 0:120:R ==> [002] 5882: 94:R sleep
硬件延迟检测器¶
硬件延迟检测器通过启用“hwlat”跟踪器来执行。
请注意，此跟踪器会影响系统的性能，因为它会定期使CPU保持繁忙且中断禁用状态。
# echo hwlat > current_tracer
# sleep 100
# cat trace
# tracer: hwlat
#
# entries-in-buffer/entries-written: 13/13 #P:8
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
<...>-1729 [001] d... 678.473449: #1 inner/outer(us): 11/12 ts:1581527483.343962693 count:6
<...>-1729 [004] d... 689.556542: #2 inner/outer(us): 16/9 ts:1581527494.889008092 count:1
<...>-1729 [005] d... 714.756290: #3 inner/outer(us): 16/16 ts:1581527519.678961629 count:5
<...>-1729 [001] d... 718.788247: #4 inner/outer(us): 9/17 ts:1581527523.889012713 count:1
<...>-1729 [002] d... 719.796341: #5 inner/outer(us): 13/9 ts:1581527524.912872606 count:1
<...>-1729 [006] d... 844.787091: #6 inner/outer(us): 9/12 ts:1581527649.889048502 count:2
<...>-1729 [003] d... 849.827033: #7 inner/outer(us): 18/9 ts:1581527654.889013793 count:1
<...>-1729 [007] d... 853.859002: #8 inner/outer(us): 9/12 ts:1581527658.889065736 count:1
<...>-1729 [001] d... 855.874978: #9 inner/outer(us): 9/11 ts:1581527660.861991877 count:1
<...>-1729 [001] d... 863.938932: #10 inner/outer(us): 9/11 ts:1581527668.970010500 count:1 nmi-total:7 nmi-count:1
<...>-1729 [007] d... 878.050780: #11 inner/outer(us): 9/12 ts:1581527683.385002600 count:1 nmi-total:5 nmi-count:1
<...>-1729 [007] d... 886.114702: #12 inner/outer(us): 9/12 ts:1581527691.385001600 count:1
上面的输出在标题中略有相同。所有事件都将禁用中断“d”。在FUNCTION标题下有
- #1
这是记录的事件数，这些事件大于tracing_threshold（请参见下文）。
inner/outer(us): 11/11
这显示了两个数字，分别是“内部延迟”和“外部延迟”。该测试在一个循环中运行，检查时间戳两次。在两个时间戳内检测到的延迟是“内部延迟”，而在循环中的前一个时间戳和下一个时间戳之后检测到的延迟是“外部延迟”。
ts:1581527483.343962693
窗口中记录的第一个延迟的绝对时间戳。
count:6
在窗口期间检测到延迟的次数。
nmi-total:7 nmi-count:1
在支持它的体系结构上，如果在测试期间出现NMI，则NMI中花费的时间将在“nmi-total”中报告（以微秒为单位）。
如果测试期间出现NMI，则具有NMI的所有体系结构都将显示“nmi-count”。
hwlat 文件
- tracing_threshold
这会自动设置为“10”以表示10微秒。 这是在记录跟踪之前需要检测到的延迟阈值。
请注意，当hwlat跟踪器完成时（将另一个跟踪器写入“current_tracer”），tracing_threshold的原始值将放回此文件中。
- hwlat_detector/width
测试运行时中断禁用的时间长度。
- hwlat_detector/window
测试运行的窗口时间长度。 也就是说，测试将在每个“窗口”微秒内运行“width”微秒
- tracing_cpumask
测试何时开始。 创建一个内核线程来运行测试。 此线程将在每个周期（一个“窗口”）在tracing_cpumask中列出的CPU之间交替。 要将测试限制为特定CPU，请在此文件中将掩码设置为仅测试应在其上运行的CPU。
function¶
此跟踪器是函数跟踪器。 可以从调试文件系统中启用函数跟踪器。 确保设置了ftrace_enabled； 否则，此跟踪器是空操作。 请参见下面的“ftrace_enabled”部分。
# sysctl kernel.ftrace_enabled=1
# echo function > current_tracer
# echo 1 > tracing_on
# usleep 1
# echo 0 > tracing_on
# cat trace
# tracer: function
#
# entries-in-buffer/entries-written: 24799/24799 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
bash-1994 [002] .... 3082.063030: mutex_unlock <-rb_simple_write
bash-1994 [002] .... 3082.063031: __mutex_unlock_slowpath <-mutex_unlock
bash-1994 [002] .... 3082.063031: __fsnotify_parent <-fsnotify_modify
bash-1994 [002] .... 3082.063032: fsnotify <-fsnotify_modify
bash-1994 [002] .... 3082.063032: __srcu_read_lock <-fsnotify
bash-1994 [002] .... 3082.063032: add_preempt_count <-__srcu_read_lock
bash-1994 [002] ...1 3082.063032: sub_preempt_count <-__srcu_read_lock
bash-1994 [002] .... 3082.063033: __srcu_read_unlock <-fsnotify
[...]
注意：函数跟踪器使用环形缓冲区来存储以上条目。 最新数据可能会覆盖最旧的数据。 有时使用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);
}
[...]
}
单线程跟踪¶
通过写入set_ftrace_pid，您可以跟踪单个线程。 例如
# cat set_ftrace_pid
no pid
# echo 3111 > set_ftrace_pid
# cat set_ftrace_pid
3111
# echo function > current_tracer
# cat trace | head
# tracer: function
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
# echo > set_ftrace_pid
# cat trace |head
# tracer: function
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
##### CPU 3 buffer started ####
yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
如果要执行时跟踪函数，可以使用如下所示的简单程序。
#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 0 > $tracefs/tracing_on
echo $$ > $tracefs/set_ftrace_pid
echo function > $tracefs/current_tracer
echo 1 > $tracefs/tracing_on
exec "$@"
函数图跟踪器¶
此跟踪器与函数跟踪器类似，不同之处在于它在其进入和退出时探测函数。 这是通过使用每个task_struct中动态分配的返回地址堆栈来完成的。 在函数条目上，跟踪器将跟踪的每个函数的返回地址覆盖设置为自定义探测。 因此，原始返回地址存储在task_struct中返回地址的堆栈上。
在函数的两端进行探测会导致特殊功能，例如
测量函数的执行时间
具有可靠的调用堆栈以绘制函数调用图
此跟踪器在以下几种情况下很有用
您想找到奇怪的内核行为的原因，并且需要详细了解任何区域（或特定区域）中发生的情况。
您遇到奇怪的延迟，但很难找到其根源。
您想快速找到特定函数采用的路径
您只是想窥视正在运行的内核，并想看看那里发生了什么。
# 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_cpumask文件），或者在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
depends on: 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 | }
标志
+ means that the function exceeded 10 usecs.
! means that the function exceeded 100 usecs.
# means that the function exceeded 1000 usecs.
* means that the function exceeded 10 msecs.
@ means that the function exceeded 100 msecs.
$ means that the function exceeded 1 sec.
task/pid字段显示执行该函数的线程cmdline和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 | 0.586 us | check_for_new_grace_period(); 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
不带nofuncgraph-tail的示例（默认）
0) | putname() { 0) | kmem_cache_free() { 0) 0.518 us | __phys_addr(); 0) 1.757 us | } 0) 2.861 us | }带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() */
每个跟踪函数的返回值都可以显示在等号“=”之后。 遇到系统调用失败时，它可以非常有助于快速找到首先返回错误代码的函数。
hide: echo nofuncgraph-retval > trace_options
show: echo funcgraph-retval > trace_options
带funcgraph-retval的示例
1) | cgroup_migrate() { 1) 0.651 us | cgroup_migrate_add_task(); /* = 0xffff93fcfd346c00 */ 1) | cgroup_migrate_execute() { 1) | cpu_cgroup_can_attach() { 1) | cgroup_taskset_first() { 1) 0.732 us | cgroup_taskset_next(); /* = 0xffff93fc8fb20000 */ 1) 1.232 us | } /* cgroup_taskset_first = 0xffff93fc8fb20000 */ 1) 0.380 us | sched_rt_can_attach(); /* = 0x0 */ 1) 2.335 us | } /* cpu_cgroup_can_attach = -22 */ 1) 4.369 us | } /* cgroup_migrate_execute = -22 */ 1) 7.143 us | } /* cgroup_migrate = -22 */
上面的示例显示函数cpu_cgroup_can_attach首先返回错误代码-22，然后我们可以读取此函数的代码以获取根本原因。
当未设置选项funcgraph-retval-hex时，可以以一种智能的方式显示返回值。 具体来说，如果是错误代码，则将以带符号的十进制格式打印，否则将以十六进制格式打印。
smart: echo nofuncgraph-retval-hex > trace_options
hexadecimal: echo funcgraph-retval-hex > trace_options
带funcgraph-retval-hex的示例
1) | cgroup_migrate() { 1) 0.651 us | cgroup_migrate_add_task(); /* = 0xffff93fcfd346c00 */ 1) | cgroup_migrate_execute() { 1) | cpu_cgroup_can_attach() { 1) | cgroup_taskset_first() { 1) 0.732 us | cgroup_taskset_next(); /* = 0xffff93fc8fb20000 */ 1) 1.232 us | } /* cgroup_taskset_first = 0xffff93fc8fb20000 */ 1) 0.380 us | sched_rt_can_attach(); /* = 0x0 */ 1) 2.335 us | } /* cpu_cgroup_can_attach = 0xffffffea */ 1) 4.369 us | } /* cgroup_migrate_execute = 0xffffffea */ 1) 7.143 us | } /* cgroup_migrate = 0xffffffea */
目前，使用funcgraph-retval选项时存在一些限制，这些限制将在将来消除
即使函数返回类型为void，仍将打印返回值，您可以忽略它。
即使返回值存储在多个寄存器中，也只会记录和打印第一个寄存器中包含的值。 为了说明，在x86体系结构中，eax和edx用于存储64位返回值，较低的32位保存在eax中，较高的32位保存在edx中。 但是，只会记录和打印保存在eax中的值。
在某些过程调用标准中，例如arm64的AAPCS64，当类型小于GPR时，由使用者负责执行缩小，并且高位可能包含UNKNOWN值。 因此，建议检查代码中是否存在此类情况。 例如，当在64位GPR中使用u8时，位[63：8]可能包含任意值，尤其是当较大的类型被截断时，无论是显式还是隐式。 以下是一些具体示例来说明这一点
情况一:
函数narrow_to_u8定义如下
u8 narrow_to_u8(u64 val) { // implicitly truncated return val; }它可以编译为
narrow_to_u8: < ... ftrace instrumentation ... > RET如果您将0x123456789abcdef传递给此函数并想要缩小它，则可能会将其记录为0x123456789abcdef而不是0xef。
情况二:
函数error_if_not_4g_aligned定义如下
int error_if_not_4g_aligned(u64 val) { if (val & GENMASK(31, 0)) return -EINVAL; return 0; }它可以编译为
error_if_not_4g_aligned: CBNZ w0, .Lnot_aligned RET // bits [31:0] are zero, bits // [63:32] are UNKNOWN .Lnot_aligned: MOV x0, #-EINVAL RET当传递0x2_0000_0000给它时，返回值可能被记录为0x2_0000_0000而不是0。
您可以使用trace_printk()在特定函数上添加一些注释。 例如，如果您想在__might_sleep()函数中添加注释，则只需包含<linux/ftrace.h>并在__might_sleep()中调用trace_printk()
trace_printk("I'm a comment!\n")
将产生
1) | __might_sleep() {
1) | /* I'm a comment! */
1) 1.449 us | }
您可能会在以下“动态ftrace”部分中找到此跟踪器的其他有用功能，例如仅跟踪特定函数或任务。
动态ftrace¶
如果设置了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
# cat available_filter_functions
put_prev_task_idle
kmem_cache_create
pick_next_task_rt
cpus_read_lock
pick_next_task_fair
mutex_lock
[...]
如果我只对sys_nanosleep和hrtimer_interrupt感兴趣
# echo sys_nanosleep hrtimer_interrupt > set_ftrace_filter
# echo function > current_tracer
# echo 1 > tracing_on
# usleep 1
# echo 0 > tracing_on
# cat trace
# tracer: function
#
# entries-in-buffer/entries-written: 5/5 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
usleep-2665 [001] .... 4186.475355: sys_nanosleep <-system_call_fastpath
<idle>-0 [001] d.h1 4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt
usleep-2665 [001] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
<idle>-0 [003] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
<idle>-0 [002] d.h1 4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt
要查看正在跟踪哪些函数，您可以cat文件
# cat set_ftrace_filter
hrtimer_interrupt
sys_nanosleep
也许这还不够。 过滤器还允许glob(7)匹配。
<match>*将匹配以<match>开头的函数
*<match>将匹配以<match>结尾的函数
*<match>*将匹配具有<match>的函数
<match1>*<match2>将匹配以<match1>开头并以<match2>结尾的函数
注意
最好使用引号将通配符括起来，否则shell可能会将参数扩展为本地目录中的文件名。
# echo 'hrtimer_*' > set_ftrace_filter
产生
# tracer: function
#
# entries-in-buffer/entries-written: 897/897 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
<idle>-0 [003] dN.1 4228.547803: hrtimer_cancel <-tick_nohz_idle_exit
<idle>-0 [003] dN.1 4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel
<idle>-0 [003] dN.2 4228.547805: hrtimer_force_reprogram <-__remove_hrtimer
<idle>-0 [003] dN.1 4228.547805: hrtimer_forward <-tick_nohz_idle_exit
<idle>-0 [003] dN.1 4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
<idle>-0 [003] d..1 4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt
<idle>-0 [003] d..1 4228.547859: hrtimer_start <-__tick_nohz_idle_enter
<idle>-0 [003] d..2 4228.547860: hrtimer_force_reprogram <-__rem
请注意，我们丢失了sys_nanosleep。
# cat set_ftrace_filter
hrtimer_run_queues
hrtimer_run_pending
hrtimer_setup
hrtimer_cancel
hrtimer_try_to_cancel
hrtimer_forward
hrtimer_start
hrtimer_reprogram
hrtimer_force_reprogram
hrtimer_get_next_event
hrtimer_interrupt
hrtimer_nanosleep
hrtimer_wakeup
hrtimer_get_remaining
hrtimer_get_res
hrtimer_init_sleeper
这是因为“>”和“>>”的作用与在bash中的作用完全相同。 要重写过滤器，请使用“>”。 要附加到过滤器，请使用“>>”。
要清除过滤器，以便再次记录所有函数
# echo > set_ftrace_filter
# cat set_ftrace_filter
#
同样，现在我们要附加。
# echo sys_nanosleep > set_ftrace_filter
# cat set_ftrace_filter
sys_nanosleep
# echo 'hrtimer_*' >> set_ftrace_filter
# cat set_ftrace_filter
hrtimer_run_queues
hrtimer_run_pending
hrtimer_setup
hrtimer_cancel
hrtimer_try_to_cancel
hrtimer_forward
hrtimer_start
hrtimer_reprogram
hrtimer_force_reprogram
hrtimer_get_next_event
hrtimer_interrupt
sys_nanosleep
hrtimer_nanosleep
hrtimer_wakeup
hrtimer_get_remaining
hrtimer_get_res
hrtimer_init_sleeper
set_ftrace_notrace可防止这些函数被跟踪。
# echo '*preempt*' '*lock*' > set_ftrace_notrace
产生
# tracer: function
#
# entries-in-buffer/entries-written: 39608/39608 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
bash-1994 [000] .... 4342.324896: file_ra_state_init <-do_dentry_open
bash-1994 [000] .... 4342.324897: open_check_o_direct <-do_last
bash-1994 [000] .... 4342.324897: ima_file_check <-do_last
bash-1994 [000] .... 4342.324898: process_measurement <-ima_file_check
bash-1994 [000] .... 4342.324898: ima_get_action <-process_measurement
bash-1994 [000] .... 4342.324898: ima_match_policy <-ima_get_action
bash-1994 [000] .... 4342.324899: do_truncate <-do_last
bash-1994 [000] .... 4342.324899: setattr_should_drop_suidgid <-do_truncate
bash-1994 [000] .... 4342.324899: notify_change <-do_truncate
bash-1994 [000] .... 4342.324900: current_fs_time <-notify_change
bash-1994 [000] .... 4342.324900: current_kernel_time <-current_fs_time
bash-1994 [000] .... 4342.324900: timespec_trunc <-current_fs_time
我们可以看到不再有锁或抢占跟踪。
通过索引选择函数过滤器¶
由于字符串的处理成本很高（在与传入的字符串进行比较之前，需要查找函数的地址），因此也可以使用索引来启用函数。这在一次设置数千个特定函数的情况下非常有用。通过传入数字列表，不会发生字符串处理。而是选择内部数组中特定位置的函数（该函数对应于“available_filter_functions”文件中的函数）。
# echo 1 > set_ftrace_filter
将选择“available_filter_functions”中列出的第一个函数
# head -1 available_filter_functions
trace_initcall_finish_cb
# cat set_ftrace_filter
trace_initcall_finish_cb
# head -50 available_filter_functions | tail -1
x86_pmu_commit_txn
# echo 1 50 > set_ftrace_filter
# cat set_ftrace_filter
trace_initcall_finish_cb
x86_pmu_commit_txn
带函数图跟踪器的动态ftrace¶
虽然上面解释的内容涉及函数跟踪器和函数图跟踪器，但某些特殊功能仅在函数图跟踪器中可用。
如果您只想跟踪一个函数及其所有子函数，只需将其名称回显到set_graph_function中
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 | }
您也可以一次展开多个函数
echo sys_open > set_graph_function
echo sys_close >> set_graph_function
现在，如果要返回以跟踪所有函数，可以通过以下方式清除此特殊过滤器
echo > set_graph_function
ftrace_enabled¶
请注意，proc sysctl ftrace_enable是函数跟踪器的一个大的开启/关闭开关。 默认情况下，它是启用的（当在内核中启用函数跟踪时）。 如果禁用它，则所有函数跟踪都将被禁用。 这不仅包括ftrace的函数跟踪器，还包括任何其他用途（perf，kprobes，堆栈跟踪，分析等）。 如果注册了具有FTRACE_OPS_FL_PERMANENT设置的回调，则无法将其禁用。
请谨慎禁用此功能。
可以使用
sysctl kernel.ftrace_enabled=0
sysctl kernel.ftrace_enabled=1
or
echo 0 > /proc/sys/kernel/ftrace_enabled
echo 1 > /proc/sys/kernel/ftrace_enabled
过滤器命令¶
set_ftrace_filter接口支持一些命令。 跟踪命令的格式如下
<function>:<command>:<parameter>
支持以下命令
mod: 此命令启用每个模块的函数过滤。 参数定义模块。 例如，如果仅需要ext3模块中的write*函数，请运行
echo ‘write*:mod:ext3’ > set_ftrace_filter
此命令与过滤器交互的方式与基于函数名称进行过滤的方式相同。 因此，通过附加（>>）到过滤器文件来添加另一个模块中的更多函数。 通过在前面加上“！”来删除特定的模块函数
echo '!writeback*:mod:ext3' >> set_ftrace_filter
Mod命令支持模块globbing。 禁用除特定模块之外的所有功能的跟踪
echo '!*:mod:!ext3' >> set_ftrace_filter
禁用所有模块的跟踪，但仍跟踪内核
echo '!*:mod:*' >> set_ftrace_filter
仅为内核启用过滤器
echo '*write*:mod:!*' >> set_ftrace_filter
为模块globbing启用过滤器
echo '*write*:mod:*snd*' >> set_ftrace_filter
traceon/traceoff: 这些命令在指定的函数被命中时打开和关闭跟踪。 参数确定跟踪系统打开和关闭的次数。 如果未指定，则没有限制。 例如，要在首次命中调度错误的前5次禁用跟踪，请运行
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_filterdump: 命中函数时，它会将ftrace环形缓冲区的内容转储到控制台。 如果您需要调试某些内容，并且希望在命中某个函数时转储跟踪，这将非常有用。 也许它是在发生三重故障之前调用的函数，并且不允许您获得常规转储。
cpudump: 命中该函数时，它会将当前CPU的ftrace环形缓冲区的内容转储到控制台。 与“dump”命令不同，它仅打印出执行触发转储的函数的CPU的环形缓冲区的内容。
stacktrace: 命中该函数时，将记录堆栈跟踪。
trace_pipe¶
trace_pipe输出与trace文件相同的内容，但是对跟踪的影响不同。 从trace_pipe的每次读取都会被消耗掉。 这意味着后续的读取将不同。 跟踪是实时的。
# echo function > current_tracer
# cat trace_pipe > /tmp/trace.out &
[1] 4153
# echo 1 > tracing_on
# usleep 1
# echo 0 > tracing_on
# cat trace
# tracer: function
#
# entries-in-buffer/entries-written: 0/0 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
#
# cat /tmp/trace.out
bash-1994 [000] .... 5281.568961: mutex_unlock <-rb_simple_write
bash-1994 [000] .... 5281.568963: __mutex_unlock_slowpath <-mutex_unlock
bash-1994 [000] .... 5281.568963: __fsnotify_parent <-fsnotify_modify
bash-1994 [000] .... 5281.568964: fsnotify <-fsnotify_modify
bash-1994 [000] .... 5281.568964: __srcu_read_lock <-fsnotify
bash-1994 [000] .... 5281.568964: add_preempt_count <-__srcu_read_lock
bash-1994 [000] ...1 5281.568965: sub_preempt_count <-__srcu_read_lock
bash-1994 [000] .... 5281.568965: __srcu_read_unlock <-fsnotify
bash-1994 [000] .... 5281.568967: sys_dup2 <-system_call_fastpath
请注意，读取trace_pipe文件将阻塞，直到添加更多输入。 这与trace文件相反。 如果任何进程打开了trace文件进行读取，它实际上将禁用跟踪并阻止添加新条目。 trace_pipe文件没有此限制。
跟踪条目¶
数据过多或不足在诊断内核中的问题时可能会很麻烦。 文件buffer_size_kb用于修改内部跟踪缓冲区的大小。 列出的数字是每个CPU可以记录的条目数。 要知道完整大小，请将可能的CPU数量乘以条目数量。
# cat buffer_size_kb
1408 (units kilobytes)
或者只是读取buffer_total_size_kb
# cat buffer_total_size_kb
5632
要修改缓冲区，只需回显一个数字（以1024字节为单位）。
# echo 10000 > buffer_size_kb
# cat buffer_size_kb
10000 (units kilobytes)
它将尝试分配尽可能多的空间。 如果分配过多，可能会导致触发内存不足。
# echo 1000000000000 > buffer_size_kb
-bash: echo: write error: Cannot allocate memory
# cat buffer_size_kb
85
也可以单独更改每个cpu缓冲区
# echo 10000 > per_cpu/cpu0/buffer_size_kb
# echo 100 > per_cpu/cpu1/buffer_size_kb
当每个cpu缓冲区不相同时，顶层的buffer_size_kb将仅显示X
# cat buffer_size_kb
X
这是buffer_total_size_kb有用的地方
# cat buffer_total_size_kb
12916
写入顶层buffer_size_kb将再次将所有缓冲区重置为相同。
快照¶
CONFIG_TRACER_SNAPSHOT使所有非延迟跟踪器都可以使用通用的快照功能。 （记录最大延迟的延迟跟踪器，例如“irqsoff”或“wakeup”，不能使用此功能，因为这些跟踪器已经在内部使用快照机制。）
快照在特定时间点保留当前跟踪缓冲区，而无需停止跟踪。 Ftrace将当前缓冲区与备用缓冲区交换，并且跟踪在新的当前（=先前的备用）缓冲区中继续。
“tracing”中的以下tracefs文件与此功能有关
snapshot
这用于拍摄快照并读取快照的输出。 将1回显到此文件中以分配备用缓冲区并拍摄快照（交换），然后从该文件中以与“trace”相同的格式读取快照（如上面的“文件系统”部分所述）。 读取快照和跟踪都可以并行执行。 分配备用缓冲区后，回显0会释放它，而回显其他（正）值会清除快照内容。 下表中显示了更多详细信息。
状态\输入
0
1
其他
未分配
（不执行任何操作）
分配+交换
（不执行任何操作）
已分配
释放
交换
清除
这是使用快照功能的示例。
# echo 1 > events/sched/enable
# echo 1 > snapshot
# 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
# 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
[...]
如果您尝试在当前跟踪器是延迟跟踪器之一时使用此快照功能，您将获得以下结果。
# echo wakeup > current_tracer
# echo 1 > snapshot
bash: echo: write error: Device or resource busy
# cat snapshot
cat: snapshot: Device or resource busy
实例¶
在tracefs跟踪目录中，有一个名为“instances”的目录。 可以使用mkdir在该目录内部创建新目录，并使用rmdir删除目录。 在此目录中使用mkdir创建的目录在创建后已经包含文件和其他目录。
# mkdir instances/foo
# 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
如您所见，新目录看起来与跟踪目录本身相似。 实际上，它非常相似，不同之处在于缓冲区和事件与主目录或创建的任何其他实例无关。
新目录中的文件的工作方式与跟踪目录中具有相同名称的文件的工作方式相同，只是使用的缓冲区是单独的新缓冲区。 这些文件会影响该缓冲区，但不会影响主缓冲区，但trace_options除外。 目前，trace_options会以相同的方式影响所有实例和顶级缓冲区，但这在将来的版本中可能会发生变化。 也就是说，选项可能会变得特定于它们所在的实例。
请注意，函数跟踪器文件都不在那里，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
# 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
[...]
# 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
[...]
# 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
[...]
# 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实例显示唤醒和任务切换。
要删除实例，只需删除它们的目录
# rmdir instances/foo
# rmdir instances/bar
# rmdir instances/zoot
请注意，如果进程在其中一个实例目录中打开了跟踪文件，则rmdir将失败并显示EBUSY。
堆栈跟踪¶
由于内核具有固定大小的堆栈，因此重要的是不要在函数中浪费它。 内核开发人员必须了解他们在堆栈上分配的内容。 如果他们添加太多内容，则系统可能会面临堆栈溢出的危险，并且会发生损坏，通常会导致系统崩溃。
有一些工具可以检查此问题，通常使用中断定期检查使用情况。 但是，如果您可以在每次函数调用时执行检查，那将非常有用。 由于ftrace提供了函数跟踪器，因此可以方便地在每次函数调用时检查堆栈大小。 这可以通过堆栈跟踪器启用。
CONFIG_STACK_TRACER启用ftrace堆栈跟踪功能。 要启用它，请将“1”写入/proc/sys/kernel/stack_tracer_enabled。
# echo 1 > /proc/sys/kernel/stack_tracer_enabled
您也可以从内核命令行启用它，以在启动期间跟踪内核的堆栈大小，方法是将“stacktrace”添加到内核命令行参数中。
运行几分钟后，输出如下所示
# cat stack_max_size
2928
# 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时，叶级函数不会被堆栈跟踪器测试。
当前，仅x86上的gcc 4.6.0及更高版本使用-mfentry。
更多¶
更多详细信息可以在源代码中的kernel/trace/*.c文件中找到。