Linux tracer ftrace笔记（4）—— 各tracer和目录文件介绍_操作系统

kernel-5.10/Documentation/trace/ftrace.rst 翻译：

========================
ftrace - Function Tracer
========================

一、介绍

------------

Ftrace 是一个内部跟踪器，旨在帮助系统的开发人员和设计人员找到内核内部发生的事情。它可用于调试或分析发生在用户空间之外的延迟和性能问题。

尽管 ftrace 通常被认为是函数跟踪器，但它实际上是一个由多种跟踪实用程序组成的框架。有延迟跟踪来检查在禁用和启用中断之间发生了什么，以及抢占和从任务被唤醒到任务
被实际调度的时间。

ftrace 最常见的用途之一是事件跟踪。整个内核中有数百个静态 event points，可以通过 tracefs 文件系统启用它们，以查看内核某些部分发生的情况。

有关更多信息，请参阅 events.rst。

二、实现细节

---------------

有关 arch 的详细信息，请参阅 :doc:`ftrace-design`。

三、文件系统

---------------

Ftrace 使用 tracefs 文件系统来保存控制文件以及显示输出的文件。

当 tracefs 被配置到内核中时（选择任何 ftrace 选项都可以），目录 /sys/kernel/tracing 将被创建 #####。要挂载此目录，您可以添加到 /etc/fstab 文件中：

tracefs /sys/kernel/tracing tracefs 默认值 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 文件系统目录中。

为了不在 debugfs 文件系统中自动挂载 tracefs，###### 请启用 defconfig 选项 CONFIG_TRACEFS_DISABLE_AUTOMOUNT。

.. 注意：：

任何选定的 ftrace 选项也将创建 tracefs 文件系统。文档的其余部分将假定您在 ftrace 目录 (cd /sys/kernel/tracing) 中，并且将只关注该目录中的文件，而不会从带有扩展 /sys/kernel/tracing” 路径名的内容中分心 .

就是这样！（假设您已将 ftrace 配置到内核中）

四、关键文件

挂载 tracefs 后，您将可以访问 ftrace 的控制和输出文件。以下是一些关键文件的列表：

注意：所有时间值都以微秒为单位。

1. current_tracer：
这用于设置或显示配置的当前跟踪器。更改当前跟踪器会清除环形缓冲区内容以及“快照”缓冲区。比如 "nop" 这个tracer 在 trace_nop.c 中通过 struct tracer nop_trace 结构
描述。

2. available_tracers:
这包含已编译到内核中的不同类型的跟踪器。可以通过将其名子 echo 到 current_tracer 中来配置选中此处列出的跟踪器。由于 available_tracers 为nop，所有跟踪器功能无法使用。

3. tracing_on:
这将设置或显示是否启用写入trace环缓冲区。在此文件中写 0 以禁用跟踪器或写 1 以启用它。请注意，这只是禁用对环形缓冲区的写入，跟踪开销可能仍在发生。
内核函数 tracing_off() 可以在内核中使用来禁用对环形缓冲区的写入，这会将这个文件设置为“0”。用户空间可以通过在文件中写“1”来重新启用跟踪。
请注意，函数和事件触发器 “traceoff” 也会将此文件设置为零并停止跟踪。用户空间也可以使用此文件重新启用。

4. race:
该文件以人类可读的格式保存跟踪的输出（如下所述）。使用 O_TRUNC 标志打开此文件进行写入会清除环形缓冲区内容。请注意，此文件不是消费者。
如果跟踪关闭（没有跟踪器运行，或者 tracing_on 为零），则每次读取时都会产生相同的输出。当跟踪打开时，它可能会产生不一致的结果，因为它试图读取整个缓冲区而不消耗它。

5. trace_pipe:
输出与 "trace" 文件相同，但此文件旨在通过实时跟踪进行流式传输。从此文件读取将阻塞，直到检索到新数据。与 "trace" 文件不同，此文件是消费者。
这意味着从该文件读取会导致顺序读取显示更多当前数据。一旦从这个文件中读取数据，它就会被消耗掉，并且不会通过顺序读取再次读取。 "trace" 文件是静态的，
如果跟踪器没有添加更多数据，则每次读取时都会显示相同的信息。

6. trace_options:
该文件允许用户控制在输出上述文件中之一的数据量。还可以选择修改跟踪器或事件的工作方式（堆栈跟踪、时间戳等）。
补充：echo 1 > options/hex 和 echo hex > trace_options 是一样的效果，可有通过 echo nohex > trace_options 取消16进制显示。

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

8. tracing_max_latency:
一些跟踪器记录最大延迟。例如，禁用中断的最长时间。最长时间保存在此文件中。最大跟踪也将被存储，并通过 "trace" 文件显示。只有当延迟大于此文件中的值（以微秒为
单位）时，才会记录新的最大延迟trace。
通过echo一个时间到此文件中，不会记录其它任何延迟，除非它大于此文件中的时间。

9. tracing_thresh:
每当延迟大于此文件中的数字时，某些延迟跟踪器将记录跟踪。仅当文件包含大于 0 的数字时才有效。（以微秒为单位）

10. buffer_size_kb:
这将设置或显示每个 CPU 缓冲区保存的千字节数(注意是每个) #####。默认情况下，每个 CPU 的跟踪缓冲区大小相同。显示的数字是 CPU 缓冲区的大小，而不是所有缓冲区的总大
小。跟踪缓冲区按页（内核用于分配的内存块，大小通常为 4KB）进行分配。可以分配一些额外的页面来容纳缓冲区管理元数据。如果分配的最后一个页面的空间比请求的字节多，
则将使用页面的其余部分，使实际分配大于请求或显示的空间。（注意，由于缓冲区管理元数据，大小可能不是页面大小的倍数。）
各个 CPU 的缓冲区大小可能会有所不同（请参阅下面的“per_cpu/cpu0/buffer_size_kb”），如果这样做，此文件将显示“X”。

11. buffer_total_size_kb:
这将显示所有(CPU的)跟踪缓冲区的总大小。

12. free_buffer:
如果一个进程正在执行跟踪，并且在进程完成时应该收缩“freed”环形缓冲区，即使它被信号杀死，该文件也可以用于该目的。关闭此文件时，环形缓冲区将调整到其最小大小。
让一个正在跟踪的进程也打开这个文件，当进程退出时，这个文件的文件描述符将被关闭，这样做时，环形缓冲区将被“释放”。

如果设置了 disable_on_free 选项，它也可能会停止跟踪。

