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”文件相同，但此文件旨在与实时跟踪一起流式传输。从此文件读取将阻塞，直到检索到新数据。与“trace”文件不同，此文件是消费者。这意味着从此文件读取会导致顺序读取显示更多当前数据。一旦数据从此文件读取，它就会被消耗，并且不会在顺序读取中再次读取。“trace”文件是静态的，如果跟踪器没有添加更多数据，每次读取时它都会显示相同的信息。
trace_options
此文件允许用户控制上述输出文件之一中显示的数据量。还存在用于修改跟踪器或事件工作方式的选项（栈跟踪、时间戳等）。
options
这是一个目录，其中包含每个可用跟踪选项的文件（也在 trace_options 中）。也可以通过将“1”或“0”分别写入具有选项名称的相应文件中来设置或清除选项。
tracing_max_latency
一些跟踪器会记录最大延迟。例如，中断禁用的最长时间。最长时间保存在此文件中。最大跟踪也将存储并由“trace”显示。仅当延迟大于此文件中的值（以微秒为单位）时，才会记录新的最大跟踪。
通过将时间回显到此文件中，除非延迟大于此文件中的时间，否则不会记录任何延迟。
tracing_thresh
当延迟大于此文件中的数字时，一些延迟跟踪器将记录跟踪。仅当文件包含大于 0 的数字时才激活（以微秒为单位）。
buffer_percent
这是环形缓冲区需要填充多少才能唤醒等待者的水位线。也就是说，如果应用程序对其中一个 per_cpu trace_pipe_raw 文件调用阻塞式读取系统调用，它将阻塞直到环形缓冲区中存在由 buffer_percent 指定的数据量，然后才唤醒读取器。这还控制 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 的任务分叉时，子任务的 PID 将自动添加到此文件中，并且子任务也将被函数跟踪器跟踪。此选项还会导致退出任务的 PID 从文件中删除。
set_ftrace_notrace_pid
使函数跟踪器忽略此文件中列出的 PID 的线程。
如果设置了“function-fork”选项，那么当此文件中列出 PID 的任务分叉时，子任务的 PID 将自动添加到此文件中，并且子任务也不会被函数跟踪器跟踪。此选项还会导致退出任务的 PID 从文件中删除。
如果一个 PID 同时在此文件和“set_ftrace_pid”中，则此文件优先，并且该线程将不被跟踪。
set_event_pid
使事件仅跟踪此文件中列出的 PID 的任务。请注意，sched_switch 和 sched_wake_up 也会跟踪此文件中列出的事件。
要在分叉时将此文件中列出 PID 的子任务的 PID 添加到此文件中，请启用“event-fork”选项。该选项还会导致任务退出时将其 PID 从此文件中删除。
set_event_notrace_pid
使事件不跟踪此文件中列出的 PID 的任务。请注意，sched_switch 和 sched_wakeup 将跟踪未在此文件中列出的线程，即使线程的 PID 在文件中，如果 sched_switch 或 sched_wakeup 事件也跟踪应该被跟踪的线程。
要在分叉时将此文件中列出 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 地址不同。
syscall_user_buf_size
一些系统调用跟踪事件将记录来自用户空间地址的数据，其中一个参数指向该地址。每个事件的数据量是有限的。此文件保存将记录到环形缓冲区中以保存此数据的最大字节数。最大值当前为 165。
dyn_ftrace_total_info
此文件用于调试目的。已转换为 nops 并可供跟踪的函数数量。
enabled_functions
此文件更多用于调试 ftrace，但也可用于查看是否有任何函数附加了回调。跟踪基础设施不仅使用 ftrace 函数跟踪实用程序，其他子系统也可能使用。此文件显示所有附加了回调的函数以及已附加的回调数量。请注意，回调也可能调用多个函数，这些函数将不在此计数中列出。
如果回调注册为由具有“save regs”属性的函数（因此开销更大）跟踪，则将在返回寄存器的函数所在的同一行显示“R”。
如果回调注册为由具有“ip modify”属性的函数（因此 regs->ip 可以更改）跟踪，则将在可以覆盖的函数所在的同一行显示“I”。
如果附加了非 ftrace 跳板 (BPF)，将显示“D”。请注意，也可以附加正常的 ftrace 跳板，但一次只能将一个“直接”跳板附加到给定函数。
某些架构无法调用直接跳板，而是将 ftrace ops 函数位于函数入口点之上。在这种情况下，将显示“O”。
如果一个函数过去曾附加“ip modify”或“direct”调用，将显示“M”。此标志永不清除。它用于了解函数是否曾被 ftrace 基础设施修改过，并可用于调试。
如果架构支持，它还会显示函数直接调用的回调。如果计数大于 1，则很可能是
ftrace_ops_list_func()。如果函数的 callback 跳转到特定于该 callback 且不是标准 trampoline 的 trampoline，则将打印其地址以及该 trampoline 调用的函数。
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
与函数图跟踪器一起使用。这是它将跟踪到函数中的最大深度。将其设置为一将仅显示从用户空间调用的第一个内核函数。
printk_formats
这适用于读取原始格式文件的工具。如果环形缓冲区中的事件引用字符串，则只有指向字符串的指针被记录到缓冲区中，而不是字符串本身。这阻止了工具知道该字符串是什么。此文件显示字符串的字符串和地址，允许工具将指针映射到字符串。
saved_cmdlines
除非事件也专门保存任务命令，否则在跟踪事件中只记录任务的 PID。Ftrace 创建了 PID 到命令的映射缓存，以尝试显示事件的命令。如果命令的 PID 未列出，则输出中会显示“<...>”。
如果选项“record-cmd”设置为“0”，则在记录期间不会保存任务的命令。默认情况下，它是启用的。
saved_cmdlines_size
默认情况下，保存 128 个命令（参见上面的“saved_cmdlines”）。要增加或减少缓存的命令数量，请将要缓存的命令数量回显到此文件中。
saved_tgids
如果设置了“record-tgid”选项，则在每次调度上下文切换时，任务的任务组 ID (TGID) 都保存在一个将线程 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，还可用于关联跨 hypervisor/guest 的事件。
- s390-tod
这使用 s390 TOD 时钟值。此时钟通常在虚拟机和启用 STP 的机器之间同步。
- 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 跟踪器：基于 Uprobe 的事件跟踪
uprobe_profile
Uprobe 统计。请参阅 uprobetrace.txt
instances
这是一种创建多个跟踪缓冲区的方法，其中不同的事件可以记录在不同的缓冲区中。请参阅下面的“实例”部分。
events
这是跟踪事件目录。它包含已编译到内核中的事件跟踪点（也称为静态跟踪点）。它显示了哪些事件跟踪点存在以及它们如何按系统分组。在不同级别有“enable”文件，当写入“1”时可以启用跟踪点。
有关更多信息，请参阅事件跟踪。
set_event
通过将事件回显到此文件中，将启用该事件。
有关更多信息，请参阅事件跟踪。
show_event_filters
具有过滤器的事件列表。这显示了系统/事件对以及附加到事件的过滤器。
有关更多信息，请参阅事件跟踪。
show_event_triggers
具有触发器的事件列表。这显示了系统/事件对以及附加到事件的触发器。
有关更多信息，请参阅事件跟踪。
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
这类似于主“快照”文件，但只会快照当前 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。当记录到新的最大值时，它会替换旧的跟踪。最好在启用 latency-format 选项的情况下查看此跟踪，该选项在选择跟踪器时会自动发生。
“preemptoff”
类似于 irqsoff，但跟踪并记录抢占被禁用的时间量。
“preemptirqsoff”
类似于 irqsoff 和 preemptoff，但跟踪并记录 irqs 和/或抢占被禁用的最长时间。
“wakeup”
跟踪并记录最高优先级任务在被唤醒后获得调度所需的最大延迟。跟踪所有任务，正如普通开发人员所期望的那样。
“wakeup_rt”
跟踪并记录仅 RT 任务（如当前“wakeup”跟踪器）唤醒所需的最大延迟。这对于对 RT 任务唤醒时间感兴趣的人很有用。
“wakeup_dl”
跟踪并记录 SCHED_DEADLINE 任务唤醒所需的最大延迟（如“wakeup”和“wakeup_rt”跟踪器）。
“mmiotrace”
一种特殊的跟踪器，用于跟踪二进制模块。它将跟踪模块对硬件进行的所有调用，以及从 I/O 进行的所有写入和读取。
“branch”
此跟踪器可在跟踪内核中可能/不可能的调用时进行配置。它将跟踪何时命中可能和不可能的分支，以及它是否正确预测了正确性。
“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）。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
当启用 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
按照它们的类型描述打印字段。这比使用 hex、bin 或 raw 更好的选择，因为它更好地解析了事件的内容。
- 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 的 errno 错误。
- 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”显示哈希指针值而不是实际地址。如果您想找出跟踪日志中哪个哈希值对应实际值，这将很有用。
- bitmask-list
启用后，位掩码使用 printk “%*pbl”格式说明符以人类可读的范围列表（例如，0,2-5,7）显示。禁用时（默认），位掩码以传统的十六进制位图表示显示。列表格式对于跟踪 CPU 掩码和其他大型位掩码特别有用，其中单个位位置比其十六进制编码更有意义。
- record-cmd
当启用任何事件或跟踪器时，sched_switch 跟踪点中会启用一个钩子，以使用映射的 PID 和命令填充命令缓存。但这可能会导致一些开销，如果您只关心 PID 而不关心任务名称，禁用此选项可以降低跟踪的影响。请参阅“saved_cmdlines”。
- record-tgid
当启用任何事件或跟踪器时，sched_switch 跟踪点中会启用一个钩子，以填充映射到 PID 的线程组 ID (TGID) 缓存。请参阅“saved_tgids”。
- overwrite
这控制了跟踪缓冲区已满时会发生什么。如果为“1”（默认），则丢弃并覆盖最旧的事件。如果为“0”，则丢弃最新的事件。（请参阅 per_cpu/cpu0/stats 以了解 overrun 和 dropped）
- 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 的任务在分叉时，其子任务的 PID 将添加到 set_event_pid 中。此外，当 set_event_pid 中列出 PID 的任务退出时，其 PID 将从文件中删除。
这也影响 set_event_notrace_pid 中列出的 PID。
- function-trace
如果启用此选项（默认已启用），延迟跟踪器将启用函数跟踪。禁用时，延迟跟踪器不跟踪函数。这在执行延迟测试时可以降低跟踪器的开销。
- function-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
设置后，在每个跟踪函数之后显示图形栈的“溢出”。溢出是指调用栈深度大于为每个任务保留的深度。每个任务都有一个固定的函数数组用于调用图跟踪。如果调用深度超过该深度，则不跟踪该函数。溢出是由于超出此数组而错过的函数数量。
- funcgraph-cpu
设置后，将显示发生跟踪的 CPU 的 CPU 编号。
- funcgraph-overhead
设置后，如果函数花费的时间超过一定量，则显示延迟标记。请参阅上面头部描述下的“delay”。
- funcgraph-proc
与其他跟踪器不同，进程的命令行默认不显示，而仅在上下文切换期间跟踪任务进出时显示。启用此选项后，每个进程的命令将显示在每一行。
- funcgraph-duration
在每个函数结束（返回）时，以微秒为单位显示函数中的持续时间。
- funcgraph-abstime
设置后，时间戳将显示在每一行。
- funcgraph-irqs
禁用后，中断内部发生的函数将不被跟踪。
- funcgraph-tail
设置后，返回事件将包含它所代表的函数。默认情况下，此功能处于关闭状态，函数的返回只显示一个右花括号“}”。
- funcgraph-retval
设置后，每个被跟踪函数的返回值将在等号“=”之后打印。默认情况下，此功能处于关闭状态。
- funcgraph-retval-hex
设置后，返回值将始终以十六进制格式打印。如果未设置此选项且返回值为错误代码，它将以带符号的十进制格式打印；否则它也将以十六进制格式打印。默认情况下，此选项处于关闭状态。
- sleep-time
运行函数图跟踪器时，在其函数中包含任务调度出的时间。启用后，它将把任务调度出的时间作为函数调用的一部分进行计算。
- 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 微秒和显示的时间戳 25 微秒之间的差异发生是因为在记录最大延迟时间和记录具有该延迟的函数之间，时钟增加了。
请注意，上面的示例没有设置 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
=> bh_submit
=> __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
=> bh_submit
=> 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 锁并启用中断（但未启用抢占）后，立即触发了一个中断。当中断完成后，它开始运行软中断。但在软中断运行时，又触发了另一个中断。当一个中断在软中断内部运行时，注解为‘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 任务，我们将以与以前的跟踪器略有不同的方式运行它。我们不是执行“ls”，而是在“chrt”下运行“sleep 1”，这会改变任务的优先级。
# 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 表示空闲任务以 nice 优先级 0 (120 - 120) 运行，处于运行状态‘R’。sleep 任务以 2389: 94:R 调度进来。这意味着优先级是内核 rtprio (99 - 5 = 94)，它也处于运行状态。
使用 chrt -r 5 和 function-trace set 执行相同的操作。
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
测试启动时，将创建一个运行测试的内核线程。该线程将在 tracing_cpumask 中列出的 CPU 之间轮流执行每个周期（一个“窗口”）。要将测试限制到特定的 CPU，请在此文件中设置掩码，使其仅包含测试应在其上运行的 CPU。
function¶
此跟踪器是函数跟踪器。可以从 debug 文件系统启用函数跟踪器。确保 ftrace_enabled 已设置；否则此跟踪器是一个 nop。请参阅下面的“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.
任务/PID字段显示执行该函数的线程命令行和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 时，消费者有责任执行窄化操作，并且高位可能包含未知值。因此，建议检查代码以处理此类情况。例如，当在 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 函数列表中移除其函数。这在模块卸载代码中是自动完成的，模块作者无需担心。
启用跟踪时，修改函数跟踪点（tracepoints）的过程取决于架构。旧方法是使用 kstop_machine 来防止与执行正在修改的代码的 CPU 发生竞争（这可能导致 CPU 执行不期望的操作，特别是如果修改后的代码跨越缓存（或页面）边界），然后将 nops 重新打补丁为调用。但这一次，它们不调用 mcount（这只是一个函数存根）。它们现在调用 ftrace 基础设施。
修改函数跟踪点的新方法是在要修改的位置设置一个断点，同步所有 CPU，修改断点未覆盖的指令的其余部分。再次同步所有 CPU，然后移除断点，用完成的版本替换为 ftrace 调用点。
某些架构甚至不需要费心进行同步，可以直接将新代码覆盖到旧代码上，而不会与其他 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¶
尽管上述解释同时涉及函数跟踪器和函数图跟踪器，但函数图跟踪器中仍有一些独有的特殊功能。
如果您只想跟踪一个函数及其所有子函数，只需将其名称 echo 到 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 命令支持模块通配符匹配。禁用除特定模块外的所有函数的跟踪：
echo '!*:mod:!ext3' >> set_ftrace_filter
禁用所有模块的跟踪，但仍跟踪内核：
echo '!*:mod:*' >> set_ftrace_filter
仅为内核启用过滤器：
echo '*write*:mod:!*' >> set_ftrace_filter
启用模块通配符匹配过滤器：
echo '*write*:mod:*snd*' >> set_ftrace_filter
traceon/traceoff：当达到指定函数时，这些命令会打开和关闭跟踪。参数决定跟踪系统打开和关闭的次数。如果未指定，则没有限制。例如，要在 schedule bug 首次发生 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
要修改缓冲区，只需 echo 一个数字（以 1024 字节为单位）。
# echo 10000 > buffer_size_kb
# cat buffer_size_kb
10000 (units kilobytes)
它将尝试分配尽可能多的内存。如果分配过多，可能导致触发内存不足（Out-Of-Memory）。
# 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
此文件用于拍摄快照并读取快照输出。向此文件 echo 1 以分配备用缓冲区并拍摄快照（交换），然后以与“trace”（如上文“文件系统”部分所述）相同的格式从此文件读取快照。快照读取和跟踪可以并行执行。当备用缓冲区被分配后，echo 0 可以释放它，而 echo 其他（正）值可以清除快照内容。更多细节显示在下表中。
状态\输入
0
1
其他
未分配
（不执行任何操作）
分配+交换
（不执行任何操作）
已分配
free
交换
清除
以下是使用快照功能的示例。
# 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 的 tracing 目录中，有一个名为“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
如您所见，新目录看起来与 tracing 目录本身相似。实际上，它非常相似，只是缓冲区和事件独立于主目录或创建的任何其他实例。
新目录中的文件功能与 tracing 目录中同名文件相同，只是所使用的缓冲区是独立的、新的缓冲区。这些文件会影响该缓冲区，但不会影响主缓冲区，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 栈跟踪功能。要启用它，请向 /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 时，栈跟踪器不会测试叶级函数。
目前，-mfentry 仅由 gcc 4.6.0 及更高版本在 x86 架构上使用。
更多信息¶
更多详细信息可以在源代码中，即 kernel/trace/*.c 文件中找到。