HDFS客户端无法及时addBlock和关闭文件问题分析

背景

现网运行过程中，某些高负载集群的 NN 频繁打印下面的 “block is COMMITTED but not COMPLETE" 日志，且客户端经常会关闭文件失败，导致业务异常退出，如下所示：

HDFS 基本逻辑

这实际是一个 block 无法及时到达 COMPLETE 状态的问题，在 HDFS 中，一个 block 只有达到最小副本数之后，才能变为 COMPLETE 状态。HDFS 默认的最小副本数是1，也就是说，NameNode 收到至少1个 DataNode 的上报之后，这个 block 才能达到 COMPLETE 状态，表示这个 block 已经正式写入完毕，其内容此时已成功固化到磁盘。

如果一个文件的 block 不能及时达到 COMPLETE 状态，则会导致

1. client 在写文件过程中，调用 addBlock 分配新的 block 时响应变慢，原因：NN 需要等待该文件已有的 block 达到 COMPLETE 状态之后，才能分配新的 block 出来（实际情况复杂一点，但大体上可以这么理解）。最终表现为客户端写入文件慢。
2. 客户端在关闭文件时，调用 completeFile 关闭文件时响应变慢，原因： NN 需要等待该文件所有的 block 都达到 COMPLETE 状态之后，才能关闭文件，最终表现为客户端关闭文件慢。
3. 如果多次重试（默认重试5次）仍不能成功，会导致客户端写文件失败，或关闭文件失败，也就是文章开头所说的问题。

HDFS 客户端默认行为

1. HDFS 客户端为正在写入的文件分配新的 block时，默认的行为（多次重试且间隔逐次倍增）

   1. 客户端为文件分配新的 block 时，如果不成功，则会等待一段时间后重试，按照默认配置，一共会重试5次（配置项：dfs.client.block.write.locateFollowingBlock.retries，默认值：5），加上最开始正常的第一次调用，一共会执行6次 addBlock RPC.
   2. 在每次重试之前，客户端的等待时间依次倍增：400ms、800ms、1600ms、3200ms、6400ms（初始等待时间配置项：dfs.client.block.write.locateFollowingBlock.initial.delay.ms，默认值：400），简单累加可知：客户端大概有 12.4s 的额外 sleep 时间。
   3. 客户端每次重试之前，都会打印INFO日志，具体为：Exception while adding a block …
   4. 客户端每次重试之前，都会打印当前的重试信息WARN，具体为：NotReplicatedYetException sleeping … retries left …
   5. 如果客户端额外sleep时间已超过5s（按默认配置即已经重试了4次），那么会打印一条INFO日志,具体为：Waiting for replication for… seconds
   6. client 在 12.4s 内一共6次 addBlock 调用全部失败之后，抛异常，具体异常为 NotReplicatedYetException

2. HDFS 客户端关闭文件时，默认的行为（多次重试且间隔逐次倍增）：
   关闭文件和分配新 block 非常类似，因为它们的关键点其实都一样，即：NameNode 需要等待 block 达到最小副本数，变为 COMPLETE 状态。

   1. 同样，客户端关闭文件时，如果不成功，则会等待一段时间后重试，按照默认配置，一共会重试5次（配置项：dfs.client.block.write.locateFollowingBlock.retries，默认值：5），加上最开始正常的第一次调用，一共会执行6次 complte RPC.
   2. 在每次重试之前，客户端的等待时间依次倍增：400ms、800ms、1600ms、3200ms、6400ms（初始等待时间配置项：dfs.client.block.write.locateFollowingBlock.initial.delay.ms，默认值：400），简单累加可知：客户端大概有 12.4s 的额外 sleep 时间。
   3. 如果客户端额外 sleep 时间已超过5s（按默认配置即已经重试了4次），那么会打印一条 INFO 日志，具体为：Could not complete… retrying…
   4. client在 12.4s 内一共6次 complete 调用全部失败之后，抛异常，异常信息为：Unable to close file because the last block ... does not have enough number of replicas.

客户端此时对重试的容忍度

1. 重试4次及4次以下才能分配 block 成功（或才能关闭文件成功），认为可以接受，此时客户端的额外 sleep 时间在 6s 以下，离 12.4s 的阈值还较远，可以认为比较安全。
2. 重试5次才能分配 block 成功（或才能关闭文件成功），就比较危险，因为这是最后一次机会，如果这次重试还是失败，那么客户端会抛异常报错。

两个高负载集群的例子

这两个集群是负载较高的两个集群，共同点是 NameNode 都会频繁的打印上面那种 “block is COMMITTED but not COMPLETE” 日志，但这两个集群又有所不同：

1. 对于集群1，绝大部分（超过99%）的 block 重试次数都为1，极少数为2，没有3及3以上的，也就是说：

   1. 绝大部分 addBlock 操作（或关闭文件操作），客户端需要付出的额外 sleep 时间不超过400ms，这个比较正常。
   2. 极少部分 addBlock 操作（或关闭文件操作），客户端需要付出的额外等待时间不超过1200ms，这个可以接受。
   3. 没有需要额外等待更长时间的 addBlock 操作（或关闭文件操作）。

   整体来看，这个集群比较OK，不再额外关注。

