Hadoop 减轻Block Report风暴方法(HDFS Block Report Storm)

对于大的Hadoop集群,停机运维后最大的挑战就是Block Report风暴问题,所谓的Block Report风暴就是在NameNode重启后,会有大量的DataNode来汇报Block,来构建NameNode内部的数据结构,包括Block 和DataNode的映射,DataNode包含的所有Block等等。这块是NameNode内存占用的比较大的一部分,另外,大量的DataNode汇报,往往伴随了直接进入老年代,造成GC或者DataNode Block report反映不及时,超过30s socket时间。NameNode甚至在处理这个Block Report的中途,中断了连接,白白耗费了写锁,而DataNode端会休息一段时间重新发起Block report,如此往复,造成了雪崩效果。这就是所谓的HDFS block report风暴。
为了解决这一个问题,社区引入了一个参数dfs.blockreport.split.threshold,默认是100万,如果单机Block数量在100万以下,那么block report会封装成一个RPC,也就是只有一次RPC发送。而如果超过了这个阈值,在DN端这个逻辑是将一个大的block report切分到单盘去做,如果单盘中有一块盘超时,在重新做全部的盘的block report。原理上说这将会降低造成block report的风险和加快重启过程。我做了一个简单的测试,来验证效果。
首先通过阿里云 EMR 购买了一个集群,集群配置如下:
使用30台D1集群:
NameNode 16核 128G
DataNode 32核 128G 5.5T * 12
然后灌入数据,最后灌入了232290855 files and directories, 215077946 blocks = 447368801 total filesystem object(s).
DataNode单机的Block数量在2000万左右。
数据灌完后,重启NameNode,Image Load时间大概是23分钟。
经过计算,大概一次的Block Report时间会在30s左右,所以一次Block Report的RPC大概率会造成Socket timeout。
1.如果将dfs.blockreport.split.threshold设置成1亿条。
NameNode重启后, DataNode一把汇报所有report

2019-11-11 10:51:49,910 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Unsuccessfully sent block report 0x17b00cec3b356,  containing 12 storage report(s), of which we sent 0. The reports had 21507382 total blocks and used 0 RPC(s). This took 4263 msec to generate and 435410 msecs for RPC and NN processing. Got back no commands.
2019-11-11 10:55:02,672 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Unsuccessfully sent block report 0x17b8514c85fdf,  containing 12 storage report(s), of which we sent 0. The reports had 21507382 total blocks and used 0 RPC(s). This took 4175 msec to generate and 60061 msecs for RPC and NN processing. Got back no commands.
2019-11-11 11:52:57,836 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Unsuccessfully sent block report 0x17ebc082c478e,  containing 12 storage report(s), of which we sent 0. The reports had 21507382 total blocks and used 0 RPC(s). This took 5277 msec to generate and 678 msecs for RPC and NN processing. Got back no commands.
2019-11-11 13:26:17,754 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Unsuccessfully sent block report 0x183dfe776d467,  containing 12 storage report(s), of which we sent 0. The reports had 21426179 total blocks and used 0 RPC(s). This took 5238 msec to generate and 542 msecs for RPC and NN processing. Got back no commands.
2019-11-11 13:26:23,126 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Unsuccessfully sent block report 0x183e1265a5171,  containing 12 storage report(s), of which we sent 0. The reports had 21426179 total blocks and used 0 RPC(s). This took 5367 msec to generate and 563 msecs for RPC and NN processing. Got back no commands.
2019-11-11 13:26:28,440 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Unsuccessfully sent block report 0x183e26411ce59,  containing 12 storage report(s), of which we sent 0. The reports had 21426179 total blocks and used 0 RPC(s). This took 5347 msec to generate and 547 msecs for RPC and NN processing. Got back no commands.
2019-11-11 13:26:33,719 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Unsuccessfully sent block report 0x183e3a2783dc1,  containing 12 storage report(s), of which we sent 0. The reports had 21426179 total blocks and used 0 RPC(s). This took 5359 msec to generate and 484 msecs for RPC and NN processing. Got back no commands.
2019-11-11 13:26:38,967 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Unsuccessfully sent block report 0x183e4db86a462,  containing 12 storage report(s), of which we sent 0. The reports had 21426179 total blocks and used 0 RPC(s). This took 5269 msec to generate and 480 msecs for RPC and NN processing. Got back no commands.

经过了3个小时,也没有汇报成功。

