在 Linux 系统中查找延迟来源¶
标题：Finding Sources of Latency on your Linux System
日期：2020/09/11
作者：Steven Rostedt
链接：https://www.youtube.com/watch?v=Tkra8g0gXAU
注意：此为 AI 翻译生成 的中文转录稿，详细说明请参阅仓库中的 README 文件。
大家好，我是 Steve Rostedt。我是 VMware 的一名开源工程师。我也是 Linux 内核开发者，并且是 Linux 内核中跟踪子系统（即 Ftrace）的维护者。我也是稳定实时树（stable real-time tree）的维护者。今天，我将讨论如何在您的 Linux 系统上查找延迟的来源。那么，我们开始吧。再次说明一下，我是 VMware 的员工，如果您想了解更多关于我们的信息，可以在 Twitter 上查看 @vmw.opensource，以及在 VMware.com 和开源博客上查看我们。
首先，我要问的是，什么是延迟？既然我要谈论查找延迟的来源，让我们先给它一个定义。如果您在维基百科上查找，它会告诉您延迟是“刺激与末端响应之间的时间间隔”，或者从更一般的角度来看，是“所观察系统中某个物理变化的原因与其效应之间的时间延迟”。好吧。可能很多人还在挠头，想知道延迟的确切定义到底是什么。所以简单来说，我将其简单地称为“事件预期发生的时间与实际发生的时间之间的间隔”。举个简单的例子：每天早上您醒来时，比如说闹钟响了，这很烦人，但那是您预期醒来的时间。然后，到您按下闹钟的时间，那就是您实际醒来的时间。我想把这个称为“唤醒延迟”。
那么，延迟从何而来？现在，如果您看一下您的系统，您会看到您的应用程序在顶层。在它下面，您的应用程序很可能与某个库（library）通信。然后该库将与内核通信，而内核将与其通信的是实际的硬盘驱动器（或者不仅仅是硬盘驱动器，而是您的硬件、您的处理器）来获取资源。库有办法绕过内核，甚至应用程序也可以绕过库直接访问内核和/或硬件。但我们今天不会深入讨论这些细节。另外，我要说的是，我们现在要做的是关注发生在内核和硬件中的延迟。您会看到那里有一个小黑框，BIOS（基本输入输出系统），它本质上是您计算机上的固件。我基本上认为它是硬件的一部分。
那么，让我们看看硬件延迟。它来自哪里？很多时候，您会遇到一种叫做系统管理中断（System Management Interrupt, SMI）的东西。这就是固件作为硬件一部分发挥作用的地方。假设您有一台笔记本电脑，您的笔记本电脑需要温控。它非常小巧，里面的所有组件都非常非常小。您需要确保它保持凉爽，但又不希望风扇一直运行。因此，有很多复杂的逻辑来确保一切正常运行。您不能依赖操作系统来正确处理这个，因为每台笔记本电脑都是独特的。这就是 BIOS（固件）的作用，它有一种方法来管理如何让您的笔记本电脑保持凉爽，无论上面运行的是什么操作系统。它通常会触发一种叫做系统管理中断（SMI）的东西。它会将系统切换到系统管理模式（System Management Mode, SMM），这基本上对操作系统是隐藏的。操作系统无法控制这个。这时它可能会检查，比如“好吧，我们开始热了，得打开风扇”，或者“一切正常，我们可以放慢风扇速度”，或者“也许我们会改变 CPU 的频率”。嗯，这项工作就是您系统中的一个延迟。如果您真正关心实时性能，您必须意识到这类变化。
硬件可能做的其他事情是：每次发生缓存未命中，无论是指令缓存未命中还是数据缓存未命中，都可能导致延迟；还有分支预测。基本上，它可能导致非确定性行为。顺便说一下，分支预测是指当您的代码中有 if 语句时，为了确保 CPU 运行得非常非常快，它会预先查看很远。当它看到一个分支时，它必须决定走哪条路。基于之前该分支被执行的历史，它会说，“好吧，大多数时候它走的是 true 路径，所以我将遵循 true 路径”。这样，当 CPU 运行到那个点时，所有内存都已经在缓存中准备好，这会让事情快得多。但如果分支预测错误或被刷新，它就必须在那一点停下来，然后重新拉取内存才能继续。
超线程，当您在一个核心上有多个线程时。超线程是指一个 CPU 核心实际上模拟两个逻辑 CPU。当一个逻辑 CPU 在执行某种任务，另一个逻辑 CPU 在执行其他任务时，它实际上是在切换工作。当一个在获取内存时，另一个在做一些 CPU 处理，如此往复。但这实际上意味着所有资源都是共享的。因此，取决于另一个线程在做什么，它可能会影响您的延迟。
最后，还有缺页异常和后备缓冲区（look-aside buffers）的问题。发生的情况是，当您执行某些东西时，除非您执行了 mlockall（它会将所有可执行内容拉入内存，然后您实际上执行了 mLock all，它会根据系统的工作方式将所有可执行文件拉入内存），否则您的系统工作方式是这样的：当您启动浏览器时，它并不会把所有内容都拉入内存运行。它实际上只执行该代码的一部分。如果该可执行文件的对应部分不在内存中，就会发生缺页异常，内核会将该文件拉入内存，然后继续执行。这当然会导致延迟。
那么我们有什么工具来检测硬件的延迟呢？好吧，如果您查看您的内核配置，您会看到一个叫做 CONFIG_HWLAT_TRACER 的选项。它实际上在 Fedora 31 系统上是可用的。我检查了我的一个系统（Fedora 31），它实际上启用了 HWLAT_TRACER，因为当它关闭时，它完全不会造成任何开销。只有当您启用它进行跟踪时，它才会增加开销。但我也注意到我的 Debian 系统没有启用它。我不知道为什么，因为这是一个查看硬件延迟来源的有用功能，而且关闭时不会造成任何开销。
那么它是做什么的呢？它在禁用中断的情况下运行一个非常非常紧凑的循环，并在获取时间戳时检查是否有任何间隔。它会在一个时间窗口内运行一段宽度为微秒级别的循环。默认情况下，宽度是 500,000 微秒（即半秒），窗口是 1,000,000 微秒（即一秒）。所以基本上，它在您的系统上每秒运行半秒的这个紧凑循环。您可以通过查看 /sys/kernel/tracing/hwlat_detector/ 目录来确定或更改宽度和窗口参数。那里有两个文件，width 和 window，用于修改这些参数。
一旦完成一个窗口的检测，它实际上会从一个 CPU 弹到下一个 CPU，再到下一个 CPU。所以它在一个 CPU 上完成这些窗口检测，然后移动到下一个 CPU 做同样的事情，再移动到下一个 CPU。您可以通过跟踪 CPU 掩码（tracing CPU mask）来确定它在哪些 CPU 上运行。
此外，它只会在检测到超过某个阈值的东西时才进行跟踪。所以有一个叫做 tracing_thresh 的文件您可以设置。默认是 10 微秒。任何大于 10 微秒的间隔都会被记录。否则，它可能会记录很多内容。如果您设置为 1 微秒，一个缓存未命中或其他什么，比如分支预测错误，如果您在寻找这些，您可能会看到更多的命中。但通常 10 微秒是合适的设置。
那么如何访问这个呢？如果您的内核启用了这个功能，您首先要做的是挂载 /sys/kernel/tracing 目录。如果启用了跟踪目录，在 /sys/kernel 目录下就会有 tracing 目录。您不需要创建它。如果您的内核配置了它，它就会一直存在。然后我们要做的是使用该选项挂载它。为了简化大多数命令的路径，我通常 cd 到那个 tracing 目录里。
然后，例如，我首先 cat 查看 hwlat_detector/width 文件是什么，您会看到它是 500,000。所以我打算大胆地将这个数字从 500,000 改为 900,000。基本上，我希望这个东西每秒运行十分之九秒。但是记住，它一次只在一个 CPU 上运行，所以其实没那么糟糕。
接着，如果您注意到，我 cat 查看 tracing_thresh 文件，它是 10，所以它会记录超过这个阈值的间隔。然后我运行它，我执行了这个操作，让它休眠了 100（秒？），然后我 cat trace 文件（显示跟踪信息的文件）。
您首先会看到的是，我想强调的是在跟踪信息里面，有这个我们称为“延迟字段”（latency field）的东西，它告诉您中断是启用还是禁用的。在这个例子中，您会注意到它们都是禁用的。顺便说一下，您会注意到箭头（IRQs off）的偏移，它们实际上没有正确地对齐到 D。那个 D 应该在 IRQs off 的正下方。发生这种情况是因为这段代码最初编写时，进程 ID 不超过 64K（或者不，抱歉，是 16K）个元素。正如您所见，有 211,000 个进程。所以基本上进程 ID 不能超过（也许是 64K？我记不清了，但当时小得多）。现在我们允许更大的进程 ID 数量，导致进程 ID 比代码最初编写时预期的要大，它把一切都偏移了，标题就对不齐了。所以忽略那个，忽略那个偏移中的小错位。
但重要的是，D 表示中断已禁用（IRQs off）。当 D 被设置时，意味着发生该跟踪点时中断是禁用的。如果是一个点 .，则意味着它是启用的。由于我们是在中断禁用的情况下做所有这些事情，所以应该都是 D。
接下来是进程是否应该被调度，如果需要调度您会看到一个 N；是否在硬中断或软中断中运行（这里不是）；以及抢占深度（preemption depth），我稍后会讲到。
然后是延迟时间戳（delays timestamp），这是跟踪器记录的时间戳。跟踪器实际上有一个时间戳，每次记录时，您可以在那个 tracefs 目录（/sys/kernel/tracing 目录）里修改这个时间戳。您会看到一个 trace_clock 文件，您可以修改使用哪个时钟。这就是它使用的时钟。
下一个有点用词不当。它写着“函数”（function），那是因为跟踪最初是为函数跟踪器（function tracer）编写的，而且这不仅仅是有点用词不当。它最初是为函数跟踪器编写的，之后还编写了许多其他跟踪器，但我们没有更新标题。所以它写着“函数”，但实际上是指无论跟踪器在做什么。在这里，您会看到一、二、三，对于硬件延迟跟踪器，我们会在“函数”字段下面放一个 1、2、3 来表示每个“检测点”（inspiration？可能指检测到的延迟事件）。所以您能看到命中了多少次，特别是如果溢出了，您就知道它在哪个位置。
接下来是内部循环。稍后我会在另一张幻灯片中更详细地解释一下。但内部循环是它获取时间戳的地方。您会注意到每个数字，它要么是零，要么内部或外部循环通常必须大于 10，因为阈值是 10，除非看到大于 10 的东西，否则它不会记录任何东西。但您会看到 14 和 15。14 表示它在内部循环中发现了延迟。15 表示它在外部循环中发现了延迟。我稍后会再讨论这个。
这里的时间戳，您会注意到这个时间戳与跟踪器使用的时间戳有点不同。这是一个内核内部的时间戳，基本上让您知道它是什么时候发生的。这实际上是它找到的第一个实例发生时记录的时间戳。所以它更准确一些，但不幸的是它与跟踪时间戳不匹配。
最后是计数。这里的 42 表示它在那个循环中找到了 42 个大于 10 微秒的实例。记住，这是在窗口完成后才输出的。所以跟踪只会在窗口完成后发生。因此，间隔应该不超过一秒，因为我在一百万微秒（1秒）的窗口内运行了九十万微秒（0.9秒）。然后在最后，它给我这个报告，显示在内部和外部循环中，它在内部找到的最大值是多少，在外部找到的最大值是多少。现在计数说它在这两者之间找到了 42 个延迟大于 10 微秒的实例。
这张图向您展示了这是如何完成的以及为什么有内部和外部循环。我们做的第一件事是将上次的 T2 计数器重置为零。然后我们连续获取两个时间戳。我们获取时间，获取时间，放入变量 T1 和 T2。然后我们检查，嘿，T2 有没有… 如果 T2 没有任何值，或者 T2 是零，或者上次 T2 是零，它就往下走进行比较。您会看到它进行比较，好吧，这两个时间戳 T1 和 T2 之间的差值是多少，实际上是 T2 减去 T1。这给出了增量（delta）。如果它大于上次找到的值，它将保存该记录。并且如果这个差值在整个循环的最后大于 10 或者跟踪阈值，那么它就会记录到跟踪缓冲区。
外部循环记录整个计算过程，因为当我们最初这样做时，我们只做了 T1、T2，结果漏掉了许多延迟。我们曾经有一台机器，每 11 分钟发生一次 SMI，持续 200 微秒，但直到我们添加了这个外部循环才被发现，因为它发生时，恰好在我们计算差值的时候发生。所以在这个窗口期间，我们希望确保捕获窗口内的一切。因此我们实际上同时查看内部和外部循环的计算结果，并且因为外部循环实际上要做的工作多一点，这就是为什么我们对它们进行不同的记录。我们记录内部循环是因为两次时间戳之间没有发生任何事情。它们就是紧挨着的两个时间戳。另一个（外部循环的差值）可能会受到分支预测和缓存未命中等因素的影响。所以它有更大的余地。因此我们想知道，我们想区分它是在内部循环还是外部循环中被发现的。
好了，关于您可以在硬件中找到的硬件延迟就讲这么多。那么内核呢？嗯，内核方面我们有中断延迟和中断本身。关于中断延迟有几点。一是中断可以中断您的进程所造成的延迟。所以您的进程想要运行，却被中断抢占（preempted）了。这是您进程的延迟。还有当中断被禁用时，我们希望中断能尽快到来。所以我们有一个延迟。当发生中断时，通常意味着某个设备想做某事。如果我们有一个键盘，我们敲击按键，或者我们正在进行网络通信，我们希望这样。当一个网络数据包进来时，我们希望立即处理它。但如果中断处理程序（interrupt handler）无法处理那个网络数据包，那就是一个延迟，也就是延迟本身。所以它们都是中断延迟，但含义不同。
我们有 IO 延迟。所以当您从设备读写时，这是您喜欢测量的东西，比如写入设备的速度有多快。这是我们确实喜欢测量的延迟。此外，内核有一堆必须完成的维护任务。如果您的进程不知道内核正在做什么来确保您的系统运行良好平稳，那么它就无法做到这一点。
但首先，我们来谈谈中断延迟。那么什么是中断？简单地说，这是我很久以前画的一个小剪贴画。如果您的进程不知道内核正在做什么来确保您的系统运行良好平稳，它可能会抢占您的进程，内核做一些事情确保系统运行良好，但它也许可以再等一会儿或在不同的 CPU 上运行。所以您需要意识到所有这些。但首先，我们来谈谈中断延迟。那么什么是中断？简单地说，这是我很久以前画的另一个小剪贴画。
您的 CPU 基本上在反复运行，执行您的处理。但如果您开始敲键盘、移动鼠标或者一个网络数据包进来，必须有办法告诉 CPU：停下你正在做的事，处理这个外部进程或这个刺激物，这个外部刺激物，你必须现在就处理它。所以 CPU 对此一无所知，除非它被中断（interrupted）。因此中断基本上就是让这些设备停止 CPU 正在做的事情并说“嘿，你需要处理这个”的一种方式。
但有些情况下，CPU 正在做的事情不能被停止。它必须继续，不能被外部设备抢占。在这种情况下，我们就有所谓的禁用中断。就这样想：它只是说“我要忽略所有人，继续前进”。
那么看看中断造成的延迟。您的程序正在运行，一个设备触发了一个中断，然后您的中断处理程序运行并返回。所以您在这里看到的这个间隔，那就是您的延迟。来自中断的延迟是可以在您的程序中测量到的，因为它（您的程序）没有在运行，它正在处理某个进程。
但是，从设备触发到中断处理开始，我们看到的这个延迟呢？为什么它没有完美地对齐上下？嗯，这就是我称之为中断延迟的地方，因为中断可能被禁用了。那里的整个延迟，这确实是我所说的完全中断延迟（full interrupt latency），当您担心设备的响应时间时，就是这个。
所以当设备触发时，有时如果一个程序在等待设备，设备中断进来，它调用中断处理程序，处理程序处理设备，然后它返回并将该信息从设备传递给您的程序。那个时间您可能也想测量，因为那是完全中断延迟。
在我继续之前，我想谈谈，就像我说的，我是 Ftrace 的维护者，它是 Linux 内核的官方跟踪器。还有所谓的 trace-cmd，或者我喜欢称之为 trace command（跟踪命令）。现在，如果您在幻灯片上看到，它写着 https://trace-cmd.org。记住这个，因为下面有链接。Trace command 安装在几个发行版上，Debian、Fedora，它们似乎都有。但如果您想要最新最好的版本，因为我正在积极开发中，最近没有发布完整的官方新版本，您最好获取源代码以获得大部分功能。所以去那里获取它。
从现在开始，在本次演讲的剩余部分，我将主要使用 trace command 来与延迟跟踪器交互。
测量来自中断的延迟。所以如果您想测量，比如说，中断处理程序延迟对您造成的影响，您可以运行这个相当漂亮的命令：trace-cmd record，意思是我要记录到一个文件。-P 指定您想要的跟踪器。是的，-P 有点用词不当。您可能会说为什么不是 -T，但 -T 已经被占用了。当我最初写 Ftrace 时，我们称它们为插件（plugins），而不是跟踪器，但现在插件有了不同的含义。所以请记住 -P 代表您的跟踪器。-L 用于限制函数图跟踪器只跟踪 irq 和任何以 _interrupt 结尾的内容，因为那些是您的中断处理程序。最终我还想启用 irq_handler_entry 事件。
现在，-e 是用于一个实际的事件，它是内核中的一个静态跟踪点（。Linux 内核中有超过一千个这样的事件遍布各处。您可以用 trace-cmd list -e 找到它们。它会列出所有可用的事件。很多看起来很有趣。irq_handler_entry 意味着每次设备中断发生时（不是定时器中断），那些带下划线的中断通常是内核中断，而 do_IRQ 是设备中断。当设备中断进来时，您可以通过 irq_handler_entry 事件看到是哪个设备。
当我做了记录之后，运行了一会儿，然后做了报告，-l 会给我延迟信息。记得我告诉过您关于 D...1 的信息？您会看到那里有三个 D...1。第一个数字是它发生在哪个 CPU 上。因为我不想看到一堆混合交错的 CPU（如果我直接运行 trace-cmd report，它会显示每个 CPU，变得很乱，也不利于截图），所以我只指定了 --cpu 3，这会告诉 trace-cmd report 只显示数据文件中 CPU 3 的信息。这就是我得到的结果。您会注意到这里的小部分。这就是中断延迟发生的地方，您可以看到中断花了多长时间。
现在，您会注意到有一些相当大的延迟，比如那个 98。嗯，首先，您看到名为 irq_handler_entry 的跟踪事件，那是给我的网络设备的。所以 em1 是我的网络设备，它在中断号 26 上。正如您从那里看到的，我用蓝色高亮显示了名称。所以我知道 do_IRQ 来自我的网络设备。在底部，您会注意到处理该设备花了 98 微秒。这相当长。您知道，98 微秒是一个相当大的延迟。24 也算长的，那是另一个网络设备。请注意，这不是实时内核（real time kernel）。这实际上只是我下载的最新（我想是 Linus 的树）并编译的，启用了一堆东西。我有一些其他东西会延迟事情，我在这个内核上运行了这个测试。
那么，如果我用真正的实时内核做这个会怎样呢？嗯，这是我在 5.4.14-rt7 内核上尝试同样的事情。我得到的是这个输出。现在您会注意到那里有一个相当大的间隙。那个 19 微秒仍然算长的。我不会告诉您为什么实时内核在处理中断处理程序方面比普通内核更好。我之前做过几次关于这个的演讲。查一下。您会找到它们，我以后可能还会做更多演讲。但这超出了本次范围。这仅仅是让您知道，对于实时内核，它的表现比普通的香草内核好得多。顺便说一下，我演讲的其余部分，这次演讲，我是在增长中的内核（grow kernel？可能是口误，指某个内核）上运行的。
那么，来自中断的延迟。记得我谈到的这部分，即从设备触发到中断能够发生之间的延迟。我还说过，这发生在我们禁用中断的时候。所以让我们看看如何测量这个。
另一个有趣的事情我们想看看，不仅仅是禁用中断，因为很多时候当中断被禁用时，我们还担心能否被调度。内核还有另一种方式：它可以保持中断启用，但也可以禁用抢占，这样中断可以进来，处理程序可以工作，但内核不会让 CPU 调度另一个进程。所以如果一个进程正在运行，一个低优先级进程正在运行并且它禁用了抢占，然后一个高优先级进程进来了，中断发生了，内核说“嘿，这家伙需要运行”，那么内核会回来说“不行，这里抢占被禁用了，你必须等待”。这是来自内核的另一种形式的延迟。
抢占禁用发生在中断被禁用的时候，因为您无法通知任务停止。所以它就包含在其中了。当您禁用中断时，您基本上也禁用了抢占，因为 CPU 不知道要切换。
自旋锁，当您获取一个自旋锁时，内核必须禁用抢占，因为自旋锁意味着，当您持有一个锁时，如果另一个任务进来试图获取同一个锁，它会自旋，它不会等待。它不会去睡眠，也不会等待。它只会自旋，希望锁很快被释放。如果您让持有自旋锁的任务被调度出去，它可能会导致死锁，因为它可能被调度回那个正在自旋等待的家伙身上。所以您不能让任何持有自旋锁的任务被抢占。
另外，在内核上可以做的一个优化是当您访问每 CPU 数据时。因为如果所有… 如果您不关心其他 CPU，因为当您访问您 CPU 上的数据时，另一个 CPU 上的进程不会访问它，但您担心被调度出去再调度进来，因为如果您被调度出去，另一个进程进来，它现在就会访问相同的每 CPU 数据。所以有时为了处理这个，如果您不担心这个数据是否被中断处理（或者不被中断接触），您就没问题。但如果您有每 CPU 数据，您可以简单地关闭抢占，修改您的每 CPU 数据，然后启用抢占，基本上这就是您非常快速的锁。这是我们有抢占禁用的另一个原因。
现在我们有了延迟跟踪器。正如您已经看到的，有硬件延迟跟踪器（HWLAT Latency Tracer）。现在我要谈谈我们拥有的另外几个延迟跟踪器：中断关闭延迟跟踪器，它基本上跟踪所有中断被禁用的时间；抢占关闭延迟跟踪器（preempt off latency tracer），它只查看抢占被禁用的情况。但我最喜欢的是抢占和中断关闭延迟跟踪器，这是我使用的那个。我其实不太… 另外两个对我来说更学术化。嗯，irqs off 如果您只担心设备进来是有用的，但 preempt off 有点… 它不测量中断关闭，所以如果您只担心设备进来，它就没那么有用。它更学术化。但 irqs off，抢占和中断关闭跟踪器很好，因为它会查看中断被禁用和抢占被禁用作为一个整体的整个时间。所以这确实是如果您有一个高优先级任务想做某事时，您会拥有的真正调度延迟。
不，这些在生产内核中都没有配置，因为即使它们被关闭，它们也确实有开销。所以您看不到它们被启用，但它们通常在调试内核（debug kernel）中。有它们很好。
还有跟踪事件。记得我告诉过您那些内核中的静态跟踪点吗？也有 preempt 和 irq 的禁用、启用事件，但因为它们需要在这些地方加上包装器（wrappers），它们也会在启用时造成一点开销，所以您在生产内核上也看不到它们被启用。
所以如果您去打开您的 make menuconfig，进入内核调试（Kernel hacking）-> 跟踪器（Tracers）菜单，现在 make menuconfig 是指当我进入 Linux 源代码并想修改配置时，有一个基于 NCURSES 的方式来修改这些配置。您会看到，您可以找到这些跟踪器在哪里启用和禁用。就像我说的，如果您进入内核调试菜单，然后是跟踪器菜单，您会看到这个菜单，在那个红框里您会注意到，您有… 它从抢占启用和禁用跟踪点开始，您会看到它们是关闭的，因为这是生产内核，这更多是为生产内核准备的。您有中断延迟跟踪和抢占关闭延迟跟踪器。您可能会问，嗯，抢占和中断关闭延迟跟踪器在哪里？嗯，如果您启用了中断跟踪器和抢占跟踪器，它会自动启用。如果您同时启用了它们，抢占和中断关闭跟踪器也会启用。不言而喻，但您会注意到那里，我还有另一个跟踪器，调度延迟跟踪器（scheduling latency tracer），这实际上是您即使在生产系统上也应该启用的东西。
那么，用同样的抢占和中断关闭来跟踪中断的延迟。现在我要做的是启动，我们将使用 trace-cmd start。它不是 trace-cmd record。trace-cmd start 只是启用跟踪，不记录到文件。而延迟跟踪器只显示最大值，所以您不需要真正做记录。所以您这样做：您启用 -P preemptirqsoff。然后我注意到我启用了一个选项 sim-offset。嗯，我为什么这样做？因为如果您注意到下面蓝色语句那里，它有函数的偏移量。所以当它跟踪函数时（因为它启用了函数跟踪器），我也喜欢知道事件发生在函数内部的哪个位置，而不仅仅是函数名。如果您去掉那个选项，您就看不到那些函数内部偏移量的扩展信息了。
最后，我想限制这个函数。当您启用延迟跟踪器时，它会启用完整的函数跟踪。如果您跟踪所有函数，当您跟踪内核中的每一个函数时，会造成相当大的开销。所以我喜欢将其限制在，比如说，中断和自旋锁。这是您看到的输出。在最末尾，您会看到有一个所有东西的堆栈跟踪（stack trace）。里面有些垃圾。我不太确定为什么，但您可以忽略它。但它某种程度上让您知道事情发生在哪里。
那么，接下来我想谈的是调度延迟跟踪器。当您不启用它时，它没有开销。它基本上完全构建在跟踪事件之上。所以如果您的内核启用了跟踪事件，不妨也启用这个，因为它有效。我有点沮丧，因为我并不总是在生产内核或生产系统上看到这个被启用，因为它确实… 除非您担心大小，因为它确实占用内存，它确实有内存占用。但在速度方面，如果您担心性能，请启用它。有它很好。
当您启用它时，您有三种类型的跟踪事件：唤醒跟踪器、唤醒 RT和唤醒 DL（wakeup DL，即截止期限跟踪器 deadline tracer）。它们之间的区别是：wakeup 查看任何进程，无论是实时的、截止期限的等等。但是，您知道，其中一些进程，因为它寻找最高优先级进程，但因为，您知道，它们不是 FIFO，像一个实时任务会一直运行直到被抢占。这家伙可能一直运行直到，嘿，它可能只是用完时间片（run out of time）。然后它会启动下一个任务。然后您会在 wakeup 中看到这些巨大的间隙，掩盖了实时和截止期限任务，因为 wakeup 会跟踪非实时任务，这些任务总是比另外两个有更大的跟踪，更大的延迟。如果您在寻找另外两种，您永远看不到它们，因为它只记录最大延迟。这就是为什么我们有 wakeup RT，因为 RT 会忽略任何不是实时任务的东西，只跟踪具有最高优先级的实时任务。这为您提供了实时任务调度延迟的更好视图。截止期限调度器出于同样的原因也是如此。
所以如果我在抢占卡（preempt card？可能指支持抢占的内核）上用 wakeup RT 运行，这就是您得到的。现在您唯一会注意到的是，我选择了 wakeup RT 调度器。其他一切保持不变，只是我还添加了 sched_switch 和 sched_waking 跟踪事件。
现在，sched_switch 是当一个进程被调度出去而另一个进程被调度进来时发生的跟踪事件。sched_waking 是当该进程实际被唤醒时。所以如果您的进程正在睡眠，等待一个事件，当那个事件进来时，必须有东西唤醒它，当它被唤醒时，sched_waking 会跟踪那个动作。
它与其他 IRQs off 跟踪非常相似。那么延迟跟踪器有什么问题呢？您拥有的延迟跟踪器，首先，它们是僵化的，不够灵活。您能做的不多。您启用和禁用它们，它们给您最大值。就像我说的，它总是记录最高优先级任务或所有任务。您不能说“我只是对这个特定任务好奇。我想看这个单一任务的延迟”，因为很难告诉这些延迟跟踪器去记录那个。而且它只记录最大延迟。我想知道的是所有延迟，无论是不是最大的，平均值，直方图？而且它专门针对 IRQ 禁用、抢占禁用或唤醒延迟。您只有这些。您不能做其他类型的延迟，比如 IO 延迟或任何其他延迟。
所以我想谈谈直方图触发器（histogram triggers）和合成事件（synthetic events）。接下来。这是您可以自定义选择事件的地方。这就是那些抢占和 IRQ 启用禁用事件派上用场的地方，用于这里的合成事件和直方图。您可以添加过滤器。您可以说，我只想跟踪特定进程。我不关心任何其他进程。我想查看单个进程的延迟。它给您一个很好的所有内容的直方图。
那么我们如何创建它呢？首先，您必须挂载 tracefs 文件系统，我之前提到过，如果它还没有被挂载的话。顺便说一下，如果您运行 trace-cmd，它会自动为您挂载。然后您要做的是，我创建一个合成事件（synthetic event）。就在这里，我 echo 我想要创建的事件名称。这将有两个参数。一个将是类型为进程 ID。另一个将是 u64 因为它将是一个时间戳。时间戳总是 u64。然后我命名第一个，第一个将是我要跟踪的进程 ID，以及延迟。
从这里开始，制作直方图。所以我运行 trace-cmd start 和 -e，意思是我要启用 irq_disable 跟踪事件。我之前提到过这些。您必须在配置中启用它们。它们不在生产系统上。-R 表示触发器。所以我给这个添加一个触发器。然后我添加我的直方图，我的键（keys）等等。我会稍微多谈一点这个。
我们开始。首先我映射两个事件。我有禁用事件和启用事件会在它之后立即发生。我想确保这两个事件前后发生。我如何将这两个事件映射在一起？因为我知道当它们发生时，它们总是在同一个 CPU 上，因为中断被禁用时不能被抢占。所以启用必须在同一个 CPU 上。我将使我的键（keys）匹配两者，即 CPU。然后我要记录时间戳并加载到这个名为 ts0 的变量中。并且我只想在公共 PID（common PID）大于零时进行跟踪。所有事件都有公共 PID。这就是为什么它叫公共的。所有事件的进程 ID，但空闲事件的 PID 大于零？空闲事件的进程 ID 是零。我不想跟踪空闲事件的原因是它会被调度出去，并且在中断禁用的情况下，它将能够跟踪空闲事件？然后我要记录时间戳并加载到这个名为 ts0 的变量中。我不想跟踪空闲事件的原因是它会被调度出去，在中断禁用的情况下，然后又被调度回来。那会搞乱这个跟踪。所以我只想忽略空闲事件。我只关心进程。我实际上可以针对特定事件设置过滤器，而不是这个。我说如果公共 PID 等于我关心的某个进程 ID。
从这里开始，记得我创建的那个合成事件吗？嗯，我要填充它。接下来是… 我在这里要做的是查看… 这是 irq_lat。嗯，这个实际上… 我应该叫它 irq_lat。我们就叫它 lat。lat 等于公共时间戳（common timestamp）usec 减去 ts0。嗯，那个 ts0 是从 irq_disable 事件保存的时间戳。现在在 irq_enable 事件上，我想获取当前时间戳，减去 irq_disable 的时间戳，这将给我增量（delta）或延迟。我把它存储在 irq_lat 变量里。
然后如果您注意到，所有以美元符号 $ 开头的东西，所有以美元符号开头的东西都是您可以在跟踪中使用的变量。然后 onmatch 是告诉 irq_enable 跟踪事件的方式，说我想匹配 irq_disable 跟踪事件来执行这个。注意我有 preempt_irq.irq_disable。要放置 onmatch，您必须知道 irq_disable 的系统名称。所有事件都按系统分组，irq_enable 和 disable 都属于 preempt_irq 系统名称下。所以您必须输入完整的系统名称才能使这个工作。
最终，现在 trace，这是我说 trace 表示触发或基本上执行我创建的合成事件，带着 irq_lat 和两个参数（PID 和 IRQ 延迟）到那个事件。
最后，在这个 trace-cmd start 中，我想跟踪我刚创建的那个事件，那个合成事件。所以我要跟踪 irq_latency，并且我要创建另一个直方图来为它制作直方图。所以它不仅会出现在环形缓冲区（ring buffer）中（您可以在跟踪发生时看到它），它也会为其创建直方图。
现在，如果我查看那个直方图，您会看到它是这样的，这相当不错，因为我可以看到在这次运行期间，中断被禁用的最大延迟是 21 微秒，因为我在那里放了 .usec。默认情况下，公共时间戳（common timestamp）是纳秒，加上 .usec 就是微秒。所以最大延迟是 21 微秒。发生了一次。大多数时候都很好，像 2、3、4 微秒，这对于 IRQ 关闭来说相当不错。不算长。
现在，让我们对唤醒延迟做同样的事情。就像我说的，您可以比其他东西灵活得多，但现在让我们为唤醒延迟做完全相同的事情。您会注意到现在我 echo wakeup_lat 而不是之前的那个。并且我放入了 prio。所以我仍然有进程 ID 和延迟，但我也关心唤醒延迟发生在什么优先级，因为我想记录所有内容并做这个。所以我在这里做了和之前一样的事情。基本上是相同类型的格式。我运行跟踪，您会看到现在内核内部的优先级实际上是反的。内核中优先级数字越高，实际优先级越低。所以当您看到像 99 或 98 的优先级时，那实际上是优先级为 2（原文为 two，可能指非常低）。它不是非常高优先级的任务。您会看到零优先级是最低的？零优先级是可能有的最高优先级任务。这背后有历史原因。我没时间细说。所以您会看到它发生了，延迟是 7。最大命中一次是… 我猜我们是在看唤醒延迟。抱歉，那是唤醒延迟。唤醒延迟是 7 微秒。它发生了几次。您在这里看到它相当不错。记住，这是实时内核。
但是直方图触发器和合成事件。它们很强大。它们可以在生产系统上启用。有它们很棒。我的意思是，显然，这取决于您有什么事件，但实际的直方图触发器和合成事件本身… 不能在生产系统上启用？您可能没有启用抢占启用禁用事件（preempt enabled disabled events），但其他任何东西，读 IO，唤醒延迟有效。所有这些都在您拥有的任何系统上。而且它易于使用，对吧？我刚才在最后几分钟谈到的所有内容，您都理解了。您完全理解了一切。您可以自己去做了。嗯，它的格式相当奇怪，需要一段时间来习惯。但我不知道您要做什么。我不知道您要做什么。我不知道您要做什么。我不知道您要用这个做什么。我不知道您要做什么。我不知道您要做什么。我不知道您要用这个做什么。我不知道您要用这个做什么。我不知道您要用那个做什么。但我理解它是如何工作的。我知道，因为我在使用它时发现了本应被发现（如果有人在用的话）的 bug。如果它很难，人们就不会用它。所以我们需要更好一点的东西，以便我们可以完成这项工作，让它更容易使用，人们可以及时做到这一点。或者我们可以在用户空间做这个。
所以欢迎来到纸上谈兵软件（paperware），有些人说欢迎来到云端（cloud），这是欢迎来到雾件（vaporware）… 嗯，它几乎像一个词。所以如果我们需要的是一种人们不必重新学习的新语言呢？嗯，SQL 怎么样？想想看，事件就像表。事件中的字段是列。事件的每个实例就像一行。我们可以连接（join）表，基本上这些合成事件就是在连接事件。那我们为什么不能那样做呢？
从这里开始，与其拥有这种古老的输出，不如让它看起来更熟悉。这是我们正在研究的东西，几乎完成了。所以我们有我们的 SELECT 语句，每个人都很熟悉。我是说，我懂 SQL，虽然不情愿用，但大多数人懂。我们有… 您可以放入变量。您可以将某些东西标记为 pid，它会为您找到它。例如，start 被定义为 irq_disable，没有关于跟踪的内容，因为 trace-cmd 可以访问事件目录，它可以为您找到那个事件，并为您找到事件所在的系统。所以您不必担心变量。您不必担心事件在哪个系统上。您不必担心合成事件。这为您处理了一切。这里是 irq_enabled 作为结束。这就是您的组合。这是一种测量方式。
然后您可以说 AS irq_lat，这将是您的合成事件，您以后可以引用它。通过命名表，表就是事件本身，您命名了它，所以您不必担心合成事件。所有事情都在幕后完成。您只需要懂 SQL。
这就是您映射的方式。让我们看看两者放在一起。这里是它们… 这是我为禁用中断准备的，下面是 SQL 的相同版本。对于延迟跟踪器，这是我们为延迟跟踪准备的。同样，这是我为唤醒准备的。
要将两者映射在一起，如果您看上面… 您会看到变量，所有存在的变量，那实际上是在这里之前完成的。让我开始分解这个。一开始您必须创建您的合成事件，就像我说的，那就是表的命名。然后您必须放入该事件的参数，那个合成事件的参数，恰好是选择字段。所以如果您不放入 AS pid，但如果您省略它，您看到的都是 arg1, arg2 等等，没有意义。所以命名它是好的，这样当您看到跟踪点时，或者跟踪输出，或者如果您想在直方图中做点什么，您会看到效果。
FROM sched_waking，sched_waking 是您开始的第一个事件。FROM 是第一个事件，您要映射的第二个事件是 JOIN 事件。您注意到我用了 AS start 和 AS end，所以我只需要在那里命名它们。然后我在其他地方都使用 start 和 end。
从这里开始，时间戳，记得我有那个记录时间戳并映射它的变量。嗯，当我把代码放在这里，common_timestamp.usec - start.common_timestamp.usec，trace-cmd 会知道… 哦，我们需要放一个变量，我们需要一个变量来映射两者，它会为您做这件事。所以您不需要担心那个。
对于这里，我们如何映射？记得我说过您有一种方式将两个进程映射在一起。所以 sched_waking 将进程 ID 映射到下一个 PID？嗯，在这里您只需在 ON 语句上进行连接，它会告诉您如何进行这些连接，就像它在 SQL 中做的那样。然后您有这个过滤，我们在 WHERE 子句里。所以如果我放 WHERE start.prio < 100，那就是过滤器。一切都很简单。
它快来了。我基本都搞定了… 除了 WHERE 子句还有点问题。但我们快完成了。如果您想自己看看，就去我的 GitHub 页面，我有 sql_histogram。您可以把它 echo 进文件。如果您从这里注意到，我去掉了 WHERE 子句，它会给出实际的输出… 它会给出它将要运行的输出… 我们已经完成工作并将这个作为 trace-cmd 的一部分，所以它会为您准备好。
它叫什么… 您必须以 root 身份运行这个，因为它需要访问 tracefs 目录，这只有 root 可用。或者您可以复制它，有办法解决。但嘿，请随意尝试，我们很快会有的。
到此结束，非常感谢大家。再次介绍一下，我叫 Steve Rostedt，我在 VMware 工作。在 Twitter 上查看我们 @vmw_opensource，以及在 VMware.com 和开源博客上查看我们的博客。现在希望我们有几分钟时间，大概能回答一个问题。谢谢。
好的，快速切换一下场景，希望您能听到我… 并且看到… 技术人员说他们能听到我吗？希望可以… 好的，我看到还有其他问题进来… 嗯，让我看看，我已经回答了一些问题… 我写了一些回复…
第一个问题是：它与其他内核系统如 eBPF 或监控工具如 Netdata 有什么关系？我知道 eBPF 实际上使用 perf 进行跟踪，但也挂钩到很多 Ftrace 基础设施。如果您使用 bpf_trace_printk 来调试您的 BPF 模块，它实际上会写入 Ftrace，您实际上可以读取您呈现的内容或在您的模块中。
另一个问题是：hwlat_detector（或延迟检测器）是否支持 arm64 架构？是的，因为它完全与架构无关。它只是禁用中断，自旋并完成所有工作。它不需要任何特定于硬件的东西。可能有一点硬件相关的是，如果您有 NMI（不可屏蔽中断）发生，那里有一些钩子（hooks）可以让您知道 NMI 发生了，因为禁用 IRQ 并不会禁用… 我是说抱歉，并不能稳定不可屏蔽中断。所以如果您只是说禁用 IRQ，它会停止所有正常中断，但不可屏蔽中断（NMI）顾名思义，不能被中断或不能被停止。所以它可以检测到 NMI 的发生。所以当它们发生时知道是 NMI 而不是硬件问题，这很好。
一个问题是关于 Ftrace 与 strace 有什么不同。我喜欢 strace，我一直使用它，因为它显示您的实用程序或应用程序调用的系统调用。但仅此而已，它只停留在系统调用层面。Ftrace 是您可以实际跟踪系统调用到底做了什么的地方。如果您想学习比如 sys_read 做了什么，或者如果您在学习一个新的文件系统，比如您在看 Btrfs，想知道“Btrfs 如何实现读取”，您可以运行 Ftrace，实际执行一个系统调用读操作，然后让 Ftrace 读取或监视 Ftrace 跟踪在 Btrfs 内部被调用的所有函数，然后查看源代码，您可以学习它是如何工作的，或者至少它在做什么。
我想还有一个问题是：我们可以使用 renice 或 rtprio 来影响被分析的最高优先级任务吗？嗯，如果… 如果您改变了最高优先级任务，但它仍然是最高优先级，它仍然会被常规跟踪分析到。但如果您把最高优先级任务改成不再是最高优先级，它就不会被分析到了。所以它只是选择当前运行时刻的最高优先级任务进行跟踪分析。
哦，这里有一个：您如何比较这个与 DTrace、BPF trace 和 perf？嗯，它们都有点不同，略有重叠。Brendan Gregg 有一个非常好的演讲，我想他也有相关的书要出版，我推荐阅读。每种工具都有其优缺点，我喜欢有很多工具。有些人说工具太多了，但如果您只有一种工具，您就不会有完全符合您需求的东西。我发现我有时用 perf，有时用 BPF，有时用 Ftrace，取决于我认为哪种最适合当前用例。
有人问合成事件和直方图的最低版本要求是什么。我实际上不幸手头没有。我通常记得，我有点惊讶我没把它放在我的幻灯片里。有时候像这种信息我会放进幻灯片里说明它们何时可用，但它们已经可用一段时间了，而且还有很多工作在进行中。
看… 跟踪器是否对延迟值有影响？在大多数情况下，它会告诉您… 这要看情况。好吧，是也不是… 显然您可以改变它。海森堡不确定性原理（Heisenberg principle），无论您尝试测量什么，或者您测量这个事实本身，都会影响您试图测量的东西，这总是如此。但您可以将其限制在一定程度。当我进行延迟跟踪时，我有时会禁用函数跟踪，只启用跟踪事件，因为当您试图找出中断被禁用了多长时间时，跟踪每个函数会显著增加那个时间。所以我有时会选择几个，我会使用函数跟踪的过滤功能，只跟踪我想跟踪的函数，而不是跟踪所有函数。我想我在演讲中甚至提到过，我可能只选择跟踪正在获取的自旋锁，也许还有几个将被触发的其他函数，然后只运行延迟跟踪器，因为这样可以大大降低开销。相比获取跟踪延迟时间的良好数值，我更喜欢这样做。但是是的，您启用的跟踪越多，它会影响跟踪的延迟时间。但如果您移除所有函数跟踪，只运行像 irqs off 这样的跟踪器，它不会告诉您中间发生了什么，因为跟踪会被关闭，但这通常是中断被禁用时间的一个非常准确的数字。要评估 Ftrace 的输出，通常需要具备良好的内核内部知识吗？是的。嗯，这就是为什么我认为 Ftrace 对于学习内核非常好，因为您查看输出，然后您可能会对自己说“嗯，这是什么意思”，然后您去查看内核，您跟随 Ftrace 输出，查看内核，您就学习了它在做什么。嗯，总之，我想这是我所能回答的最后一个问题了。我会在 Slack 上… 在嵌入式 Linux（Embedded Linux）频道找我，您会在那里找到我。我也在 Linux 系统（Linux Systems）频道，但… 请随意，就像我说的，来看看我们的展位，我想 VMware 有个展位，来那里找我们。非常感谢，不再谈论了。