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 文件系统启用，以查看内核某些部分中发生的情况。
有关更多信息，请参阅事件跟踪。
实现细节¶
有关架构移植人员等的详细信息，请参阅函数跟踪器设计。
文件系统¶
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
这用于设置或显示当前配置的跟踪器。更改当前跟踪器会清除环形缓冲区内容以及“快照”缓冲区。
available_tracers
这保存了已编译到内核中的不同类型的跟踪器。此处列出的跟踪器可以通过将其名称回显到 current_tracer 中进行配置。
tracing_on
这设置或显示是否启用了写入跟踪环形缓冲区。将 0 回显到此文件中以禁用跟踪器，或将 1 回显到此文件中以启用它。注意，这仅禁用写入环形缓冲区，跟踪开销可能仍在发生。
内核函数 tracing_off() 可在内核中使用，以禁用写入环形缓冲区，这将把此文件设置为“0”。用户空间可以通过将“1”回显到该文件中来重新启用跟踪。
注意，函数和事件触发器“traceoff”也会将此文件设置为零并停止跟踪。用户空间也可以使用此文件重新启用跟踪。
trace
此文件以人类可读的格式保存跟踪的输出（如下所述）。使用 O_TRUNC 标志打开此文件进行写入会清除环形缓冲区内容。注意，此文件不是使用者。如果跟踪已关闭（没有跟踪器运行，或 tracing_on 为零），则每次读取时都会产生相同的输出。当跟踪打开时，它可能会产生不一致的结果，因为它会尝试读取整个缓冲区而不消耗它。
trace_pipe
trace_pipe
trace_options
输出与“trace”文件相同，但此文件旨在通过实时跟踪进行流式传输。从此文件读取将阻塞，直到检索到新数据。与“trace”文件不同，此文件是使用者。这意味着从此文件读取会导致顺序读取显示更多当前数据。从该文件读取数据后，该数据将被消耗，并且不会通过顺序读取再次读取。“trace”文件是静态的，如果跟踪器没有添加更多数据，则每次读取时都会显示相同的信息。
trace_options
此文件允许用户控制在上述输出文件之一中显示的数据量。还存在修改跟踪器或事件工作方式的选项（堆栈跟踪、时间戳等）。
options
这是一个目录，其中包含每个可用跟踪选项的文件（也在 trace_options 中）。也可以通过将“1”或“0”分别写入具有选项名称的相应文件来设置或清除选项。
tracing_max_latency
一些跟踪器会记录最大延迟。例如，禁用中断的最大时间。最大时间保存在此文件中。最大跟踪也将被存储，并通过“trace”显示。只有当延迟大于此文件中的值（以微秒为单位）时，才会记录新的最大跟踪。
通过将时间回显到此文件中，除非延迟大于此文件中的时间，否则不会记录任何延迟。
tracing_thresh
当延迟大于此文件中的数字时，一些延迟跟踪器将记录跟踪。仅当文件包含大于 0 的数字时才活动。（以微秒为单位）
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_percent
这是环形缓冲区需要填充多少才能唤醒等待器的水位线。也就是说，如果应用程序在 per_cpu trace_pipe_raw 文件之一上调用阻塞读取 syscall，它将阻塞，直到环形缓冲区中存在由 buffer_percent 指定的给定数量的数据，然后它才会唤醒读取器。这也控制了 splice 系统调用在此文件上的阻塞方式
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
当配置动态 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 事件也跟踪应跟踪的线程，则 sched_switch 和 sched_wakeup 将跟踪未在此文件中列出的线程，即使线程的 PID 在文件中也是如此。
要在 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 操作函数位于函数入口点之上。在这种情况下，将显示“O”。
如果一个函数过去附加了“ip modify”或“direct”调用，则会显示“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
此命令显示 “快照” 缓冲区，并允许用户获取当前正在运行的跟踪的快照。有关更多详细信息，请参阅下面的“快照”部分。
stack_max_size
当堆栈跟踪器激活时，此命令将显示它遇到的最大堆栈大小。请参阅下面的“堆栈跟踪”部分。
stack_trace
当堆栈跟踪器激活时，此命令将显示遇到的最大堆栈的堆栈回溯。请参阅下面的“堆栈跟踪”部分。
stack_trace_filter
这类似于 “set_ftrace_filter”，但它限制了堆栈跟踪器将检查哪些函数。
trace_clock
每当事件被记录到环形缓冲区中时，都会添加一个 “时间戳”。此时间戳来自指定的时钟。默认情况下，ftrace 使用 “本地” 时钟。此时钟非常快且严格按每个 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); }start
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 缓冲区是 per_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”，延迟格式（下面解释），时间戳格式为 <秒>.<微秒>，被跟踪的函数名称 “sys_close” 以及调用此函数的父函数 “system_call_fastpath”。时间戳是函数被进入的时间。
延迟跟踪格式¶
当启用延迟格式选项或设置了其中一个延迟跟踪器时，跟踪文件会提供更多信息以了解延迟发生的原因。这是一个典型的跟踪示例
# 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）。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 发生在硬中断中
‘z’ - 表示 NMI 正在运行
‘H’ - 表示硬中断发生在软中断中。
‘h’ - 表示硬中断正在运行
‘s’ - 表示软中断正在运行
‘.’ - 表示正常上下文。
preempt-depth：preempt_disabled 的级别
以上内容主要对内核开发人员有意义。
- time
当启用延迟格式选项时，跟踪文件输出包含相对于跟踪开始的时间戳。这与禁用延迟格式时的输出不同，后者包含绝对时间戳。
- 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 标志。默认情况下，顶层跟踪设置了此标志，如果另一个实例设置了此标志然后清除它，它将再次设置此标志。此标志不能被顶层实例清除，因为它是默认实例。顶层实例清除此标志的唯一方法是在另一个实例中设置此标志。
- 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()将仅显示格式，而不显示其参数（如果使用 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 跟踪点启用一个钩子，以填充映射到 pid 的线程组 ID (TGID) 的缓存。请参阅“saved_tgids”。
- overwrite
这控制着跟踪缓冲区已满时会发生什么。如果为 “1” （默认），则将丢弃并覆盖最旧的事件。如果为 “0”，则将丢弃最新的事件。（有关溢出和丢弃，请参阅 per_cpu/cpu0/stats）
- disable_on_free
当 free_buffer 关闭时，跟踪将停止（tracing_on 设置为 0）。
- irq-info
显示中断、抢占计数、需要重新调度数据。禁用后，跟踪看起来像
# 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 将从文件中删除。
这也会影响 set_event_notrace_pid 中列出的 PID。
- function-trace
如果启用此选项（默认情况下启用），延迟跟踪器将启用函数跟踪。禁用后，延迟跟踪器不会跟踪函数。这可以在执行延迟测试时降低跟踪器的开销。
- function-fork
设置后，当 set_ftrace_pid 中列出的 PID 的任务 fork 时，它们的子级的 PID 将被添加到 set_ftrace_pid 中。此外，当 set_ftrace_pid 中的 PID 的任务退出时，它们的 PID 将从文件中删除。
这也会影响 set_ftrace_notrace_pid 中的 PID。
- display-graph
设置后，延迟跟踪器（irqsoff、wakeup 等）将使用函数图跟踪而不是函数跟踪。
- stacktrace
设置后，会在记录任何跟踪事件后记录堆栈跟踪。
- branch
使用跟踪器启用分支跟踪。这将启用分支跟踪器以及当前设置的跟踪器。使用“nop”跟踪器启用此功能与仅启用“branch”跟踪器相同。
提示
某些跟踪器有自己的选项。它们仅在跟踪器处于活动状态时才会出现在此文件中。它们始终出现在选项目录中。
以下是每个跟踪器的选项
函数跟踪器的选项
- func_stack_trace
设置后，将在记录的每个函数之后记录堆栈跟踪。注意！在启用此功能之前，请使用“set_ftrace_filter”限制要记录的函数，否则系统性能将严重下降。请记住在清除函数过滤器之前禁用此选项。
function_graph 跟踪器的选项
由于 function_graph 跟踪器的输出略有不同，因此它有自己的选项来控制显示的内容。
- funcgraph-overrun
设置后，将在每次跟踪函数后显示图堆栈的“溢出”。溢出是指调用堆栈的深度大于为每个任务保留的深度。每个任务都有一个固定大小的函数数组，用于在调用图中跟踪。如果调用的深度超过该值，则不会跟踪该函数。溢出是由于超出此数组而错过的函数数量。
- funcgraph-cpu
设置后，将显示发生跟踪的 CPU 的 CPU 编号。
- funcgraph-overhead
设置后，如果函数运行时间超过一定量，则会显示延迟标记。请参见上面的“延迟”标题下的说明。
- funcgraph-proc
与其他跟踪器不同，默认情况下不显示进程的命令行，而仅在上下文切换期间跟踪任务进出时才显示。启用此选项后，将在每行显示每个进程的命令。
- funcgraph-duration
在每个函数结束时（返回），将以微秒为单位显示函数运行的时间长度。
- funcgraph-abstime
设置后，将在每行显示时间戳。
- funcgraph-irqs
禁用后，将不会跟踪中断内发生的函数。
- funcgraph-tail
设置后，返回事件将包括它所代表的函数。默认情况下，此选项处于关闭状态，对于函数的返回，仅显示一个右花括号“}”。
- funcgraph-retval
设置后，每个跟踪函数的返回值将在等号“=”后打印。默认情况下，此选项处于关闭状态。
- funcgraph-retval-hex
设置后，返回值将始终以十六进制格式打印。如果未设置该选项且返回值为错误代码，则将以带符号的十进制格式打印；否则，它也将以十六进制格式打印。默认情况下，此选项处于关闭状态。
- sleep-time
在运行 function graph 跟踪器时，包括任务在其函数中调度的出队时间。启用后，它将把任务调出的时间计为函数调用的一部分。
- graph-time
当使用 function graph 跟踪器运行函数分析器时，包括调用嵌套函数的时间。如果未设置此选项，则报告的函数时间仅包括函数本身执行的时间，而不包括其调用的函数的时间。
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
当在汇编代码中禁用中断时，会从 x86 上的汇编调用 trace_hardirqs_off_thunk。如果没有函数跟踪，我们就不知道中断是否在抢占点内启用。我们确实看到它是在启用抢占的情况下开始的。
这是一个设置了 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 运行和调出开始，然后由 ls 接管。但是，一旦 ls 释放 rq 锁并启用中断（但未启用抢占），中断就会触发。当中断完成时，它开始运行 softirq。但是，当 softirq 运行时，另一个中断触发了。当中断在 softirq 内运行时，注释是“H”。
唤醒¶
人们感兴趣的跟踪的一个常见案例是唤醒的任务实际唤醒所需的时间。现在对于非实时任务，这可以是任意的。但是跟踪它仍然很有趣。
没有函数跟踪
# 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
跟踪器仅跟踪系统中优先级最高的任务，以避免跟踪正常情况。在这里，我们看到优先级为 -20（不是很友好）的 kworker 从唤醒到运行仅用了 15 微秒。
非实时任务不是那么有趣。更令人感兴趣的跟踪是仅关注实时任务。
wakeup_rt¶
在实时环境中，知道唤醒的最高优先级任务从唤醒到执行所需的时间非常重要。这也被称为“调度延迟”。我强调这一点是关于实时任务。了解非实时任务的调度延迟也很重要，但是平均调度延迟更适合非实时任务。像 LatencyTop 这样的工具更适合这种测量。
实时环境对最坏情况的延迟感兴趣。那是发生某事所需的最长延迟，而不是平均值。我们可能有一个非常快的调度程序，它可能只是偶尔有较大的延迟，但这对于实时任务来说效果不佳。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 微秒。请注意，由于调度中的跟踪点在实际“切换”之前，因此我们在记录的任务即将调度时停止跟踪。如果我们在调度程序末尾添加新标记，则可能会更改此设置。
请注意，记录的任务是 ‘sleep’，PID 为 2389，并且其 rt_prio 为 5。此优先级是用户空间优先级，而不是内部内核优先级。对于 SCHED_FIFO，策略为 1，对于 SCHED_RR，策略为 2。
请注意，跟踪数据显示内部优先级 (99 - rtprio)。
<idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
0:120:R 表示空闲以 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
测试运行的窗口时间长度。也就是说，测试将每“window”微秒运行“width”微秒。
- 如果进程正在执行跟踪，并且当进程完成时应缩小“释放”环形缓冲区，即使它被信号终止，也可以使用此文件来实现该目的。关闭此文件后，环形缓冲区将调整大小为最小大小。让一个正在跟踪的进程也打开此文件，当该进程退出时，其此文件的文件描述符将被关闭，这样做时，环形缓冲区将被“释放”。
当测试启动时，会创建一个内核线程来运行测试。此线程将在每个周期（一个“窗口”）之间在 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 跟踪切换时看到无序的函数调用。
隐藏：echo nofuncgraph-cpu > trace_options
显示：echo funcgraph-cpu > trace_options
持续时间（函数的执行时间）显示在函数的右括号行上，或者在叶函数的情况下与当前函数在同一行上。默认情况下启用。
隐藏：echo nofuncgraph-duration > trace_options
显示：echo funcgraph-duration > trace_options
在达到持续时间阈值的情况下，开销字段位于持续时间字段之前。
隐藏：echo nofuncgraph-overhead > trace_options
显示：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 | }
标志
+ 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。默认情况下禁用。
隐藏：echo nofuncgraph-proc > trace_options
显示：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 | }绝对时间字段是自系统启动以来系统时钟给出的绝对时间戳。在函数的每个入口/出口都会给出此时间的快照
隐藏：echo nofuncgraph-abstime > trace_options
显示：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 搜索函数持续时间。默认情况下禁用。
隐藏：echo nofuncgraph-tail > trace_options
显示：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() */
每个跟踪函数的返回值可以显示在等号“=”之后。当遇到系统调用失败时，它可以非常有助于快速定位首先返回错误代码的函数。
隐藏：echo nofuncgraph-retval > trace_options
显示：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 时，可以以一种智能的方式显示返回值。具体来说，如果它是错误代码，它将以带符号的十进制格式打印，否则将以十六进制格式打印。
智能：echo nofuncgraph-retval-hex > trace_options
十六进制：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> 并调用 trace_printk() 在 __might_sleep() 内
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 调用点。
某些架构甚至不需要进行同步操作，可以直接将新代码覆盖到旧代码之上，而无需担心其他 CPU 同时执行它。
记录被跟踪函数的一个特殊副作用是，我们现在可以选择性地选择要跟踪哪些函数，以及哪些函数的 mcount 调用保持为 nops（空操作）。
使用两个文件，一个用于启用指定函数的跟踪，另一个用于禁用。
tracing_cpumask
它们是
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
[...]
您可以在以下文件中找到可以添加到这些文件的可用函数列表：
# 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
如果我只对 sys_nanosleep 和 hrtimer_interrupt 感兴趣
# cat set_ftrace_filter
hrtimer_interrupt
sys_nanosleep
要查看正在跟踪哪些函数，您可以 cat 以下文件：
也许这还不够。过滤器还允许 glob(7) 匹配。<match>*
将匹配以 <match> 开头的函数*<match>
将匹配以 <match> 结尾的函数*<match>*
将匹配包含 <match> 的函数<match1>*<match2>
将匹配以 <match1> 开头并以 <match2> 结尾的函数
注意
# echo 'hrtimer_*' > set_ftrace_filter
最好使用引号将通配符括起来，否则 shell 可能会将参数扩展为本地目录中的文件名。
# 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
产生
# cat set_ftrace_filter
hrtimer_run_queues
hrtimer_run_pending
hrtimer_init
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
请注意，我们丢失了 sys_nanosleep。
这是因为“>”和“>>”的作用与 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_init
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
再次，现在我们要追加。
# echo '*preempt*' '*lock*' > set_ftrace_notrace
最好使用引号将通配符括起来，否则 shell 可能会将参数扩展为本地目录中的文件名。
# 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
set_ftrace_notrace 阻止跟踪这些函数。
我们可以看到不再有 lock 或 preempt 跟踪。
通过索引选择函数过滤器¶
# 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
将选择“available_filter_functions”中列出的第一个函数
使用函数图跟踪器的动态 ftrace¶
尽管上面解释的内容涉及函数跟踪器和函数图跟踪器，但有些特殊功能仅在函数图跟踪器中可用。
echo __do_fault > set_graph_function
如果要仅跟踪一个函数及其所有子函数，只需将其名称回显到 set_graph_function 中即可
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 | }
将生成 __do_fault() 函数的以下“扩展”跟踪
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
可以使用以下命令禁用（和启用）它：
过滤器命令¶
<function>:<command>:<parameter>
set_ftrace_filter 接口支持一些命令。跟踪命令具有以下格式
支持以下命令
mod：此命令启用每个模块的函数过滤。参数定义模块。例如，如果只需要 ext3 模块中的 write* 函数，请运行
echo 'write*:mod:ext3' > set_ftrace_filter
echo '!writeback*:mod:ext3' >> set_ftrace_filter
此命令与基于函数名称的过滤以相同的方式与过滤器交互。因此，通过追加 (>>) 到过滤器文件来实现添加其他模块中的更多函数。通过在前面加上“!”来删除特定的模块函数
echo '!*:mod:!ext3' >> set_ftrace_filter
Mod 命令支持模块通配符。禁用所有函数的跟踪，除了特定模块
echo '!*:mod:*' >> set_ftrace_filter
禁用所有模块的跟踪，但仍然跟踪内核
echo '*write*:mod:!*' >> set_ftrace_filter
仅为内核启用过滤器
echo '*write*:mod:*snd*' >> set_ftrace_filter
为模块通配符启用过滤器
echo '__schedule_bug:traceoff:5' > set_ftrace_filter
traceon/traceoff：这些命令在命中指定函数时打开和关闭跟踪。参数确定跟踪系统打开和关闭的次数。如果未指定，则没有限制。例如，要在第一次命中调度错误时禁用跟踪 5 次，请运行
echo '__schedule_bug:traceoff' > set_ftrace_filter
要在命中 __schedule_bug 时始终禁用跟踪
echo '!__schedule_bug:traceoff:0' > set_ftrace_filter
这些命令是累积的，无论它们是否附加到 set_ftrace_filter。要删除命令，请在其前面加上“!”并删除参数
echo '!__schedule_bug:traceoff' > set_ftrace_filter
上面删除了具有计数器的 __schedule_bug 的 traceoff 命令。要删除没有计数器的命令
echo 'native_flush_tlb_others:snapshot' > set_ftrace_filter
snapshot：将在命中函数时触发快照。
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
删除以上命令
echo 'try_to_wake_up:enable_event:sched:sched_switch:2' > \ set_ftrace_filterenable_event/disable_event：这些命令可以启用或禁用跟踪事件。请注意，由于函数跟踪回调非常敏感，因此在注册这些命令时，跟踪点将被激活，但在“软”模式下禁用。也就是说，将调用跟踪点，但不会被跟踪。只要有触发它的命令，事件跟踪点就会保持在此模式下。
<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 环形缓冲区的内容转储到控制台。如果您需要调试某些内容，并且希望在命中某个函数时转储跟踪，这将非常有用。也许它是一个在发生三重故障之前调用的函数，并且不允许您获得常规转储。
cpudump：当命中该函数时，它会将当前 CPU 的 ftrace 环形缓冲区的内容转储到控制台。与“dump”命令不同，它仅打印出执行了触发转储的函数的 CPU 的环形缓冲区内容。
stacktrace：当命中该函数时，会记录堆栈跟踪。
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_pipe 读取都会被消耗。这意味着后续读取将不同。跟踪是实时的。
请注意，读取 trace_pipe 文件将阻塞，直到添加更多输入。这与跟踪文件相反。如果任何进程打开跟踪文件进行读取，它实际上会禁用跟踪并阻止添加新条目。trace_pipe 文件没有此限制。
跟踪条目¶
# cat buffer_size_kb
1408 (units kilobytes)
在诊断内核中的问题时，数据过多或不足都可能很麻烦。文件 buffer_size_kb 用于修改内部跟踪缓冲区的大小。列出的数字是每个 CPU 可以记录的条目数。要了解完整大小，请将可能的 CPU 数乘以条目数。
# cat buffer_total_size_kb
5632
或直接读取 buffer_total_size_kb
# echo 10000 > buffer_size_kb
# cat buffer_size_kb
10000 (units kilobytes)
要修改缓冲区，只需回显一个数字（以 1024 字节段为单位）。
# echo 1000000000000 > buffer_size_kb
-bash: echo: write error: Cannot allocate memory
# cat buffer_size_kb
85
它将尝试分配尽可能多的空间。如果您分配过多，则可能会触发内存不足。
# echo 10000 > per_cpu/cpu0/buffer_size_kb
# echo 100 > per_cpu/cpu1/buffer_size_kb
也可以单独更改每个 CPU 的缓冲区
# cat buffer_size_kb
X
当每个 CPU 的缓冲区不相同时，顶层的 buffer_size_kb 将仅显示 X
# cat buffer_total_size_kb
12916
这是 buffer_total_size_kb 有用的地方
写入顶层 buffer_size_kb 将再次将所有缓冲区重置为相同。
快照¶
CONFIG_TRACER_SNAPSHOT 使所有非延迟跟踪器都可以使用通用快照功能。（记录最大延迟的延迟跟踪器，例如“irqsoff”或“wakeup”，无法使用此功能，因为这些跟踪器已经在内部使用快照机制。）
快照在特定时间点保留当前跟踪缓冲区，而不会停止跟踪。Ftrace 将当前缓冲区与备用缓冲区交换，并且跟踪在新当前（=先前的备用）缓冲区中继续。
snapshot
“tracing”中的以下 tracefs 文件与此功能相关
此文件用于拍摄快照并读取快照的输出。将 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
如果您尝试在当前跟踪器是延迟跟踪器之一时使用此快照功能，您将获得以下结果。
实例¶
# 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
在 tracefs 跟踪目录中，有一个名为“instances”的目录。可以使用 mkdir 在此目录中创建新目录，并使用 rmdir 删除目录。使用 mkdir 在此目录中创建的目录将在创建后就已经包含文件和其他目录。
如您所见，新目录看起来与跟踪目录本身类似。实际上，它非常相似，只是缓冲区和事件与主目录或任何其他创建的实例无关。
新目录中的文件的工作方式与跟踪目录中同名的文件相同，只是使用的缓冲区是一个单独的新缓冲区。这些文件会影响该缓冲区，但不会影响主缓冲区，但 trace_options 除外。当前，trace_options 对所有实例和顶层缓冲区的影响相同，但将来版本可能会更改。也就是说，选项可能会成为特定于它们所在的实例。
# 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 堆栈跟踪功能。要启用它，请在 /proc/sys/kernel/stack_tracer_enabled 中写入“1”。
# 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 文件中找到。