2.将dfs.blockreport.split.threshold设置成100万条.

2019-11-11 14:18:15,588 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Unsuccessfully sent block report 0x18695e8fff624,  containing 12 storage report(s), of which we sent 2. The reports had 21426179 total blocks and used 2 RPC(s). This took 10670 msec to generate and 137642 msecs for RPC and NN processing. Got back no commands.
2019-11-11 14:20:04,027 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Unsuccessfully sent block report 0x186c1389c74b2,  containing 12 storage report(s), of which we sent 0. The reports had 21426179 total blocks and used 0 RPC(s). This took 5248 msec to generate and 60062 msecs for RPC and NN processing. Got back no commands.
2019-11-11 14:20:13,913 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Unsuccessfully sent block report 0x186bf29b0ccc7,  containing 12 storage report(s), of which we sent 2. The reports had 21426179 total blocks and used 2 RPC(s). This took 5339 msec to generate and 78788 msecs for RPC and NN processing. Got back no commands.
2019-11-11 14:23:29,457 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Unsuccessfully sent block report 0x186e125f12a27,  containing 12 storage report(s), of which we sent 4. The reports had 21426179 total blocks and used 4 RPC(s). This took 5219 msec to generate and 128366 msecs for RPC and NN processing. Got back no commands.
2019-11-11 14:32:14,183 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Unsuccessfully sent block report 0x18745b6b058ae,  containing 12 storage report(s), of which we sent 6. The reports had 21426179 total blocks and used 6 RPC(s). This took 5107 msec to generate and 221167 msecs for RPC and NN processing. Got back no commands.
2019-11-11 14:36:13,401 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Unsuccessfully sent block report 0x18778e2f96d16,  containing 12 storage report(s), of which we sent 6. The reports had 21426179 total blocks and used 6 RPC(s). This took 5229 msec to generate and 240599 msecs for RPC and NN processing. Got back no commands.
2019-11-11 14:36:43,543 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Successfully sent block report 0x187825e7cb772,  containing 12 storage report(s), of which we sent 12. The reports had 21426179 total blocks and used 12 RPC(s). This took 5510 msec to generate and 230014 msecs for RPC and NN processing. Got back no commands.

大概经历20分钟,汇报成功。再经过10分钟左右,心跳正常,能够正常提供服务。大概重启时间20+10+20,在1小时左右。大大缩短了时间。
经过测试,通过调整fs.blockreport.split.threshold 是有效的减少br风暴影响,加快汇报速度的方法。

DataXceiver本地读异常bug说明(HDFS-11802)

现象描述

用户在读取文件的时候报三台DN都无法取得该文件对应的block,经过fsck检查后没有发现该文件有丢块现象,到对应的dn上去查看日志,发现三台机器已经都处于不可读状态,报错为

2015-11-25 00:01:55,999 WARN org.apache.hadoop.hdfs.server.datanode.DataNode: 10.39.5.160:50010:DataXceiverServer:
java.io.IOException: Xceiver count 4097 exceeds the limit of concurrent xcievers: 4096
    at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:137)
    at java.lang.Thread.run(Thread.java:745)

很明显,这是超过了dataxceiver设置的最大的线程数4096,正常情况下是不可能超过的,所以说明dn有线程泄露的bug或者其它问题。
再检查日志,发现了以下的日志

Exception in thread "Thread-19" java.lang.IllegalStateException: failed to remove c53ce04928d1baa854f5dc1bfc8d565b
    at com.google.common.base.Preconditions.checkState(Preconditions.java:145)
    at org.apache.hadoop.hdfs.server.datanode.ShortCircuitRegistry.removeShm(ShortCircuitRegistry.java:115)
    at org.apache.hadoop.hdfs.server.datanode.ShortCircuitRegistry$RegisteredShm.handle(ShortCircuitRegistry.java:102)
    at org.apache.hadoop.net.unix.DomainSocketWatcher.sendCallback(DomainSocketWatcher.java:371)
    at org.apache.hadoop.net.unix.DomainSocketWatcher.access$1000(DomainSocketWatcher.java:52)
    at org.apache.hadoop.net.unix.DomainSocketWatcher$1.run(DomainSocketWatcher.java:511)
    at java.lang.Thread.run(Thread.java:745)

看到这个日志以后就大概知道了原因,是由于DomainSocketWatcher线程异常退出,导致本地读线程没有回收机制,占满了所有的dataxceiver slot导致的。