2. 但对于集群2，情况格外严重，以2020.12.25日 [16:40:00, 16:50:00) 这10分钟为例，在这10min 内，NN 一共有 11297个 block 不能及时达到 COMPLETE 状态，需要客户端重试。其中：

   1. 11106个 addBlock 操作（或关闭文件操作），客户端只需要重试一次即可，客户端需要付出的额外 sleep 时间为：400ms。
   2. 160个 addBlock 操作（或关闭文件操作），客户端需要重试2次，客户端需要付出的额外 sleep 时间为：400ms + 800ms = 1.2s。
   3. 18个 addBlock 操作（或关闭文件操作），客户端需要重试3次，客户端需要付出的额外 sleep 时间为：400ms + 800ms + 1600ms = 2.8s。
   4. 9个 addBlock 操作（或关闭文件操作），客户端需要重试4次，客户端需要付出的额外 sleep 时间为：400ms + 800ms + 1600ms + 3200ms = 6s。
   5. 3个 addBlock 操作（或关闭文件操作），客户端需要重试5次，客户端需要付出的额外 sleep 时间为：400ms + 800ms + 1600ms + 3200ms + 6400ms = 12.4s。
   6. 1个 addBlock 操作（或关闭文件操作），客户端重试了5次，但第5次重试依然失败，这会导致客户端抛异常报错。

   整体来看，这个集群的问题比较严重，甚至有导致客户端出错的情况，需要仔细分析原因。

导致业务异常退出的那个 Block

以那个导致客户端出错的 block 为例（block ID 为：blk_16141305305），可以看到，客户端有5次重试，加上第一次的正常操作，一共尝试了6次 addBlock（或 completeFile），但全部未成功，这将直接导致客户端写文件失败（或关闭文件失败）：

这个 block 涉及到两个 DN，以9.179.163.164 这个 DN 为例，可以看到，DN IO 线程在 16:46:16 写完 block 触发增量上报之后，一直过了45s 到了16:47:01，DN 心跳线程才开始真正向 NN 发送增量上报 RPC 消息，这很不正常，正常情况应该是立即发送才对（另外结合上面的 NN 日志可以看到，DN 发送增量上报 IBR 之后，就被 NN 同时在16:47:01处理完毕，可见此时 NN 没有问题）：

进一步分析 DN 的 IBR 上报记录，可以看到：心跳线程在 16:46:07 到 16:47:01 之间，这54s之内，根本没有进行任何 IBR 上报，这也导致 16:47:01一下子积攒了很多 block，那么问题很清楚了，在这长达54s 的时间内，DN 心跳线程到底在干什么？

DN 心跳线程的工作

DN 心跳线程循环执行 BPServiceActor.offerService() 函数，在这个函数里，它循环做下面的事情：

1. 第一步：心跳。
2. 第二步：执行心跳可能带回来的命令（如删除 block 等）
3. 第三步：发送增量上报 IBR
4. 第四步：如果已到达全量上报时间点，则发送全量上报 FBR
5. 第五步：处理全量上报 FBR 可能带回来的命令
6. 继续返回第一步执行。

现在的问题集中在：DN 在处理这次 IBR 之前，一共54s 内，到底在干嘛？

问题时间段 DN 心跳线程在干什么？

首先想到的就是 jstack，但是现在是事后分析，已经没法再 jstack 了。好在这个问题集群其实一直在持续性的出现这种文件不能及时关闭的问题，所以，现在再 jstack，也来的及，具体步骤：

1. 首先找两个嫌疑比较大的 DN 进行操作，比如上面出现的9.179.163.49和9.179.163.164。
2. 开始对这两个 DN 周期性的 jstack（5s 一次），并保存结果。jstack 本身对 DN 的影响微乎其微（会导致 DN 进程停顿 200ms左右）。
3. 同时，打开这两个 DN 的 IBR 日志，找到长时间未进行 IBR 的时间段，一般会长达几十秒。
4. 结合问题时间段的 jstack 结果，确定心跳线程到底在干嘛。

这次倒是比较顺利的拿到了结果：

1. 心跳线程在问题时间段，在进行心跳，但是卡在 getStorageReports 函数里，具体 synchronize 在 statsLock 这个对象上：

   
   

2. 而拿到 statsLock 对象锁的线程，此时正在向另一个 NN 心跳，但是在 getDfsUsed() 时阻塞在另外一把锁上，就是大名远扬的 FsDatasetImpl.datasetLock

   
   

3. 到这一步其实就比较清楚了，FsDatasetImpl.datasetLock 几乎是 DN 的一把全局互斥锁，超多流程都需要拿这把锁，比如：写 IO 线程构造 BlockReceiver 时、读 IO 线程构造 BlockSender 时、写线程 Finalize 一个 block 时、VolumeScanner scan 一个 block 时，等等，实际上，此时 DN 进程里，有156个线程在竞争这把互斥锁：

   
   