13. trace_cpumask:
这是一个让用户只跟踪指定 CPU 的掩码。格式是表示 CPU 的十六进制字符串。echo ff 或 01 分别表示跟踪全部CPU或只CPU0。

14. set_ftrace_filter:
在配置动态 ftrace 时（请参阅下面的"dynamic ftrace"部分），代码将被动态修改（code text 重写）以禁用函数分析器 (mcount) 的调用。这允许在几乎没有性能开销的情况下配
置跟踪。这也具有启用或禁用要跟踪的特定功能的副作用。将函数的名称echo到此文件中会将跟踪限制为仅这些函数。这会影响跟踪器“function”和“function_graph”，因此也会影
响函数分析（参见“function_profile_enabled”）。

15. set_ftrace_notrace:
这与 set_ftrace_filter 的效果相反。在此添加的任何功能都不会被追踪。如果 set_ftrace_filter 和 set_ftrace_notrace 中都存在一个函数，则该函数将_不_被跟踪。

16. set_ftrace_pid:
让函数跟踪器只跟踪其 PID 列在此文件中的线程。
如果设置了“function-fork”选项，那么当一个PID列在这个文件中的任务fork时，子进程的PID会自动添加到这个文件中，子进程也会被函数跟踪器跟踪。此选项还将导致退出的任务
的 PID 从文件中删除。

17. set_ftrace_notrace_pid:
让函数跟踪器忽略其 PID 列在此文件中的线程。
如果设置了“function-fork”选项，那么当一个PID列在这个文件中的任务fork时，子进程的PID会自动添加到这个文件中，子进程也不会被函数跟踪器跟踪。此选项还将导致退出的任务
的 PID 从文件中删除。
如果这个文件和“set_ftrace_pid”中都有一个PID，那么这个文件优先，线程不会被跟踪。

18. set_event_pid:
让事件仅跟踪具有此文件中列出的 PID 的任务。请注意， sched_switch 和 sched_wake_up 还将跟踪此文件中列出的事件。
要在 fork 上添加带有此文件中的 PID 的任务子项的 PID，请启用“event-fork”选项。该选项还将导致在任务退出时从该文件中删除任务的 PID。

19. set_event_notrace_pid:
让事件不使用此文件中列出的 PID 跟踪任务。请注意，如果 sched_switch 或 sched_wakeup 事件也跟踪应跟踪的线程，则 sched_switch 和 sched_wakeup 将跟踪未在此文件中列出
的线程，即使线程的 PID 在文件中。
要在 fork 上添加带有此文件中的 PID 的任务子项的 PID，请启用“event-fork”选项。该选项还将导致在任务退出时从该文件中删除任务的 PID。

20. set_graph_function:
此文件中列出的函数将导致函数图跟踪器仅跟踪这些函数及其调用的函数。（有关更多详细信息，请参阅"dynamic ftrace"部分）。请注意， set_ftrace_filter 和
set_ftrace_notrace 仍然会影响正在跟踪的函数。

21. set_graph_notrace：
类似于 set_graph_function，但会在函数被命中时禁用函数图跟踪，直到它退出函数。这使得可以忽略由特定函数调用的跟踪函数。

22. available_filter_functions:
这列出了 ftrace 已处理并可跟踪的函数。这些是您可以传递给“set_ftrace_filter”、“set_ftrace_notrace”、“set_graph_function”或“set_graph_notrace”的函数名称。
（有关更多详细信息，请参阅下面的"dynamic ftrace"部分。）

23. dyn_ftrace_total_info:
此文件用于调试目的。已转换为 nops 函数是可用于跟踪的。

24. enabled_functions:
此文件更多用于调试 ftrace，但也可用于查看是否有任何函数附加了回调。不仅跟踪基础设施使用 ftrace 函数跟踪实用程序，而且其他子系统也可能使用。此文件显示所有附加了
回调的函数以及已附加的回调数。请注意，一个回调也可能调用多个函数，这些函数不会在此计数中列出。
如果回调注册为由具有“save regs”属性的函数跟踪（因此开销更大），则“R”将显示在与返回寄存器的函数相同的行上。
如果回调注册为由具有“ip modify”属性的函数跟踪（因此可以更改 regs->ip），则“I”将显示在与可以覆盖的函数相同的行上。
如果架构支持它，它还会显示函数直接调用的回调。如果计数大于 1，则很可能是 ftrace_ops_list_func()。
如果函数的回调跳转到特定于回调的蹦床而不是标准蹦床，则将打印其地址以及蹦床调用的函数。

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

26. trace_stat:
保存不同跟踪统计信息的目录。

27. kprobe_events：
启用动态跟踪点。参见 kprobetrace.rst。

28. kprobe_profile:
动态跟踪点统计信息。参见 kprobetrace.rst。

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

30. printk_formats:
这是用于读取原始格式文件的工具。如果环形缓冲区中的事件引用了一个字符串，则只会将指向该字符串的指针记录到缓冲区中，而不是字符串本身。这可以防止工具知道该字符串是
什么。该文件显示字符串的字符串和地址，允许工具将指针映射到字符串的内容。例如 /rcu/tree.c:trace_rcu_utilization(TPS("Start scheduler-tick")); 中的 "Start scheduler-tick"
将会显示在该文件中。

31. saved_cmdlines:
只有任务的 pid 会记录在跟踪事件中，除非该事件还专门保存了任务的comm。 Ftrace 将 pid 映射缓存到comm以尝试显示事件的comm。如果未列出通信的 pid，则输出中将显示“<...>”。###############
如果选项“record-cmd”设置为“0”，则在记录过程中不会保存任务的comm。默认情况下，它是启用的。

32. saved_cmdlines_size:
默认情况下，会保存 128 条 comms（请参阅上面的“saved_cmdlines”）。要增加或减少缓存的comm数量，请将要缓存的comm的数量echo到此文件中。

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

34. snapshot:
这将显示"snapshot"缓冲区，并且还允许用户获取当前运行跟踪的快照。有关更多详细信息，请参阅下面的"Snapshot"部分。

35. stack_max_size:
当堆栈跟踪器被激活时，这将显示它遇到的最大堆栈大小。请参阅下面的"Stack Trace"部分。

36. stack_trace:
这将显示激活堆栈跟踪器时遇到的最大堆栈的堆栈回溯跟踪。请参阅下面的"Stack Trace"部分。

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

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

用于跟踪的常用时钟::
/sys/kernel/tracing # cat trace_clock
local global counter uptime perf mono mono_raw [boot]