问题原因

DomainSocketWatcher线程负责对本地读线程建立的socket进行一些处理和清理等。出问题的代码为

<code>
      try {
        while (true) {
              doSomecleanup.......
        }
      } catch (InterruptedException e) {
        LOG.info(toString() + " terminating on InterruptedException");
      } catch (IOException e) {
        LOG.error(toString() + " terminating on IOException", e);
      } finally {
        lock.lock();
        try {
          kick(); // allow the handler for notificationSockets[0] to read a byte
          Iterator<Entry> iter = entries.values().iterator();
          while(iter.hasNext()) {
            sendCallback("close", iter, fdSet);
          }
          entries.clear();
          fdSet.close();
        } finally {
          lock.unlock();
        }
      }
</code>

正常情况下代码不会走入到finally,而是一直在while中loop。而报出的异常则是remove一个共享内存对象的时候失败,而导致的运行时异常。
经过jira查询和我们集群中机器日志查看,发现原因为在于Client向DataNode申请本地读时候,DataNode建立共享内存对象以及File Descriptor出现异常,导致分配失败,日志为

2015-11-06 04:52:41,080 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: cliID: DFSClient_attempt_1435099124107_5925361_m_000028_0_1777694543_1, src: 127.0.0.1, dest: 127.0.0.1, op: REQUEST_SHORT_CIRCUIT_SHM, shmId: n/a, srvID: 01f352c6-4e63-4158-8ead-3e8146103b6f, success: false

而在DataXceiver的requestShortCircuitShm代码中,如果失败则close连接

      if ((!success) && (peer == null)) {
        // If we failed to pass the shared memory segment to the client,
        // close the UNIX domain socket now.  This will trigger the 
        // DomainSocketWatcher callback, cleaning up the segment.
        IOUtils.cleanup(null, sock);
      }

但是,所有close操作都是通过回调DomainSocketWatcher来做的,这样,当DomainSocketWatcher再次close的时候内存中的共享内存对象由于已经close被释放,而报runtimeerror,这样DomainSocketWatcher线程异常退出,本地读没有清理线程,慢慢占满了slot,最后导致了DataNode不可用。

解决方法

DataXceiver不负责close连接,而只是负责将与client连接shutdown,使client能够快速反应读异常,同时增加更多的catch,如果后续还有异常能够找到原因。

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

       

DataNode与NameNode通讯

这是我近期做的关于DataNode与NameNode之间通讯的一个简单培训,这也是在查询DataNode动态上下盘时候发现问题时候顺便总结的。关于动态上下盘的Bug会在稍后写一篇文章分享。

DataNode BlockReport bug分析(一)

一、现象描述

       上周2.4集群迁移升级,使用平滑升级将中心机从较差的几台机器迁移到真正的中心机服务器上,升级前原始中心机一切状态都是正常的,不存在丢块等问题,将image等文件拷贝到新集群并启动一起正常,随后将所有DataNode重启,将ns地址换位新中心机节点地址,汇报所有block,猛然发现竟然后18个missing block。回滚后,重新将ns地址位置换位老中心机节点地址,重启所有DataNode发现竟然也有missing block,没有办法只能将ns地址还是换为新中心机地址,重启DataNode,继续向下升级。

       第二天去调查这个问题,可以肯定的是原先中心机内存中blockmap肯定是不正确的,深入调查这个问题,从文件入手,看块的分布,得到了以下情况分(只分析一个文件中的一个block)。

       1、9月30号,block被写入,三个副本,分别写入到A,B,C三台机器,一切正常,pipeline无异常,block 文件写入datanode没有问题,说明在这一时刻没有任何问题。

                                                Miss1

       2、10月10号问题产生了

       机器A  /data10在13:00磁盘损坏,机器B,机器C由于服务器硬件问题,分别在13:57和14:15下线。按照以前的方式,这种方式没有任何问题,每下线一台服务器都会等足够的时间,使namenode将under  replica给repicate出去,保证3副本的稳定性。

       然而机器B、C下线后,namenode一直认为机器A是正常的,并且反复要求机器A去replicate block。A机器由于磁盘损坏,没有该Block反复报错。

                                               Miss2

                                                   Miss3

       至此,该Block丢失,但是NameNode仍然认为机器A保留该块,产生了严重的问题。

 

 