4. 在一共156个竞争者中，IO 线程就有120个，可见 IO 线程是争这把锁的大户，

   
   

5. 这个 DN 此时总的 IO 线程数是171，也非常高了（正常100以下）。其实，这也是为什么以前一旦发现 addBlock 或 completeFile 超时，总是习惯性的第一时间怀疑 DN 负载太高。现在这个关系总算是搞清楚了：DN IO 线程是争 FsDatasetImpl.datasetLock 这把全局互斥锁的大户，如果 IO 线程太多，那么会导致心跳线程长时间争不到这把锁，从而卡在 getStorageReports() 这个地方走不下去：

   
   

如何解决

既然找到了原因，那么解决起来就比较容易了，通过上面的分析，核心的原因还是 FsDatasetImpl.datasetLock 这把全局互斥锁实在是太难抢了，导致心跳线程在 getStorageReports() 时长时间等这把锁（最终是 getDfsUsed() ）。但实际上，心跳线程此时其实不需要这把锁，因为它拿到锁之后，要访问的数据结构是一个 ConcurrentHashMap，要知道 ConcurrentHashMap 本身即是一个支持并发读写的结构，访问它根本不需要额外再加什么锁。

到底为止，改法其实出来了，DN 心跳线程在 getDfsUsed() 时，不用加 FsDatasetImpl.datasetLock 这把全局互斥锁。

历尽千辛万苦，终于找到了原因，但是当我要去改的时候，发现 hdfs 3.x 已经改了这个地方（改动的目的是解决另外一个问题，但却顺带着也解决了我们这次的问题），所以 backport 就可以了，具体 jira 为：HDFS-7060 Avoid taking locks when sending heartbeats from the DataNode

多线程任务的性能瓶颈到底在哪里？

从这个问题的分析过程，也可以看出，像 NameNode 和 DataNode 这种高并发、大吞吐的多线程任务，在功能方面，可以不断的增加新特性，但在性能方面，最终的瓶颈往往会落到某个全局锁上（或者虽然不是全局但范围特别广的锁），这时候争锁才是导致多线程无法完全发挥潜力、整体吞吐量下降的阿克琉斯之踵。更加难受的是，争锁的困境往往很难通过小修小补解决，而是需要架构层面的重构，这又进一步加大了优化的成本。典型的比如 HDFS NN 和 DN 中的两把全局锁，对整体性能的影已经是一个旷日持久的问题，但直到现在，也依然没有得到解决:

1. NameNode 的全局读写锁
   即 FSNameSystem.rwlock，现在限制 NN 吞吐量的，其实就是这个全局锁，现网大多数 NN 吞吐量下降从而导致 callQueue 积压，最终导致客户端操作变慢的情形，其实都不是因为 NN handler 线程不够、CPU 负载太高、内存不够、硬盘不足、网卡不足等硬性条件，基本都是因为某个线程拿锁太久，导致其他线程全部停下来等锁。在这种情况下，增大线程数其实毫无意义，再多的线程也只能停下来等锁，特别是在公平读写锁之下，有时候读锁和写锁都会造成互斥锁的效果，即：某一个线程拿锁运行，其他所有线程全部停下来阻塞等锁。

2. DataNode 的近似全局互斥锁
   即 FSDataetImpl.lock，这个虽然不是全局锁，但也差不多了，DataNode 的大多数核心线程，例如 IO 线程、心跳线程、VolumeScanner 线程、DirectoryScanner 线程等等，都需要争这把锁，特别是当 DN 进程 IO 负载很高、IO 线程创建销毁频繁的情况下，这种争锁将更加严重，很多时候都会导致心跳线程争不到这把锁，无法及时进行 IBR 或心跳，导致客户端无法及时关闭文件（或分配新的block），严重情况下可能导致 DN dead。这次比较幸运的是，经过分析我们发现心跳线程在 getDfsUsed() 时，其实可以不拿这把锁，从而不受影响，但如果这次没这么简单，那想要优雅地剥离这把锁就千难万难了。

后续

DN 心跳线程争锁是一个老生常谈的问题，除了上面已经合入的 HDFS-7060 之外，社区还有其他几个 Patch 也需要合入：

1. 第一个是“DN 异步处理 NN 命令” 的特性，用来消除 DN 在执行 NN 命令过程中的争锁（特别是删除 block 命令），相关的 patch 如下：
   1. HDFS-14997. BPServiceActor processes commands from NameNode asynchronously
   2. HDFS-15075. Remove process command timing from BPServiceActor
   3. HDFS-15113. Missing IBR when NameNode restart if open processCommand async feature
   4. HDFS-15651. Client could not obtain block when DN CommandProcessingThread exit
2. 第二个是 "DirectoryScanner 批量修复问题 block 特性“，用来解决 DirectoryScanner 线程持锁时间太长的问题，相关的 patch 如下：
   1. HDFS-14476. lock too long when fix inconsistent blocks between disk and in-memory