带有方括号的时钟是有效时钟，就是当前选中的。

(1) local: 默认时钟，但可能不会跨 CPU 同步
(2) global: 该时钟与所有 CPU 同步，但可能比本地时钟慢一些。
(3) counter: 这根本不是一个时钟，而是一个原子计数器。它会一一计数，但与所有 CPU 同步。当您需要确切地知道在不同 CPU 上彼此发生的顺序事件时，这很有用。##########
(4) uptime: 这使用 jiffies 计数器，时间戳是相对于启动时间的。
(5) perf: 这使得 ftrace 使用与 perf 相同的时钟。最终 perf 将能够读取 ftrace 缓冲区，这将在交错数据中有帮助。
(6) x86-tsc：架构可以定义自己的时钟。例如，x86 在这里使用自己的 TSC 周期时钟。
(7) ppc-tb：这使用 powerpc 时基寄存器值。这是跨 CPU 同步的，如果 tb_offset 已知，也可用于关联管理程序/访客之间的事件。
(8) mono: 这使用快速单调时钟 (CLOCK_MONOTONIC)，它是单调的并且受 NTP 速率调整的影响。
(9) mono_raw：这是原始单调时钟 (CLOCK_MONOTONIC_RAW)，它是单调的，但不受任何速率调整的影响，并且以与硬件时钟源相同的速率滴答。
(10) boot: 这是启动时钟 (CLOCK_BOOTTIME)，基于快速单调时钟，但也考虑了挂起所花费的时间。由于时钟访问被设计用于挂起路径中的跟踪，如果在更新快速单声道时钟之前考虑挂起时

间之后访问时钟，则可能会产生一些副作用。在这种情况下，时钟更新似乎比正常情况发生得稍早。同样在 32 位系统上，64 位引导偏移可能会看到部分更新。这些效果很少见，后
期处理应该能够处理它们。有关更多信息，请参阅 ktime_get_boot_fast_ns() 函数中的注释。

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

# echo global > trace_clock

设置时钟会清除环形缓冲区内容以及"snapshot"缓冲区。

39. 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", WR_ONLY);

注意：写入 trace_marker 文件也可以启动写入 /sys/kernel/tracing/events/ftrace/print/trigger 的触发器
请参阅 Documentation/trace/events.rst 中的 "Event triggers" 和 Documentation/trace/histogram.rst 中的示例（第 3 节）

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

41. upprobe_events：
在程序中添加动态跟踪点。参见 uprobetracer.rst

42. uprobe_profile:
Uprobe 统计。参见 uprobetrace.txt

43. instances:
这是一种制作多个跟踪缓冲区的方法，其中不同的事件可以记录在不同的缓冲区中。请参阅下面的 "Instances" 部分。

44. events:
这是跟踪事件目录。它保存已编译到内核中的事件跟踪点（也称为静态跟踪点）。它显示了存在哪些事件跟踪点以及它们如何按系统分组。不同级别的 "enable" 文件可以在向跟踪
点写入“1”时启用跟踪点。也就是说向 events 根目录下的enable写1就是使能所有的event，向i2c子目录下写1就是使能i2c相关的所有trace event。
有关更多信息，请参阅 events.rst。

45. set_event:
通过将event echo到此文件中，将启用该事件。有关更多信息，请参阅 events.rst。

46. available_events:
可以在tracing中启用的事件列表。有关更多信息，请参阅 events.rst。

47. timestamp_mode:
某些跟踪器可能会更改将跟踪事件记录到事件缓冲区时使用的时间戳模式。具有不同模式的事件可以在缓冲区中共存，但记录事件时生效的模式决定了该事件使用哪种时间戳模式。
默认时间戳模式是“delta”。
用于跟踪的常用时间戳模式：
# cat timestamp_mode
[delta] absolute
带有方括号的时间戳模式是设置为有效的模式。
delta：默认时间戳模式 - 时间戳是针对每个缓冲区时间戳的增量。
absolute：时间戳是一个完整的时间戳，而不是相对于其他值的增量。因此，它占用更多空间并且效率较低。

48. hwlat_detector:
硬件延迟检测器的目录。请参阅下面的“Hardware Latency Detector”部分。

49. per_cpu：
这是一个包含跟踪 per_cpu 信息的目录。
per_cpu/cpu0/buffer_size_kb：
ftrace 缓冲区定义为 per_cpu。也就是说，每个 CPU 都有一个单独的缓冲区，允许以原子方式进行写入，并且不会出现cache bouncing。这些缓冲区可能有不同大小的缓冲区。
该文件类似于 buffer_size_kb 文件，但它仅显示或设置特定 CPU 的缓冲区大小。（这里是 cpu0）。

50. per_cpu/cpu0/trace:
这类似于“trace”文件，但它只会显示特定于 CPU 的数据。如果写入，它只会清除特定的 CPU 缓冲区。

51. per_cpu/cpu0/trace_pipe
这类似于“trace_pipe”文件，并且是消耗性读取，但它只会显示（和消耗）特定于 CPU 的数据。

52. per_cpu/cpu0/trace_pipe_raw
对于可以解析ftrace ring buffer二进制格式的工具，可以直接使用trace_pipe_raw文件从ring buffer中提取数据。通过使用 splice() 系统调用，可以将缓冲区数据快速传输到文
件或服务器正在收集数据的网络。和 trace_pipe 一样，这是一个消费读取器，多次读取总是会产生不同的数据。

53. per_cpu/cpu0/snapshot:
这类似于主“snapshot”文件，但只会对当前 CPU 进行快照（如果支持）。它只显示给定 CPU 的快照内容，如果写入，只清除该 CPU 缓冲区。

54. per_cpu/cpu0/snapshot_raw：
与 trace_pipe_raw 类似，但将从给定 CPU 的快照缓冲区读取二进制格式。

55. per_cpu/cpu0/stats:
这将显示有关环形缓冲区的某些统计信息：
entries: 仍在缓冲区中的事件数。
overrun: 缓冲区已满时由于覆盖而丢失的事件数。
commit overrun: 应该始终为零。如果在嵌套事件中发生了太多事件（环形缓冲区是可重入的），它会被设置，它会填充缓冲区并开始丢弃事件。
bytes: 实际读取的字节数（未覆盖）。
oldest event ts: 缓冲区中最旧的时间戳
now ts: 当前时间戳
dropped events: 由于覆盖选项关闭而丢失的事件。
read events: 读取的事件数。

五、The Tracers

---------------

