2015年6月23日重启失败原因及解决方案

一、现象描述

      2015年6月23日由于NameNode设置的内存快要达到现有元数据使用内存的上限,为了增加内存jvm 参数,对NameNode进行了重启,为了保证业务不受影响,采用了fail over的方式。

      首先切换ns1 nn1为Standby NameNode,然后切换ns1 nn2 为Active NameNode,时间在16:50分左右,之后用户的操作基本正常,随后重启ns1 nn1并将堆内存调至100G,在18:13分左右将ns1 nn2切换为Standby NameNode,将ns1 nn1重新切换为Active NameNode。但是,在这一切换过程中,nn2的切换没有成功,直接被kill掉,随后nn1切换为Active NameNode,但是用户的响应非常慢,jstack后定位了相应的问题后,随后打开了debug日志,发现了大量的如下日志:

      BLOCK* rescanPostponedMisreplicatedBlocks: Re-scanned block ****, result is POSTPONE

      查看了代码路径发现了是每个磁盘的Block Report之后都会扫描这个结构,当时postpone结构里有70万个block,相当于每台机器block report都要扫70万*12(磁盘数)的block,并且还要从blockMap中进行查询,相当费时,甚至一个blockreport要到几秒级别,严重占据了写锁,导致了用户响应极慢。

      为了解决这一问题,我们重启了NameNode和DataNode,每次重启100台DataNode,但是这次遇到的是Java GC 风暴,最后的解决是每次重启25台,起了相当长时间才启动完成。

 

二、问题原因

      出现这一问题不是单一一个原因导致的,是多个因素混杂在一起触发了这一严重的问题。

      (一)POSTPONE问题

       前面已经说明每次Block Report都会扫描postpone结构,如果里面block过多就会导致了响应变慢。Block放入postpone结构的原因如下。

      首先看一下fail over的代码路径和行为:

      1、ns1 fail over到ns2后,ns2会将所有DataNode标记为stale状态,处于stale状态的

      2、处于stale状态storage的blocks无法删除,只能放到postpone结构中,等到DataNode标记不是stale状态后,才会从postpone结构去掉,放到invalidate结构中,等待heartbeat到来删除

Bug1

      3、然而由于代码的问题,fail over后重启的NameNode即nn1需要两次block report才能将datanode storageinfo状态置为正常状态。代码如下:

Bug2

      首先,重启nn后所有的状态都是false,对于DataNode,向NameNode发送心跳后会得到reregister的命令,stale状态改变需要heartbeat进行过一次,同时blockreport进行过一次,然而,reregister首先会进行blockreport,随后才会进行heartbeat,导致了第一次blockreport不会将stale状态恢复,由于我们集群blockreport时间设置为6个小时,这就导致了6个小时postpone不断增加。

      4、POSTPONE block产生的原因

      有如下几个原因产生了POSTPONE:

      (1)balancer导致的,由于balancer过后要invalidate多余的block,但是处于postpone无法删除

      (2)随着Block report的时间由于postpone block过多导致的增长,会有个别DataNode由于心跳汇报原因超时,导致了NameNode replicate对应的blocks,心跳正常后这些blocks就处于POSTPONE队列中

      (3)错误的将之前已经停机的DataNode重启,新加入的blocks基本上都添加到了postpone结构中

      5、除此之外在failover过程中有一次大的删除操作,fail over到nn1后,nn1有大量的BLOCK* processReport: block**** on node**** size**** does not belong to any file. 日志,这条日志是在写锁中,大概将近百万,也会加重占写锁的时间

      (二)Block Report GC Storm问题

      随后在重启NameNode和DataNode的过程中,我们遇到的是另一个问题,被叫做Block Report GC风暴。虽然将NameNode内存设置为100G,但是如果DataNode基本在同一时间内进行BlockReport,势必将新生代很快占满,随后将新生代移入老年代后failed,进行一次非常长的full gc,日志如下:

Bug3

Bug4

      GC时间接近400秒,甚至到500秒,这样的时间会导致dn的block report和hearbeat超时,超时后直接重试引起了接近雪崩效应的现象。

 

三、问题解决

      (一)POSTPONE问题

      引入如下patch,解决postpone问题:

      1、https://issues.apache.org/jira/browse/HDFS-7980IBR在NN重启后没有进入快速加块代码路径

      2、https://issues.apache.org/jira/browse/HDFS-7503blockreport中在锁中如果之前删除大目录,会打大量的日志

      3、https://issues.apache.org/jira/browse/HDFS-6772DataNode reregister逻辑问题导致的content stale 持续两个block report

      4、https://issues.apache.org/jira/browse/HDFS-6425Postpone逻辑移除出BR,而在后台进行

      5、https://issues.apache.org/jira/browse/HDFS-6830blockInfo逻辑问题导致的删除indoe而出现的npe异常

 

     (二)Block Report GC storm问题

     1、根据统计每个磁盘大概5万个块的Block Report时间大概为50msec,一台机器大概0.6s,对于我们1000台机器设置每台机器的随机延时时间为0.6*1000=600s=10min即可

     2、配置ipc.server.read.threadpool.size 为10,是Server rpc reader线程变为10个

     3、配置dfs.namenode.servicerpc-address 将client与NN的rpc请求与DN与NN的请求进行分离,虽然可能对这次没有太多的帮助,但是据其它公司测试,性能大概提升20%

近期值得关注的patch-hdfs层

    最近对namenode做了次failover,简直是惨痛的经历,稍后会补充细节,以下列出hdfs层近期值得关注的patch,如果版本没有达到2.6+,请打如下patch。

 

https://issues.apache.org/jira/browse/HDFS-7980

https://issues.apache.org/jira/browse/HDFS-7503

https://issues.apache.org/jira/browse/HDFS-6833

https://issues.apache.org/jira/browse/HDFS-6772

https://issues.apache.org/jira/browse/HDFS-6425       

https://issues.apache.org/jira/browse/HDFS-6830