【HDFS】JN回滚大量edit日志导致Namenode主备切换的故障记录

前言

集群大了，这莫名其妙的问题就多了起来；今天上午还在地铁上的时候，就接到电话说集群出问题了，电话里描述的现象就是集群任务运行出了问题，让我看看调度服务是不是异常了：

看监控图表发现在8点40-50之间存在明显的任务空洞，第一反应还是YARN或者HDFS是不是有啥问题，而领导之所以会让查调度也是因为这两天才做了调度服务的迁移不久，怕新的服务器不稳定；

本人到了公司以后就开始对调度服务及底座进行巡检，最终确定问题原因并恢复集群，接下来详细记录本次问题的处理。

正文

整体的排查思路还是要从调度到底座逐步进行的，第一步还是先看下调度服务及服务器指标状态：

问题排查

调度服务状态

首先登录上服务器看下调度服务器的相关性能指标，从指标图来看，并不存在太大问题，暂时不需要细查，尤其是内存、CPU及load_avg，都维持在可以接受的水平：

内存占用高的疑问：领导怀疑内存占用过高，其实根据整体监控的趋势，判断这个是正常现象，主要是缓存占用，将内存监控跨度拉长到一天的跨度：

图中可以看到在凌晨的时候，缓存被释放了一部分，这是因为在0点时分，调度时间会前移一天，比如调度周期是2天，17号当天就会调度16、17号的任务，当跨过17号23:59:59到达18号的0点时，调度周期变为17号和18号的任务，这个时候，内存中16号的任务相关的缓存会被刷写到磁盘，所以出现了一个骤降陡坡；

由此可见，操作系统的内存回收在正常进行，且每日50w+的任务调度，这样的内存占用率还是可以接受的。

HDFS服务状态

调度服务基本确认正常后，就怀疑是YARN或者HDFS的问题，YARN简单检查了一下，无论是测试任务的提交还是节点的状态，都没有太大问题，所以就略过深入排查的部分了，直接检查HDFS的监控指标，最先发现的疑点就是JVM的内存使用率变化：

我们的集群有0-7总共8对NameNode，组成的联邦，JVM内存使用率基本都在上午8点40-50之间发生骤变，该时间点和Yarn上的任务空置时间基本吻合，这显然是不正常的，NameNode就算是发生GC回收也不应该在同一时间，所以初步怀疑NameNode有变故。

接下来缩短时间范围，只查看8:30-9:30之间的监控数据，这次检查RPC响应的指标，发现所有联邦都在这个时间出现了RPC响应缓慢的情况：

抽查一对NameNode节点的日志，发现发生了主备切换，ZKFC日志中也有记录：

2022-08-09 21:41:30,290 INFO org.apache.hadoop.ha.HealthMonitor: Entering state SERVICE_NOT_RESPONDING
2022-08-09 21:41:30,530 FATAL org.apache.hadoop.ha.ZKFailoverController: Couldn't make NameNode at XXXXX/XX.X.X.X:XXXX active
1
2

基于此，赶紧把整个联邦的切换时间都拉出来看：

妈耶，全切了，都在8点40-50之间切换的，接下来就要去分析这个时间为何会发生切换了。

问题分析

NameNode日志

继续检查NameNode，查看宕机的原因：

2022-08-18 08:42:25,451 WARN org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Waited 18042 ms (timeout=20000 ms) for a response for sendEdits. Succeeded so far: [hostname001:8485,hostname001:8485,hostname001:8485,hostname001:8485,hostname001:8485,hostname001:8485,hostname001:8485]
2022-08-18 08:42:26,453 WARN org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Waited 19043 ms (timeout=20000 ms) for a response for sendEdits. Succeeded so far: [hostname001:8485,hostname001:8485,hostname001:8485,hostname001:8485,hostname001:8485,hostname001:8485,hostname001:8485]
2022-08-18 08:42:27,411 FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: flush failed for required journal (JournalAndStream(mgr=QJM to [XXXXX], stream=QuorumOutputStream starting at txid 148503555010))
1
2
3

又是超过半数的JN写入失败导致的，接下来就是找到这个时间点出现大批量的的JN交互失败的诱因了，这个现象和之前发的文章遇到的类似，但是生产环境服务器都是物理机，要说IO性能导致的可能性不太大，但是还是查一下主机的监控指标。

JN服务器主机指标

总共16台JN都看了一下，基本上都在问题时间点有异常的指标，主要集中在内存和磁盘使用率上：

看到在问题时间点存在很明显的降低，降了接近200G的使用，JN磁盘使用率也降了接近20%，不过在这个时间点中，IO的性能和负载都不高，还需要继续查JN的日志。

JN日志

查看JN的日志，在问题时间点有大量以下日志打印：