这是可以配置的当前跟踪器的列表。

1. "function"：
函数调用跟踪器来跟踪所有内核函数。

2. "function_graph"：
类似于函数跟踪器，除了函数跟踪器在函数入口处探测函数，而函数图跟踪器同时跟踪函数的入口和出口。然后，它提供了绘制类似于 C 代码源的函数调用图的能力。

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

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

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

6. "preemptoff"
与 irqsoff 类似，但跟踪和记录禁用抢占的时间量。

7. "preemptirqsoff"
类似于 irqsoff 和 preemptoff，但跟踪和记录禁用 irqs 和/或 preemption 的最长时间。

8. "wakeup"
跟踪并记录最高优先级任务在被唤醒后被调度所需的最大延迟。像普通开发人员期望的那样跟踪所有任务。

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

10. “wakeup_dl”
跟踪并记录唤醒 SCHED_DEADLINE 任务所需的最大延迟（如“wakeup”和“wakeup_rt”所做的那样）。

11. "mmiotrace"
用于跟踪二进制模块的特殊跟踪器。它将跟踪模块对硬件进行的所有调用。它也从 I/O 写入和读取的所有内容。

12. "branch"
在跟踪内核中 likely/unlikely 调用时，可以配置此跟踪器。它将跟踪 likely 和 unlikely 的分支何时被命中，以及它的预测是否正确。

13. "nop"
这是“trace nothing”跟踪器。要从跟踪中删除所有跟踪器，只需将“nop” echo到 current_tracer 中即可。

六、Error conditions

--------------------

对于大多数 ftrace 命令，失败模式很明显，并且使用标准返回码进行通信。

对于其他更复杂的命令，可以通过 tracing/error_log 文件获得扩展错误信息。对于支持它的命令，在出现错误后读取 tracing/error_log 文件将显示有关出错原因的更多详细信息
（如果有信息可用）。 tracing/error_log 是一个循环错误日志，显示最后 (8) 个失败命令的少量（当前为 8 个）ftrace 错误。

扩展的错误信息和用法采用本例所示的形式：

# echo xxx > /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger 
echo: write error: Invalid argument 
 
# cat /sys/kernel/debug/tracing/error_log 
[ 5348.887237] location: error: Couldn't yyy: zzz 
  Command: xxx 
           ^ 
[ 7517.023364] location: error: Bad rrr: sss 
  Command: ppp qqq 
               ^

要清除错误日志，请将空字符串echo到其中：
# echo > /sys/kernel/debug/tracing/error_log

七、Examples of using the tracer

--------------------------------

以下是仅使用 tracefs 接口（不使用任何用户端实用程序）控制跟踪器时使用跟踪器的典型示例。

1. 输出格式：
--------------

以下是文件“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

标头与由跟踪表示的跟踪器名称一起打印。在这种情况下，tracer是“function”。然后它显示缓冲区中的事件数以及写入的条目总数。不同之处在于由于缓冲区填满而丢失的条目数（250280 - 140080 = 110200 个事件丢失）。

标题解释了事件的内容。任务名称“bash”、任务 PID“1977”、它在“000”CPU上运行的、延迟格式（如下所述）、<secs>.<usecs> 格式的时间戳、被跟踪的函数名称 “sys_close”和调
用此函数的父函数“system_call_fastpath”。时间戳是输入函数的时间。

八、Latency trace format

-----------------------
1. 当启用延迟格式选项或设置延迟跟踪器之一时，跟踪文件会提供更多信息以了解延迟发生的原因。这是一个典型的trace：

  # 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 是它们再次启用的地方。

2. 标题之后的下一行是跟踪器本身。标题解释了哪个是哪个:

cmd： 
    trace中的进程名称。 
pid： 
    该进程的PID。 
CPU#： 
    进程运行在哪个CPU。 
irqs-off:  
    - 'd' 中断被禁用， 
    - '.' 表示没被禁用。 
    警告:: 如果体系结构不支持读取 irq 标志变量的方法，则将始终在此处打印“X”。 
need-resched: 
    - 'N' TIF_NEED_RESCHED 和 PREEMPT_NEED_RESCHED 都被设置， 
    - 'n' 只设置了 TIF_NEED_RESCHED， 
    - 'p' 只设置了 PREEMPT_NEED_RESCHED， 
    - '.' 两个标志位都没设置。 
hardirq/softirq:  
    - 'Z' - 在 hardirq 上下文中触发 NMI 中断 
    - 'z' - NMI 正在运行 
    - 'H' - 在软中断上下文中触发硬中断 
    - 'h' - 硬中断正在运行 
    - 's' - 软中断正在运行 
    - '.' - 正常情况。 
preempt-depth： 
    preempt_disabled 的级别 
 
以上对内核开发人员来说最有意义。 
 
time: 
当启用 latency-format 选项时，跟踪文件输出包括一个相对于跟踪开始的时间戳。 这与禁用 latency-format 时的输出不同，其包括绝对时间戳。 
 
delay: 
这只是为了帮助您更好地吸引眼球。 并且需要固定为仅相对于同一个 CPU。 标记由当前trace和下一个trace之间的差异决定。 
- '$' - 大于 1 秒 
- '@' - 大于 100 毫秒 
- '*' - 大于 10 毫秒 
- '#' - 大于 1000 微秒 
- '!' - 大于 100 微秒 
- '+' - 大于 10 微秒 
- ' ' - 小于或等于 10 微秒。

其余部分与“trace”文件相同。

请注意，延迟跟踪器通常以回溯结束，以便轻松找到延迟发生的位置。

九、trace_options

-------------

1. trace_options 文件（或选项目录）用于控制在跟踪输出中打印的内容，或操作跟踪器。要查看可用的内容，只需对文件进行cat：

# cat trace_options
print-parent
nosym-offset
nosym-addr
noverbose
noraw
nohex
nobin
noblock
trace_printk
annotate
nouserstacktrace
nosym-userobj
noprintk-msg-only
context-info
nolatency-format
record-cmd
norecord-tgid
overwrite
nodisable_on_free
irq-info
markers
noevent-fork
function-trace
nofunction-fork
nodisplay-graph
nostacktrace
nobranch

要禁用其中一个选项，请在以“no”开头echo一个选项：

echo noprint-parent > trace_options

要启用一个选项，请去掉“no”::

echo sym-offset > trace_options

以下是可用选项：

(1) print-parent
在函数跟踪上，显示调用（父）函数以及被跟踪的函数。
print-parent:
bash-4000 [01] 1477.606694: simple_strtoul <-kstrtoul
noprint-parent:
bash-4000 [01] 1477.606694: simple_strtoul

