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

2023年6月11日下午9:33 • Python • 阅读 145

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

前言
正文
*
问题排查
–
- 调度服务状态
- HDFS服务状态
问题分析
–
故障恢复
结语
*
过程复盘
思考

前言

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

看监控图表发现在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

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

妈耶，全切了，都在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))

又是超过半数的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

这种日志在这个时间里打印了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 {
      .......

      purgeOldStorage(nnf);
    } finally {

      ctx.markComplete();
      ctx = null;
    }
    prog.endPhase(Phase.SAVING_CHECKPOINT);
  }

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

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

故障恢复

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

<property>
    <name>ipc.client.connect.timeoutname>
    <value>20000value>
property>

结语

过程复盘

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

大集群中有一个联邦的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文件，才导致了后面的一系列问题，反思！反思！警钟长鸣！

Original: https://www.cnblogs.com/Meepoljd/p/16625227.html
Author: 风灵动铭
Title: 【HDFS】JN回滚大量edit日志导致Namenode主备切换的故障记录

原创文章受到原创版权保护。转载请注明出处：https://www.johngo689.com/601892/

转载文章受原作者版权保护。转载请注明原作者出处！

python

【自取】最近整理的，有需要可以领取学习：

Linux核心资料大放送~

全栈面试题汇总（持续更新&可下载）

一个提高学习100%效率的工具！

【超详细】深度学习面试题目！

LeetCode Python刷题答案下载！

LeetCode Java版刷题答案下载！

LeetCode C++ 版本，抓紧保存！

LeetCode GO语言刷题答案下载！

python用几行代码实现数据的按列去重及合并处理

前言： Pandas模块是Python用于数&a…

Python 2023年8月8日
0051
dataframe数据分析常用操作汇总

dataframe的常用操作汇总目录1.建 12.读 23.存 24.阅 25.取 26.改 47.增 48.删 59.并 510.序 7 1.建创建只有一列的数据框 df =…

Python 2023年8月17日
0054
使用JsonConverter处理上传文件的路径

我们上传一个文件，把文件保存到服务器上，会有一个明确的物理路径，由于需要从前端访问这个文件，还需要web服务器中的一个虚拟路径。这个虚拟路径的存储会有一个问题，我们应该在数据库里存…

Python 2023年10月11日
0041
灰色预测模型——Python

GM(1,1) 预测模型原理步骤 Step1: 数据检验和处理设参考数列为 (x^{(0)} = (x^{(0)}(1),x^{(0)}(2),\cdots,x^{(0)}(n…

Python 2023年6月9日
0096
Mybatis-Plus开发提速器mybatis-plus-generator-ui

前言在基于Mybatis的开发模式中，很多开发者还会选择Mybatis-Plus来辅助功能开发，以此提高开发的效率。虽然Mybatis也有代码生成的工具，但Mybatis-Plu…

Python 2023年10月24日
0041
Django学习笔记（Part1-简介）

说明：1.笔记来源于B站up主达内官方和千锋教育的教学视频、一些书籍以及自己的总结2.Django官方参考文档：https://docs.djangoproject.com/zh-…

Python 2023年8月6日
0066
一、pytest安装和使用

pip install pytest pytest –version 1、用例文件：所有文件名为 test_ 开头或者 _test 开头的文件会被识别为用例文件。 2、用例类：…

Python 2023年9月9日
0054
【数字图像处理】实验二图像增强（MATLAB实现）

目录一、实验意义及目的二、实验内容三、Matlab 相关函数介绍四、算法原理五、参考代码及扩展代码流程图（1）参考代码流程图（2）扩展代码流程图六、参考代码七、实…

Python 2023年8月1日
0046
django配置静态资源和媒体资源

在项目下，新建文件夹pstatic存放静态资源，新建文件夹media存放媒体资源。静态资源的配置分别由配置属性STATIC_URL,STATICFILES_DIRS和STATIC…

Python 2023年8月4日
0059
django基于python的水果销售系统–python-计算机毕业设计

项目介绍系统权限按管理员，用户和门店这三类涉及用户划分。(a) 管理员；管理员使用本系统涉到的功能主要有：首页，个人中心，门店管理，用户管理，商品分类管理，商品信息管理，商品咨询…

Python 2023年8月6日
0073
python爬虫

import numpy as np import pandas as pd import matplotlib.pyplot as plt import seaborn as s…

Python 2023年8月7日
0063
软件设计模式白话文系列（十二）组合模式

1、模式描述组合模式属于结构型模式，把多个对象组成树状结构来表示局部与整体，这样用户可以以 相同的方式对待单个对象和组合对象。需要注意…

Python 2023年10月15日
0087
python测试框架之pytest （二）参数化

一、引言在自动化测试中，一个测试用例对应一个测试点，通常一组测试数据无法完全覆盖测试范围，所以，需要参数化来传递多组数据。pytest的测试用例参数化，使用 @pytest.ma…

Python 2023年9月10日
0046
docker命令之docker build

明天要讲docker file的公开课，正好借此机会，整理下docker 命令的专题 docker build [OPTIONS] PATH | URL | – 通过dockerf…

Python 2023年6月12日
00113
ptorch常用代码梯度篇（梯度裁剪、梯度累积、冻结预训练层等）

在训练比较深或者循环神经网络模型的过程中，我们有可能发生梯度爆炸的情况，这样会导致我们模型训练无法收敛。我们可以采取一个简单的策略来避免梯度的爆炸，那就是梯度截断 Clip, …

Python 2023年10月28日
0050
Flask——使用sqlalchemy的配置

flask对mysql数据库的操作要预先安装mysql数据库，安装的方法可以参考以下博主的文章：https://blog.csdn.net/zhouzezhou/article/d…

Python 2023年8月11日
0036

2024 年 5 月
一	二	三	四	五	六	日
		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