我们使用Kafka作为微服务之间异步通信的骨干。它每秒发布多达 30 万条消息，消耗多达 100 万条消息，是我们基础设施的关键部分。几个月前，在我们的主 Kafka 集群中，我们注意到以下差异：虽然生产请求的中值响应时间 为个位数毫秒，但尾部延迟要严重得多。即，p99潜伏期长达1秒，p999潜伏期长达3秒。对于我们即将启动的新项目来说，这是不可接受的，因此我们决定研究这个问题。在这篇博文中，我们想描述我们的旅程——如何使用 Kafka 协议嗅探和 eBPF 来识别和消除性能瓶颈。
追踪的必要性
Kafka Agent公开了各种指标。从他们那里，我们可以看出高百分位数的产品请求很慢，但我们无法确定原因。系统指标也没有显示出任何令人担忧的情况。
为了查明根本问题，我们决定跟踪各个请求。通过分析 Kafka 涉及处理生产请求的组件，我们的目的是揭示延迟峰值的根源。一种方法是分叉 Kafka、实施检测并将我们的自定义版本部署到集群。然而，这将非常耗时且具有侵入性。我们决定尝试一种替代方法。
我们做的第一件事是找到每个 Kafka 产品请求的_到达_和_结束时间。_
| |
| 产品请求的时间表。到达时间和结束时间定义了请求的边界。处理请求所涉及的 Kafka 组件及其延迟未知。 |
Kafka 使用 TCP 上的二进制协议将生产者（和消费者）的请求发送到代理。我们首先使用tcpdump捕获选定代理上的网络流量。然后我们编写了一个工具来分析捕获的数据包，这使我们能够列出所有请求和响应时间。在输出中，我们看到了对我们已经知道的事情的确认——有许多缓慢的生产请求需要一秒钟才能完成。更重要的是，我们能够看到请求元数据 -主题名称、分区 ID_和_消息 ID（我们的内部标识符包含在 Kafka 标头中）：
ARRIVAL TIME END TIME LATENCY(ms) MESSAGE_ID TOPIC PARTITION
12:11:36.521 12:11:37.060 538 371409548 topicA 2
12:11:36.519 12:11:37.060 540 375783615 topicB 18
12:11:36.519 12:11:37.060 540 375783615 topicB 18
12:11:36.555 12:11:37.061 505 371409578 topicC 7
12:11:36.587 12:11:37.061 473 375783728 topicD 16
12:11:36.690 12:11:37.061 370 375783907 topicB 18
有了这些额外的知识，我们就准备好进行更深入的挖掘。
动态追踪
通过网络流量分析，我们获得了每个请求的到达时间、结束时间和元数据。然后，我们希望深入了解哪些 Kafka 组件是延迟的根源。由于生产请求主要与保存数据有关，因此我们决定对底层存储进行写入检测。
在 Linux 上，Kafka 使用常规文件来存储数据。写入是使用普通的写入系统调用完成的——数据首先存储在页面缓存中，然后异步刷新到磁盘。我们如何在不修改源代码的情况下跟踪单个文件的写入？我们可以利用_动态跟踪_。
什么是_动态追踪_？在 Brendan Gregg 的_《系统性能》_中，他使用了我们非常喜欢的以下类比：
考虑一个操作系统内核：分析内核内部结构就像冒险进入一个暗室，在内核工程师认为需要的地方放置蜡烛[...]。动态仪器就像有一个可以指向任何地方的手电筒。
这基本上意味着可以检测任意内核代码，而无需修改用户空间应用程序或内核本身。例如，我们可以使用动态跟踪来检测文件系统调用，以检查它们是否是延迟的根源。为此，我们可以利用一种称为 BPF 的技术。
BPF（或 eBPF）代表_（扩展）伯克利数据包过滤器_，是一项具有丰富历史的技术，但如今它是一种通用的内核执行环境 [ Gregg Brendan (2020)。系统性能：企业和云，第二版]。它具有广泛的应用，包括网络、安全和跟踪工具。 eBPF 程序被编译为字节码，然后由 Linux 内核解释。
eBPF 有几个成熟的前端，包括BCC、 bpftrace和libbpf。它们可用于编写自定义跟踪程序，但它们还附带许多已实现的有用工具。ext4slower就是这样的工具之一。它允许跟踪 ext4 文件系统中的文件系统操作，ext4 文件系统是 Linux 的默认文件系统。
追踪Kafka
在 Kafka 中，每个分区都有自己的目录，根据以下模式命名：topicName - partitionID。在每个目录中，都有存储消息的段文件。在下图中，我们可以看到这种结构的一个例子。在此场景中，代理为_topicA托管两个分区（0 和 7），为__topicB_托管一个分区 (1) 。
通过稍微修改 ext4slower 程序以包含父目录，我们能够跟踪 Kafka 文件系统写入。对于持续时间超过指定阈值的每次写入，我们观察到以下情况：
- 开始时间和结束时间
- 期间
- 线程 ID (TID)
- 写入的字节数
- 文件偏移量
- 主题名称
- 分区ID
以下是该程序的输出示例：
START TIME END TIME LATENCY TID BYTES OFF_KB FILE
15:37:00.627 15:37:00.785 158 ms 4478 2009 88847331 topicA-0/00000000002938697123.log
15:37:00.629 15:37:00.785 156 ms 4492 531 289315894 topicB-7/00000000001119733846.log
15:37:00.629 15:37:00.785 156 ms 4495 815 167398027 topicC-7/00000000015588371822.log
15:37:00.631 15:37:00.785 154 ms 4488 778 502626221 topicD-7/00000000004472160265.log
15:37:00.644 15:37:00.785 141 ms 4486 341 340818418 topicE-7/00000000002661443174.log
15:37:00.650 15:37:00.785 135 ms 4470 374 230883174 topicF-7/00000000006102922534.log
15:37:00.653 15:37:00.785 132 ms 4461 374 375758631 topicF-19/00000000001555977358.log
这已经非常有用，因为我们可以根据时间戳、主题和分区，将 tcpdump 输出的生成请求与对文件系统的写入关联起来：
ARRIVAL TIME END TIME LATENCY MESSAGE_ID TOPIC PARTITION
15:37:00.627 15:37:00.785 158 ms 839584818 topicA 0
15:37:00.629 15:37:00.785 156 ms 982282008 topicB 7
15:37:00.629 15:37:00.785 156 ms 398037998 topicC 7
15:37:00.631 15:37:00.785 154 ms 793357083 topicD 7
15:37:00.644 15:37:00.786 141 ms 605597592 topicE 7
15:37:00.649 15:37:00.785 136 ms 471986034 topicF 7
15:37:00.653 15:37:00.786 132 ms 190735697 topicF 19
为了获得额外的信心，我们编写了一个工具来解析 Kafka 日志文件，读取写入其中的记录（使用文件偏移量和写入的字节数），解析它们并返回它们的_消息 ID_。这样，我们就能够将传入请求与其各自的写入完美关联起来：
START TIME END TIME LATENCY MESSAGE_ID FILE TOPIC PARTITION BYTES OFF_KB
15:37:00.627 15:37:00.785 158 ms 839584818 topicA-0/00000000002938697123.log topicA 0 2009 88847331
15:37:00.629 15:37:00.785 156 ms 982282008 topicB-7/00000000001119733846.log topicB 7 531 289315894
15:37:00.629 15:37:00.785 156 ms 398037998 topicC-7/00000000015588371822.log topicC 7 815 167398027
15:37:00.631 15:37:00.785 154 ms 793357083 topicD-7/00000000004472160265.log topicD 7 778 502626221
15:37:00.644 15:37:00.786 141 ms 605597592 topicE-7/00000000002661443174.log topicE 7 341 340818418
15:37:00.649 15:37:00.785 136 ms 471986034 topicF-7/00000000006102922534.log topicF 7 374 230883174
15:37:00.653 15:37:00.786 132 ms 190735697 topicF-19/00000000001555977358.log topicF 19 374 375758631
从分析中，我们可以看出有许多缓慢的生产请求花费了所有时间等待文件系统写入完成。
然而，有些请求没有相应的慢速写入。
Kafka锁争用
没有相应的慢速写入的慢速生产请求总是在其他一些慢速写入的时间附近发生。我们开始怀疑这些请求是否可能正在排队等待某些事情完成。通过分析 Kafka 源代码，我们确定了几个使用_同步_ 块的地方，包括那些保护日志文件写入的地方。
我们开始测量 Kafka 线程在处理生产请求时花费在上述锁上的时间。我们的目标是将等待锁定的时间段与文件系统的写入时间相关联。我们考虑了两种方法来做到这一点。
第一个是再次使用跟踪，并且可能将其结果与我们已有的用于跟踪 ext4 文件系统的工具结合起来。查看 JDK 源代码，我们无法识别_同步_块和可跟踪内核例程之间的连接。相反，我们了解到 JVM 附带了预定义的 DTrace 跟踪点（DTrace 可以被认为是 eBPF 的前身）。这些跟踪点包括_hotspot:monitor__contended__enter_ 和_hotspot:monitor__contended__entered_，它们监视线程何时开始等待争用锁以及何时最终进入争用锁。通过使用_-XX:+DTraceMonitorProbes_ VM 选项运行 Kafka 并附加到这些跟踪点，我们能够看到给定线程的监视器等待时间。
我们提出的另一种方法是通过 与 ext4 跟踪脚本一起运行async-profiler来捕获 Kafka 线程的状态。然后，我们将分析这两个工具的结果并将其输出关联起来。
在尝试了这两种想法之后，我们最终选择坚持使用 async-profiler。它提供了线程状态的清晰可视化，并提供了对线程的 JVM 特定属性的更多见解。
现在，让我们根据示例 async-profiler 记录、eBPF 跟踪和解析的 tcpdump 输出，深入研究如何分析发生延迟峰值时的情况。为简洁起见，我们将重点关注一个 Kafka 主题。
通过捕获代理上的网络流量，我们可以看到对所选主题有四个缓慢的生产请求：
ARRIVAL TIME END TIME LATENCY MESSAGE_ID TOPIC PARTITION
17:58:00.644 17:58:00.770 126 ms 75567596 topicF 6
17:58:00.651 17:58:00.770 119 ms 33561917 topicF 6
17:58:00.655 17:58:00.775 119 ms 20422312 topicF 6
17:58:00.661 17:58:00.776 114 ms 18658935 topicF 6
然而，该主题只有一个缓慢的文件系统写入：
START TIME END TIME LATENCY TID BYTES OFF_KB FILE
17:58:00.643 17:58:00.769 126 ms 4462 498 167428091 topicF-6/00000000000966764382.log
当时对该主题的所有其他写入都很快：
START TIME END TIME LATENCY TID BYTES OFF_KB FILE
17:58:00.770 17:58:00.770 0 ms 4484 798 167451825 topicF-6/00000000000966764382.log
17:58:00.775 17:58:00.775 0 ms 4499 14410 167437415 topicF-6/00000000000966764382.log
17:58:00.776 17:58:00.776 0 ms 4467 1138 167436277 topicF-6/00000000000966764382.log
我们知道其中一项快速写入是从 ID 为 4484 的线程执行的。从线程转储中，我们提取了线程名称和本机 ID (NID)。知道 NID 直接转换为 Linux TID（线程 ID）后，我们找到了一个 NID 为 0x1184（十进制：4484）的线程。我们确定该线程的名称为_data-plane-kafka-request-handler-24_。
我们在 async-profiler 输出中搜索该线程的活动：
| |
| 在 Java Mission Control 中可视化的异步分析器输出。 TID 4484 的线程在监视器上被阻止。 |
在输出中，我们看到了我们所怀疑的内容——一个线程等待锁的持续时间与另一个线程上发生的缓慢写入的持续时间大致相同。这证实了我们最初的假设。
| |
| 对于具有快速文件系统写入的慢速请求，等待获取锁被证明是延迟的根源。 |
应用这种技术，我们分析了许多案例，结果是一致的：对于缓慢的生产请求，要么存在匹配的缓慢写入，要么线程正在等待获取保护对日志文件的访问的锁。我们确认文件系统写入是生产请求缓慢的根本原因。
跟踪文件系统
我们最初的 eBPF 脚本仅跟踪对ext4_file_write_iter函数的调用。虽然这足以粗略地确定文件系统的缓慢写入导致了延迟峰值，但还不足以查明文件系统的哪些参数需要调整。为了解决这个问题，我们分别使用 profile和offcputime捕获了ext4_file_write_iter的on-CPU 和off-CPU 配置文件。我们的目标是识别内核中激活的路径，然后测量与它们相关的功能的延迟。
| |
| ext4_file_write_iter 的 CPU 上配置文件 |
| |
| ext4_file_write_iter 的 Off-CPU 配置文件 |
我们注意到函数ext4_dirty_inode [1] 出现在两个火焰图中。在Linux内核中，ext4_dirty_inode_函数负责将inode（文件或目录数据结构）标记为处于脏状态。脏inode表示对应文件的数据或元数据被修改，需要与底层存储设备（通常_是 磁盘）同步，以保证数据的一致性。
在脱离 CPU 的配置文件中引起我们注意的是jbd2__journal_start [2] 函数，它是 ext4 中采用的日志机制的一部分，可确保数据的完整性和可靠性。 ext4 中的日志记录涉及在将更改提交到文件系统之前维护记录更改的详细日志。该日志通常称为_日志_，在发生意外系统崩溃或电源故障时充当安全网。当文件系统操作发生时，例如创建、修改或删除文件，ext4 首先在日志中记录此更改。随后，更新实际的文件系统结构。更新文件系统的过程称为_提交_日志。在提交期间，日志中记录的更改将以受控和原子的方式应用于文件系统结构。如果发生中断，文件系统可以通过重播日志来快速恢复，确保它反映文件系统的一致状态。
如图所示的关闭 CPU 配置文件，wait_transaction_locked [3] 是在自愿让出处理器之前执行的函数，允许调度程序选择并切换到准备运行的不同进程或线程 ( schedule() )。根据_wait_transaction_locked_函数上面的注释：
等待，直到正在运行的事务传递到 T_FLUSH 状态，然后可以启动新事务。如果需要的话还会启动提交。该函数期望正在运行的事务存在并释放j_state_lock。
我们搜索了内核代码来确定是什么设置了_T_FLUSH_标志。我们发现的唯一地方是 由内核日志线程定期执行的jbd2_journal_commit_transaction函数内。因此，我们决定跟踪该函数以探索其延迟与_ext4_dirty_inode_延迟之间的相关性。获得的结果与我们的预期完全一致——即**jbd2_journal_commit_transaction****中的高延迟 转化为_ext4_dirty_inode_中的高延迟 。**我们的调查结果详情如下：
START TIME END TIME LATENCY FUNCTION
19:35:24.503 19:35:24.680 176 ms jbd2_journal_commit_transaction
19:35:24.507 19:35:24.648 141 ms ext4_dirty_inode
19:35:24.508 19:35:24.648 139 ms ext4_dirty_inode
19:35:24.514 19:35:24.648 134 ms ext4_dirty_inode
...
19:38:14.508 19:38:14.929 420 ms jbd2_journal_commit_transaction
19:38:14.511 19:38:14.868 357 ms ext4_dirty_inode
19:38:14.511 19:38:14.868 357 ms ext4_dirty_inode
19:38:14.512 19:38:14.868 356 ms ext4_dirty_inode
...
19:48:39.475 19:48:40.808 1332 ms jbd2_journal_commit_transaction
19:48:39.477 19:48:40.757 1280 ms ext4_dirty_inode
19:48:39.487 19:48:40.757 1270 ms ext4_dirty_inode
19:48:39.543 19:48:40.757 1213 ms ext4_dirty_inode
...
ext4 改进监控
在确定日志提交是写入缓慢的原因之后，我们开始思考如何缓解该问题。我们有一些想法，但我们想知道如何才能观察到改进。在那之前，我们依赖命令行工具并在短时间内分析它们的输出。我们希望能够在较长时间内观察优化的影响。
为了报告长期跟踪的函数延迟，我们使用了ebpf_exporter，该工具以 Prometheus 格式公开基于 eBPF 的指标。然后我们就能够在 Grafana 中可视化痕迹。例如，给定代理的最大 ext4 写入延迟：
这样，我们就能够运行具有不同配置的代理，并随着时间的推移观察它们的写入延迟。
ext4 的改进
让我们回到ext4。我们知道日志提交是延迟的根源。通过研究 ext4 文档，我们确定了一些提高性能的可能解决方案：
- 禁用日记功能
- 减少提交间隔
- 将日志模式从 更改
data=ordered为data=writeback - 启用快速提交
让我们逐一讨论一下。
禁用日记功能
如果日志是高延迟的根源，为什么不完全禁用它呢？事实证明，写日记是有原因的。如果没有日记，我们将面临崩溃时长时间恢复的风险。于是，我们很快就排除了这个方案。
减少提交间隔
ext4 有_commit_ mount 参数，它告诉执行提交的频率。它的默认值为 5 秒。根据 ext4 文档：
此默认值（或任何低值）会损害性能，但有利于数据安全。 [...]将其设置为非常大的值将提高性能。
然而，我们决定减少该值，而不是增加该值。为什么？我们的直觉是，通过更频繁地执行提交，我们将使它们变得“更轻”，从而使它们更快。我们会用吞吐量换取更低的延迟。我们对commit=1、 和进行了实验，commit=3但没有观察到显着差异。
将日志记录模式从 data=ordered 更改为 data=writeback
ext4 提供三种日志模式：journal、ordered_和_writeback。默认模式是_排序的_，并与性能最高的模式_writeback_进行比较，它保证在将元数据提交到日志之前将数据写入主文件系统。正如 文档中提到的，Kafka 不依赖此属性，因此将模式切换为_写回_应该会减少延迟。
我们在其中一个代理上切换了日志模式，事实上，我们观察到了延迟的改善：
| |
|
|
| 当 data=writeback 时，p999 从 3 秒减少到 800 毫秒。 |
启用快速提交
在阅读有关 ext4 日志记录的文章时，我们偶然发现了一篇文章，该文章描述了 Linux 5.10 中引入的一项名为 _快速提交_的新功能。正如本文中所解释的，_快速提交_是一种轻量级的日志方法，可以提高某些工作负载的性能。
我们在其中一个代理上启用了_快速提交。_**我们注意到最大写入延迟显着降低。**深入研究后我们发现，在 启用_快速提交_的代理上：
- jdb2_journal_commit_transaction_的延迟降低了一个数量级。这意味着由于启用了_快速提交，定期日志提交确实要快得多。
- _当jbd2_fc_begin_commit_的延迟出现峰值时，同时发生缓慢的 ext4 写入。此方法是_快速提交_流程的一部分。它成为新的延迟来源，但其最大延迟低于没有快速提交的_jdb2_journal_commit_transaction_的延迟。
| |
| 没有和有快速提交的代理的 ext4 写入的最大延迟 [s] 的比较。 |
反过来，较低的文件系统写入延迟会减少生产延迟：
| |
|
|
| 启用快速提交后，生产 P999 延迟从 3 秒降至 500 毫秒 |
概括
总而言之，我们测试了以下 ext4 优化：
- 减少提交间隔
- 将日志模式更改为
data=writeback - 启用
fast commit
我们观察到两者data=writeback都fast commit显着减少了延迟，并且fast commit延迟稍低。结果令人鼓舞，但我们抱有更高的希望。值得庆幸的是，我们还有一个想法。
XFS
在研究 ext4 中的日志记录主题时，我们偶然发现一些消息来源，表明 XFS 文件系统及其更高级的日志记录非常适合处理大文件和高吞吐量工作负载，在这种情况下通常优于 ext4。 Kafka 文档还提到 XFS 已经进行了大量调整，应该比默认的 ext4 更适合。
我们将其中一个代理迁移到 XFS 文件系统。结果令人印象深刻。与前面提到的 ext4 优化相比，非常有特色的是 XFS 性能的一致性。虽然其他代理配置在一天中经历了 p999 延迟峰值，但 XFS（使用其默认配置）仅出现了一些问题。
经过几周的测试，我们确信 XFS 是最佳选择。因此，我们将所有代理从 ext4 迁移到 XFS。
概括
通过结合使用数据包嗅探、eBPF 和 async-profiler，我们成功地确定了 Kafka 集群中生产请求缓慢的根本原因。然后，我们测试了该问题的几种解决方案：data=writeback日志模式、fast commits将文件系统更改为 XFS。这些优化的结果在下面的热图中可视化：
最终，我们发现 XFS 性能最高，并将其推广到我们所有的经纪商。使用 XFS，超过 65 毫秒（我们的 SLO）的生产请求数量减少了 82%。
以下是我们在此过程中学到的一些教训：
- eBPF 在分析过程中非常有用。使用 bcc 或 bpftrace 中的现有工具之一非常简单。我们还可以根据我们的自定义用例轻松修改它们。
- ebpf_exporter 是一个很好的工具，可以在较长时间内观察跟踪结果。它允许基于 libbpf 程序公开 Prometheus 指标。
- p99 和 p999 分析有时是不够的。在我们的例子中，文件系统写入的 p999 延迟小于 1 毫秒。事实证明，单个缓慢的写入可能会导致锁争用和一系列缓慢的请求。如果不追踪单个请求，根本原因就很难找到。