(2) sym-offset
不仅显示函数名称，还显示函数中的偏移量。例如，您将看到的不是“ktime_get”，而是“ktime_get+0xb/0x20”。
sym-offset:
bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0

(3) sym-addr
这还将显示函数地址以及函数名称。
sym-addr:
bash-4000 [01] 1477.606694: simple_strtoul <c0339346>

(4) verbose
这在启用 latency-format 时跟踪文件的细节。
bash 4000 1 0 00000000 00010a95 [58127d26] 1720.415ms (+0.000ms): simple_strtoul (kstrtoul)

(5) raw
这将显示原始数字。此选项最适合与可以比在内核中更好地完成转换原始数字的用户应用程序一起使用。

(6) hex
与 raw 类似，但数字将采用十六进制格式。

(7) bin
这将以原始二进制格式打印。

(8) block
设置后，在轮询时读取 trace_pipe 不会阻塞。注：轮询读取(select、poll、epoll)才不会阻塞，实测cat还是会阻塞。

(9) trace_printk
可以禁止 trace_printk() 写入缓冲区。

(10) 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

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

(12) sym-userobj
当启用用户堆栈跟踪时，查找地址属于哪个对象，并打印一个相对地址。这在 ASLR 打开时特别有用，否则在应用程序不再运行后，您将没有机会将地址解析为对象/文件/行
当您读取 trace，trace_pipe 时执行查找。

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

注：但是测试没有生效，没有打印出路径。

(13) printk-msg-only
设置后，trace_printk()s 将只显示格式而不显示它们的参数（如果使用 trace_bprintk() 或 trace_bputs() 来保存 trace_printk()）。
只显示成：C|3358|front|-89，前面的部分没有了。测试发现上层通过 tracing_mark_write()写下来的也没有前缀了。

(14) context-info
仅显示事件数据。隐藏comm、PID、时间戳、CPU 和其他有用数据（中断、抢占等）。

(15) latency-format
此选项更改tarce的输出。启用后，跟踪会显示有关延迟的附加信息，如“Latency trace format”中所述。
测试发现只是时间戳变成以us为单位显示的时间了，而且CPU信息那一列还丢了。

(16) pause-on-trace
设置后，打开跟踪文件进行读取，将暂停写入环形缓冲区（就像tracing_on 设置为零一样）。这模拟了跟踪文件的原始行为。当文件关闭时，将再次启用跟踪。

(17) record-cmd
当启用任何事件或跟踪器时，将在 sched_switch 跟踪点中启用挂钩，以使用映射的 pid 和 comms 填充comm缓存。但这可能会导致一些开销，如果您只关心 pid，而不关心任务的名
称，则禁用此选项可以降低跟踪的影响。请参阅“saved_cmdlines”。
实测显示上好像没区别。

(18) record-tgid
当启用任何事件或跟踪器时，会在 sched_switch 跟踪点中启用挂钩以填充映射到 pid 的映射线程组 ID (TGID) 的缓存。请参阅“saved_tgids”。

(19) overwrite
这控制了当跟踪缓冲区已满时会发生什么。如果为“1”（默认），最旧的事件将被丢弃并覆盖。如果为“0”，则丢弃最新事件。（请参阅 per_cpu/cpu0/stats 了解超限和掉线）

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

(21) irq-info
显示interrupt, preempt count, need resched data。禁用时，跟踪看起来像：

# 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

但实测显示上没区别

(22) markers
设置后，trace_marker 是可写的（仅由 root 用户）。禁用时，trace_marker 将在写入时出现 EINVAL 错误。
注： disable这个，再diable trace_printk 这两个options后，就可以得到纯净的自己想trace的event的log.

(23) event-fork
设置后，具有在 set_event_pid 中列出的 PID 的任务将在这些任务 fork 时将其子项的 PID 添加到 set_event_pid。此外，当 set_event_pid 中带有 PID 的任务退出时，它们的
PID 将从文件中删除。
这也会影响 set_event_notrace_pid 中列出的 PID。

(24) function-trace
如果启用此选项（默认），则延迟跟踪器将启用功能跟踪。当它被禁用时，延迟跟踪器不会跟踪functions。这可以在执行延迟测试时降低跟踪器的开销。

(25) function-fork
设置后，具有在 set_ftrace_pid 中列出的 PID 的任务将在这些任务分叉时将其子项的 PID 添加到 set_ftrace_pid。此外，当 set_ftrace_pid 中带有 PID 的任务退出时，它们的
PID 将从文件中删除。
这也会影响 set_ftrace_notrace_pid 中的 PID。

(26) display-graph
设置后，延迟跟踪器（irqsoff、wakeup 等）将使用函数图跟踪而不是函数跟踪。

(27) stacktrace
设置后，将在记录任何跟踪事件后记录堆栈跟踪。

(28) branch
使用跟踪器启用分支跟踪。这将启用分支跟踪器以及当前设置的跟踪器。使用“nop”跟踪器启用此功能与仅启用“branch”跟踪器相同。

提示:: 一些跟踪器有自己的选择。它们仅在跟踪器处于active状态时出现在此文件中。但它们总是出现在选项目录中。

2. 以下是每跟踪器选项：

## function tracer的选项：

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

## function_graph 跟踪器的选项：

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

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

(2) funcgraph-cpu
设置后，将显示发生跟踪的 CPU 的 CPU 编号。

(3) funcgraph-overhead
设置后，如果函数花费的时间超过一定量，则显示延迟标记。请参阅上面标题描述下的“delay”。

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

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

(6) funcgraph-abstime
设置后，时间戳显示在每一行。

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

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

(9) sleep-time
在运行函数图跟踪器时，将任务安排在其函数中的时间包括在内。启用后，它将计算任务已作为函数调用的一部分被安排的时间。

(10) graph-time
使用函数图跟踪器运行函数探查器时，包括调用嵌套函数的时间。如果未设置，则为函数报告的时间将仅包括函数本身执行的时间，而不包括它调用的函数的时间。

## blk 跟踪器的选项：

(1) blk_classic
显示更简约的输出。

十、irqsoff

-----------

1. tracer作用和用途

当中断被禁用时，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 之间出现差异是因为时钟在记录最大延迟的时间和记录具有该延迟的函数之间有时间的增加。