2022-08-18 08:41:42,584 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96810687406
2022-08-18 08:41:42,590 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 97200674082
2022-08-18 08:41:42,593 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96615191632
2022-08-18 08:41:42,601 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 97044934037
2022-08-18 08:41:42,603 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96384222404
2022-08-18 08:41:42,615 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 95261691460
2022-08-18 08:41:42,629 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96352115446
2022-08-18 08:41:42,632 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96384916493
2022-08-18 08:41:42,633 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 97220781650
2022-08-18 08:41:42,634 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96799641693
2022-08-18 08:41:42,644 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 97011821194
2022-08-18 08:41:42,646 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96864710656
2022-08-18 08:41:42,657 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96626075374
2022-08-18 08:41:42,670 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 95998171116
2022-08-18 08:41:42,696 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 97708448466
2022-08-18 08:41:42,698 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 95848069461
2022-08-18 08:41:42,717 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 95799027857
2022-08-18 08:41:42,734 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96574073515
2022-08-18 08:41:42,749 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 95633241492
2022-08-18 08:41:42,773 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 95221791533
2022-08-18 08:41:42,777 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96665778757
2022-08-18 08:41:42,779 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96639895736
2022-08-18 08:41:42,790 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96875550047
2022-08-18 08:41:42,791 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96042767328
2022-08-18 08:41:42,793 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96257807954
2022-08-18 08:41:42,811 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96611145675
2022-08-18 08:41:42,824 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96639763733
2022-08-18 08:41:42,828 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96834306087
2022-08-18 08:41:42,836 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96619005041
2022-08-18 08:41:42,848 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96504221043
2022-08-18 08:41:42,849 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 95206785547
2022-08-18 08:41:42,863 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 95336116029
2022-08-18 08:41:42,865 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 97048279800
2022-08-18 08:41:42,869 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96664943401
2022-08-18 08:41:42,877 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 95242430887
2022-08-18 08:41:42,886 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 95626277939
2022-08-18 08:41:42,906 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96380113241
2022-08-18 08:41:42,916 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96210476386
2022-08-18 08:41:42,931 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96625066699
2022-08-18 08:41:42,939 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96000623734
2022-08-18 08:41:42,940 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 96071930686
2022-08-18 08:41:42,954 INFO org.apache.hadoop.hdfs.server.common.Storage: Purging no-longer needed file 97181499035
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42

这种日志在这个时间里打印了20000+条，就很尬：

这个时候突然想到有一对NameNode的备机NN宕机了接近一个月，16号才发现，当时看到这个联邦的很久没做Checkpoint，然后在17号上午接近10点的时候尝试拉起宕机的NameNode，当时就有2w+的Edit日志，感觉这个数字相似的太巧了，看了下启动记录，加载了也是20000多的Edit：

启动时间持续了22个小时：

确认一下是何时进行的NameNode启动的，这个数据可以在Jmx中找到，记录显示是2022年8月17日上午9点57分启动的，也就是说完成时间大概是9点40左右：

在启动完成时进行一次Checkpoint操作，理论上应该会在8点33左右进行，事实也确实如此：

源码中可以看到在进行Checkpoint以后，确实会对目录下的过期edit log进行清理：

  private synchronized void saveFSImageInAllDirs(FSNamesystem source,
      NameNodeFile nnf, long txid, Canceler canceler) throws IOException {
    StartupProgress prog = NameNode.getStartupProgress();
    prog.beginPhase(Phase.SAVING_CHECKPOINT);
    if (storage.getNumStorageDirs(NameNodeDirType.IMAGE) == 0) {
      throw new IOException("No image directories available!");
    }
    if (canceler == null) {
      canceler = new Canceler();
    }
    SaveNamespaceContext ctx = new SaveNamespaceContext(
        source, txid, canceler);
    
    try {
	  .......
      // Since we now have a new checkpoint, we can clean up some
      // old edit logs and checkpoints.
      purgeOldStorage(nnf);
    } finally {
      // Notify any threads waiting on the checkpoint to be canceled
      // that it is complete.
      ctx.markComplete();
      ctx = null;
    }
    prog.endPhase(Phase.SAVING_CHECKPOINT);
  }
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26

那么很可能在这个时间点触发checkpoint后，JN进行了过期edit log的清理，由于文件量实在太大，耗时较久，随后响应超时，然后NN发生切换。

切换完成后，JN也完成了数据清理，而主备也完成了切换，所以新的主NN能够正常工作；

故障恢复

这种故障的恢复也很简单，只需要在确认JN以后对宕机的NN进行重启即可，响应的可以对IPC的超时参数进行调整，为了应对可能的延迟，适当增大该值，但是不宜过大：

<property>
	<name>ipc.client.connect.timeoutname>
	<value>20000value>
property>
1
2
3
4

结语

过程复盘

本次故障大概的原因已经梳理清楚：

大集群中有一个联邦的NN宕机了很久，由于宕机，导致这对NN无法正常进行Checkpoint，最后的Checkpoint时间一直停留在7月19号：


因此，该组NN产生大量的edit log文件，这部分文件也存在于JN中，关键点就在这，集群的所有NN公用了一组JN，总共15台；

在2022-08-17上午9点59分对宕机的NN进行重启，由于edit log过多，重启时间跨度很久，并没有立刻触发过期edit log的判断和删除操作，因此整个集群一直没有异常表现；

在2022-08-18上午8点35分左右，NN重启完成，进行了一次Checkpoint，该操作触发了过期edit log的清理，于是所有JN都开始清理其下的2w多个过期edit log，这个过程耗时较久，导致集群的所有主NN无法和超过半数的JN进行通信，IPC响应超时，最终自杀。

思考

想来本次故障实际上还是在日常巡检中对主要节点、服务的巡检不够仔细导致的，实际上很早之前部分维护人员已经收到了异常联邦的Checkpoint延迟告警，不过并没有进一步核查：

真因为如此，该联邦下积攒了很多的edit log文件，才导致了后面的一系列问题，反思！反思！警钟长鸣！