二、产生原因

       首先看一下DataNode BlockReport及Disk Error处理流程。DataNode默认第一次启动以及稍后的每六个小时向NameNode汇报一次全量数据,其它时候只汇报增量数据。

       Block Report流程为: 

       1、BPServiceActor读取每个盘的所有Block数据,包括finalized和underConstrunction

                                         Miss4

       2、如果block过多(超过1M),会按照磁盘分批发送,否则一次发送 

                                          Miss5

一般不会超过1M,所以都是一次发送,但是注意,blockReport方法第三个参数reports是一个数组,表示每个磁盘对应的不同storageId所有的block。

       如果磁盘没有问题的话这个逻辑没有什么问题,但是,假如磁盘除了问题,同时设置了dfs.datanode.failed.volumes.tolerated这个参数,就出现了问题。

       dfs.datanode.failed.volumes.tolerated是DataNode可容忍出错的磁盘数,默认是0,它指的是当磁盘损坏多少块时,DataNode 下线,停止提供服务。在我们集群中,这一参数设置为3,即损失3块磁盘仍然能够提供服务。

       为了继续深入研究这个问题,还需要看一下Disk Error的处理流程。对于Hadoop集群,磁盘损坏是非常正常的,较大的集群一天损坏2、3块盘都是可以忍受的。 

       DataNode当接收或者发送Block出现异常时候都会对磁盘进行检查,检查的方法是

                              Miss6

       随后会对每个磁盘进行检查,首先对出现问题的磁盘从FsVolumeList去掉,同时从内存中Block对应存储的映射volumeMap清除。

随后会立即做一次BlockReport,让NameNode迅速将掉的盘中的Block通过别的机器replicate出去。

 

       NameNode中处理Block Report的主要方法是:

                                                Miss7

       参数解释为dn是当前DataNode,storage对应汇报的磁盘,newReport是该DataNode得对应磁盘汇报的所有block,剩下的是经过diff后需要处理的相应block。

       首先看一下0.20.203版本时期的report: 

                              Miss8

 

       DataNode汇报所有Block,NameNode将汇报的所有Block与内存中数据比较,如果多余内存中数据并且该block属于某个INode,则加入ToAdd中,稍后加入blockMap中;如果不属于任何INode,则加入ToRemove,放入invalidateSet中,稍后让DataNode进行删除。如果内存中数据有汇报不存在的Block,则加入ToRemove中,从blockMap中删除该节点对应Block得映射,同时更新neededBlock,即需要replicate的block列表,随后让其他存有该节点的Block将该block repicate出去。

       然而,2.4中并不是全量进行处理,而是按照磁盘处理,这样处理主要是为了异构存储而设计的。这就出现了问题,由于磁盘故障后该磁盘Volume会被清除,这样就不会汇报该Volume得任何信息了。这个磁盘就不会调用reportDiff去更新NameNode中的数据结构,这样NameNode会一直认为这个节点中其实由于磁盘故障而丢失的Block是一直存在的。就出现了我一开始提到的问题。

HDFS BlockManager chooseExcessReplicates 问题

      近日在做HDFS RAID时发现一个现象,RAID结束后需要调整Block位置,设置副本数为2,使Block尽可能的分散,但是从Raid界面发现,经过很长时间后,Block位置仍然无法满足分散到不同机器上的要求。查看NameNode日志后发现

NewImage

      Block从某个节点copy到另一个节点后,从第二个节点汇报给NameNode,并请求NameNode删除原始节点,但是NameNode并没与删除原始节点,而是直接要求汇报的节点删除该Block。

      通过DEBUG发现,问题出自BlockManager的chooseExcessReplicates方法。

NewImage

      我测试集群只有17台机器,分布在两个机架上,源节点在一个机架上,另一个副本在第二个机架上,拷贝到的也是在第二个机架上。那么上面的判断:moreThanOne指的是大于等于两个副本的机架机器,exactlyOne指的是只有一个副本的机架机器。那么moreThanOne.contains(delNodeHint)肯定是false,因为源节点属于只有一个副本的机架机器。||后面的语句addedNode!=null为true,!moreThanOne.contains(addedNode)为false,由于新添加的节点机架之前已经有一个副本了,所以为非。最后if语句结果为false,这样你即使提供了delNodeHint,指定了一个需要删除的机器,但是根据放置策略,依然不能删除,毕竟Hint只是个提示。

     当然,我的测试集群较小,较大的集群这种情况不太可能发生,另外raid主节点定期去copy,在显示集群中除了Balancer,这种情况也很少发生。