注意上面的例子没有设置函数跟踪。如果我们设置函数跟踪，我们会得到更大的输出：

 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 微秒的延迟。但是我们也看到了在那段时间被调用的所有函数#####。请注意，通过启用函数跟踪，我们会产生额外的开销。这种开销可能会延长等待时间。
尽管如此，这个跟踪还是提供了一些非常有用的调试信息。

2. 如果我们更喜欢函数图输出而不是函数，我们可以设置 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

----------------

1. preemptoff tracer 功能描述
当抢占被禁用时，我们可能能够接收中断但任务不能被抢占，并且更高优先级的任务必须等待抢占再次被启用才能抢占较低优先级的任务。

preemptoff 跟踪器跟踪禁用抢占的位置。与 irqsoff 跟踪器一样，它记录禁用抢占的最大延迟。 preemptoff tracer 的控制很像 irqsoff tracer。

# 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 的抢占跟踪示例。在这里我们看到中断并没有一直被禁用。 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 tracer 会记录 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 的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

十三、wakeup

-------------

人们对跟踪感兴趣的一个常见情况是从唤醒任务到实际唤醒所需的时间。现在对于非实时任务，这可以是任意的。但追踪它仍然很有趣。

不带 function tracing 情况下的::

# 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

跟踪器只跟踪系统中优先级最高的任务，避免跟踪正常情况。在这里我们看到 kworker 的优先级为 -20（不是很好），从它醒来到运行只用了 15 微秒。

非实时任务没有那么有趣。一个更有趣的跟踪是只专注于实时任务。

十四、wakeup_rt

---------------

在实时环境中，了解唤醒最高优先级任务到执行时所需的唤醒时间非常重要。这也称为“调度延迟”。我强调一点，这是关于 RT 任务。了解非 RT 任务的调度延迟也很重要，但平均
调度延迟更适合非 RT 任务。像 LatencyTop 这样的工具更适合这样的测量。

实时环境对最坏情况的延迟感兴趣。是发生某事所需的最长延迟，而不是平均值。我们可以有一个非常快的调度程序，它可能只是偶尔会有很大的延迟，但这不适用于实时任务。
wakeup_rt 跟踪器旨在记录 RT 任务的最坏情况唤醒。非 RT 任务不会被记录，因为跟踪器只记录一种最坏情况，跟踪不可预测的非 RT 任务将覆盖 RT 任务的最坏情况延迟（只需运
行正常的 wakeup 跟踪器一段时间即可看到效果）。

由于此跟踪器仅处理 RT 任务，因此我们的运行方式与之前的跟踪器略有不同。我们将在“chrt”下运行“sleep 1”，而不是执行“ls”，这会改变任务的优先级。

# echo 0 > options/function-trace 
# echo wakeup_rt > current_tracer 
# echo 1 > tracing_on 
# echo 0 > tracing_max_latency 
# chrt -f 5 sleep 1 
# echo 0 > tracing_on 
# cat trace 
# tracer: wakeup 
# 
# tracer: wakeup_rt 
# 
# wakeup_rt latency trace v1.1.5 on 3.8.0-test+ 
# -------------------------------------------------------------------- 
# latency: 5 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4) 
#    ----------------- 
#    | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5) 
#    ----------------- 
# 
#                  _------=> CPU#             
#                 / _-----=> irqs-off         
#                | / _----=> need-resched     
#                || / _---=> hardirq/softirq  
#                ||| / _--=> preempt-depth    
#                |||| /     delay              
#  cmd     pid   ||||| time  |   caller       
#     \   /      |||||  \    |   /            
<idle>-0       3d.h4    0us :      0:120:R   + [003]  2389: 94:R sleep 
<idle>-0       3d.h4    1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up 
<idle>-0       3d..3    5us : __schedule <-schedule 
<idle>-0       3d..3    5us :      0:120:R ==> [003]  2389: 94:R sleep

在空闲系统上运行它，我们看到执行任务切换只需要 5 微秒。请注意，由于调度中的跟踪点在实际“switch”之前，我们在记录的任务即将调度时停止跟踪。如果我们在调度程序的末
尾添加一个新标记，这可能会改变。

请注意，记录的任务是 'sleep'，PID 为 2389，它的 rt_prio 为 5。这个优先级是用户空间优先级，而不是内部内核优先级(内核中的优先级是99-5=94)。 SCHED_FIFO 的策略为 1，
SCHED_RR 的策略为 2。

请注意，跟踪数据显示了内部优先级 (99 - rtprio)。

<idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep

0:120:R 表示 idle 任务正在运行，优先级为 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

即使启用了function tracer，trace log 也不大，所以我包含了整个跟踪。

当系统空闲时中断关闭。在调用 task_woken_rt() 之前的某个地方，设置了 NEED_RESCHED 标志，这由第一次出现的 'N' 标志表示。

Latency tracing and events
--------------------------
由于使能 function 跟踪会导致更大的延迟，但如果不了解延迟内发生了什么，就很难知道是什么导致了它。有一个折中，那就是启用事件。

# 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

十五、Hardware Latency Detector

-------------------------------

硬件延迟检测器通过启用“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
这将两个数字显示为“inner latency”和“outer latency”。测试循环运行，检查时间戳两次。在两个时间戳内检测到的延迟是“inner latency”，在循环中前一个时间戳和下一个时间
戳之后检测到的延迟是“outer latency”。

ts:1581527483.343962693
第一个延迟记录在窗口中的绝对时间戳。

count:6
在窗口期间检测到延迟的次数。

nmi-total:7 nmi-count:1
在支持它的体系结构上，如果 NMI 在 test 期间进入，则在 NMI 中花费的时间以“nmi-total”（以微秒为单位）报告。
如果 NMI 在测试期间出现，所有具有 NMI 的架构都会显示“nmi-count”。

hwlat tracer的文件：

tracing_threshold：
这会自动设置为“10”以表示 10 微秒。这是在记录跟踪之前需要检测的延迟阈值。
注意，当 hwlat 跟踪器完成时（另一个跟踪器被写入“current_tracer”），tracing_threshold 的原始值被放回到这个文件中。

hwlat_detector/width：
测试在禁用中断的情况下运行的时间长度。

hwlat_detector/window
测试运行的窗口的时间长度。也就是说，测试将运行每个“窗口”微秒的“宽度”微秒

tracing_cpumask：
测试开始后。创建了一个运行测试的内核线程。该线程将在每个周期（一个“窗口”）之间的 tracking_cpumask 中列出的 CPU 之间交替。要将测试限制在特定 CPU 上，将此文件中
的掩码设置为仅应运行测试的 CPU。

十六、function

--------------

这个追踪器就是function tracer。可以从调试文件系统启用函数跟踪器。确保 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); 
    } 
    [...] 
}

十七、Single thread tracing

---------------------------

通过写入 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; 
       } 
 
       //编译过程中stringfy的#比宏展开还先处理 
       while (fscanf(fp, "%*s %" 
                 STR(MAX_PATH) 
                 "s %99s %*s %*d %*d\n", 
                 tracefs, type) == 2) { 
           if (strcmp(type, "tracefs") == 0) 
                   break; 
       } 
       fclose(fp); 
 
       if (strcmp(type, "tracefs") != 0) { 
           fprintf(stderr, "tracefs not mounted"); 
           return NULL; 
       } 
 
       strcat(tracefs, "/tracing/"); 
       tracefs_found = 1; 
 
       return tracefs; 
} 
 
const char *tracing_file(const char *file_name) 
{ 
       static char trace_file[MAX_PATH+1]; 
       snprintf(trace_file, MAX_PATH, "%s/%s", find_tracefs(), file_name); 
       return trace_file; 
} 
 
int main (int argc, char **argv) 
{ 
    if (argc < 1) 
            exit(-1); 
 
    if (fork() > 0) { 
            int fd, ffd; 
            char line[64]; 
            int s; 
 
            ffd = open(tracing_file("current_tracer"), O_WRONLY); 
            if (ffd < 0) 
                    exit(-1); 
            write(ffd, "nop", 3); 
 
            fd = open(tracing_file("set_ftrace_pid"), O_WRONLY); 
            s = sprintf(line, "%d\n", getpid()); 
            write(fd, line, s); 
 
            write(ffd, "function", 8); 
 
            close(fd); 
            close(ffd); 
 
            execvp(argv[1], argv+1); 
    } 
 
    return 0; 
}

或者这个简单的脚本！

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

十八、function graph tracer

---------------------------

1. 此跟踪器类似于函数跟踪器，不同之处在于它在函数的入口和出口处探测函数。这是通过在每个 task_struct 中使用动态分配的返回地址堆栈来完成的。在函数进入时，跟踪器会覆
盖被跟踪的每个函数的返回地址以设置自定义探测器。因此原始返回地址存储在task_struct中的返回地址堆栈中。

2. 在函数的两端进行探测会导致特殊功能，例如：
- 衡量函数的执行时间
- 有一个可靠的调用栈来绘制函数调用图

3. 此跟踪器在多种情况下很有用：
- 您想找到奇怪的内核行为的原因，并需要查看任何区域（或特定区域）的详细情况。
- 您遇到了奇怪的延迟，但很难找到它的来源。
- 您想快速找到特定函数的调用路径
- 你只想窥视一个正在工作的内核并想看看那里发生了什么。

# 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();

4. 有几个列可以动态启用/禁用。您可以根据需要使用所需的各种选项组合。

(1) 执行函数的 CPU 编号默认启用。有时只跟踪一个 cpu 会更好（请参阅 tracking_cpu_mask 文件），或者您有时可能会在 cpu 跟踪切换时看到无序的函数调用。
- 隐藏：echo nofuncgraph-cpu > trace_options
- 显示：echo funcgraph-cpu > trace_options

(2) 持续时间（函数的执行时间）显示在函数的右括号行上，或者在叶函数的情况下显示在与当前函数相同的行上。它是默认启用的。
- 隐藏：echo nofuncgraph-duration > trace_options
- 显示：echo funcgraph-duration > trace_options

(3) 在达到持续时间阈值的情况下，开销字段在持续时间字段之前。
- 隐藏：echo nofuncgraph-overhead > trace_options
- 显示：echo funcgraph-overhead > trace_options
- 取决于：funcgraph-duration

  ie:: 
 
    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  |  } 
 
Flags:: 
 
  + 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.

(4) task/pid 字段显示执行该函数的线程 cmdline 和 pid。它是默认禁用的。
- 隐藏：echo nofuncgraph-proc > trace_options
- 显示：echo funcgraph-proc > trace_options

  ie:: 
 
    # 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   |                }

(5) 绝对时间字段是系统时钟自启动以来给出的绝对时间戳。每次进入/退出函数时都会给出该时间的快照
- 隐藏：echo nofuncgraph-abstime > trace_options
- 显示：echo funcgraph-abstime > trace_options

  ie:: 
 
    # 
    #      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();

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

(6) 也可以为函数开始就在跟踪缓冲区中的函数启用右括号后的函数名称显示，从而可以更轻松地使用 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() */

您可以使用 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    |             }

您可能会在以下“dynamic ftrace”部分中找到此跟踪器的其他有用功能，例如仅跟踪特定功能或任务。

十九、dynamic ftrace

--------------------

1. 实现原理

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

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

请注意，并非所有部分都被跟踪。它们可能会被 notrace 阻止，或者以其他方式阻止，并且不会跟踪所有内联函数。检查“available_filter_functions”文件以查看可以跟踪哪些函
数。

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

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

当启用跟踪时，修改函数跟踪点的过程取决于体系结构。旧方法是使用 kstop_machine 来防止与正在执行代码的 CPU 发生竞争（这会导致 CPU 做一些不受欢迎的事情，尤其是当修
改的代码跨越缓存（或页面）边界时），并且 nops 被修补回调用 . 但这一次，他们没有调用 mcount（这只是一个函数存根）。他们现在调用 ftrace 基础设施。

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

有些架构甚至不需要在同步上monkey，只需将新代码叠加在旧代码之上，其他 CPU 同时执行它就不会出现任何问题。

记录被跟踪函数的一个特殊副作用是，我们现在可以有选择地选择我们希望跟踪的函数以及我们希望 mcount 调用保留为 nops 的函数。

2. 使用两个文件，一个用于启用和禁用指定功能的跟踪。他们是：
set_ftrace_filter
和
set_ftrace_notrace

3. 您可以添加到这些文件中的可用函数列表列在：available_filter_functions

# cat available_filter_functions 
put_prev_task_idle 
kmem_cache_create 
pick_next_task_rt 
get_online_cpus 
pick_next_task_fair 
mutex_lock 
[...]

4. 如果我只对 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

5. 要查看正在跟踪哪些函数，您可以 cat 文件：
# cat set_ftrace_filter
hrtimer_interrupt
sys_nanosleep

6. 或许这还不够。过滤器还允许 glob(7) 匹配。

``<match>*``：将匹配以 <match> 开头的函数
``*<match>``：将匹配以 <match> 结尾的函数
``*<match>*``：将匹配包含 <match> 的函数
``<match1>*<match2>``：将匹配以 <match1> 开头并以 <match2> 结尾的函数

Note：通配符最好用引号括起来，否则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_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

这是因为 '>' 和 '>>' 的行为就像它们在 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

7. 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: should_remove_suid <-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

我们可以看到不再有 preempt 或 lock 跟踪。

8. 通过索引选择函数过滤器
---------------------

因为字符串的处理开销很大（在与传入的字符串进行比较之前需要查找函数的地址），所以也可以使用索引来启用函数。这在一次设置数千个特定功能的情况下很有用。通过传入数
字列表，不会发生字符串处理。而是选择内部数组中特定位置的函数（对应于“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

9. 带有函数图(function graph)跟踪器的动态 ftrace
---------------------------------------------

尽管上面解释的内容涉及函数跟踪器和函数图跟踪器，但仍有一些特殊功能仅在函数图跟踪器中可用。

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

echo __do_fault > set_graph_function

将产生以下 __do_fault() 的“扩展”跟踪

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

您还可以一次扩展多个功能::

echo sys_open > set_graph_function
echo sys_close >> set_graph_function

现在，如果您想返回去跟踪所有功能，您可以通过以下方式清除此特殊过滤器：

echo > set_graph_function

10. ftrace_enabled
--------------

请注意，proc sysctl ftrace_enable 是 function tracer 的一个大开关。默认情况下它是启用的（在内核中启用function tracer时）。如果禁用，则禁用所有功能跟踪。这不仅
包括 ftrace 的函数跟踪器，还包括任何其他用途（perf、kprobes、堆栈跟踪、分析等）。如果注册了 FTRACE_OPS_FL_PERMANENT 设置的回调，则无法禁用它。

请小心禁用此功能。

这可以禁用（和启用）：

sysctl kernel.ftrace_enabled=0
sysctl kernel.ftrace_enabled=1
或：
echo 0 > /proc/sys/kernel/ftrace_enabled
echo 1 > /proc/sys/kernel/ftrace_enabled

11. 过滤命令
---------------

set_ftrace_filter 接口支持一些命令。跟踪命令具有以下格式：

支持以下命令：

(1) 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

(2) traceon/traceoff

当指定的函数被命中时，这些命令打开和关闭跟踪。该参数决定了跟踪系统开启和关闭的次数。如果未指定，则没有限制。例如，要在前 5 次 __schedule_bug 时禁用跟踪，请运行：

echo '__schedule_bug:traceoff:5' > set_ftrace_filter

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

echo '__schedule_bug:traceoff' > set_ftrace_filter

这些命令无论是否附加到 set_ftrace_filter 都是累积的。要删除命令，请在其前面加上 '!' 并删除参数::

echo '!__schedule_bug:traceoff:0' > set_ftrace_filter

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

echo '!__schedule_bug:traceoff' > set_ftrace_filter

(3) 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

(4) enable_event/disable_event:

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

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

格式是：

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

删除事件命令：

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

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

(6) cpudump:
当该函数被命中时，它会将当前 CPU 的 ftrace 环形缓冲区的内容转储到控制台。与“dump”命令不同，它只为执行触发转储的函数的 CPU 打印出其环形缓冲区的内容。

(7) stacktrace:
当函数被命中时，会记录堆栈跟踪。

12. trace_pipe
-------------
trace_pipe 输出与trace 文件相同的内容，但对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
文件没有这个限制。

13. trace entries
-------------

在诊断内核中的问题时，拥有过多或不足的数据可能会很麻烦。文件 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: 写错误：无法分配内存
# cat buffer_size_kb
85

per_cpu 缓冲区也可以单独更改：

# echo 10000 > per_cpu/cpu0/buffer_size_kb
# echo 100 > per_cpu/cpu1/buffer_size_kb

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

# cat buffer_size_kb
X

这是 buffer_total_size_kb 有用的地方：

# cat buffer_total_size_kb
12916

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

14. Snapshot
-----------

CONFIG_TRACER_SNAPSHOT 使通用快照功能可用于所有non latency tracers.。（记录最大延迟的延迟跟踪器，例如“irqsoff”或“wakeup”，不能使用此功能，因为它们已经在内部使用
快照机制。）

快照在特定时间点保留当前跟踪缓冲区，而不会停止跟踪。 Ftrace 将当前缓冲区与备用缓冲区交换，并在新的当前（=前一个备用）缓冲区中继续跟踪。

“tracing”中的以下tracefs文件与此功能相关：

snapshot:

这用于拍摄快照并读取输出缓冲区并拍摄快照（交换），然后以与“trace”相同的格式从此文件中读取快照（在上面的“文件系统”部分中进行了描述） . 读取快照和跟踪都可以并行执
行。分配备用缓冲区时，echo 0 将释放它，并echo其他（正）值清除快照内容。下表显示了更多详细信息。

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

这是使用快照功能的示例:

  # 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

二十、Instances

---------------

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

  # mkdir instances/foo 
  # ls instances/foo 
  buffer_size_kb  buffer_total_size_kb  events  free_buffer  per_cpu 
  set_event  snapshot  trace  trace_clock  trace_marker  trace_options 
  trace_pipe  tracing_on

如您所见，新目录看起来类似于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 实例显示唤醒和任务切换。I: 也就是说可以同时运行多个跟踪器或其实例，这样就允许各个模块(同时)抓自己的trace而互相不干扰。

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

  # rmdir instances/foo 
  # rmdir instances/bar 
  # rmdir instances/zoot

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

二十一、Stack trace

-------------------

由于内核有一个固定大小的堆栈，重要的是不要在函数中浪费它。内核开发人员必须对他们在堆栈上分配的内容保持良心。如果它们添加太多，系统可能会面临堆栈溢出的危险，并
且会发生损坏，通常会导致系统崩溃。

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

CONFIG_STACK_TRACER 启用 ftrace 堆栈跟踪功能。要启用它，请将“1”写入 /proc/sys/kernel/stack_tracer_enabled。

# echo 1 > /proc/sys/kernel/stack_tracer_enabled

可以将 “stacktrace”添加到内核命令行参数中来使能它跟踪内核启动期间堆栈的使用情况。

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

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

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

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

更多的
----
更多细节可以在源代码中找到，在`kernel/trace/*.c` 文件中。

本文参考链接：https://www.cnblogs.com/hellokitty2/p/15624976.html