记一次DataNode慢启动问题

前言

最近一段时间,由于机房需要搬迁调整,我们hadoop集群所受到的影响机器无疑是数量最多的,如何能最优的使机器在从1个机房搬到另1个机房之后,对集群的数据和上面跑的业务造成尽可能小的影响或者说几乎没有影响.这就是我们想到达到的目标.但是在实施这整个搬迁的过程中,还是发现了一些比较有意思的现象的,于是就有了如文章标题所描绘的现象,为什么说是"记一次"呢,因为这个现象并不是每次都发生,所以这件事看上去可能就不会那么直接明了了.相信你在看完了文章之后,或多或少会有所收获.

DataNode慢启动现象"场景回放"

首先看到这个子标题,估计有人会有疑问,DataNode还会出现慢启动现象?DataNode执行了sbin/hadoop-daemon.sh start datanode命令后不是几秒钟的事情吗?没有错,在绝大多数的场景下,DataNode的启动就是简单的这么几个步骤.但是不知道大家有没有尝试过如下的情况:

1.停止机器上的DataNode服务.

2.将此节点进行机房搬迁,搬迁后此节点将会拥有新的主机名和IP.

3.在第二步骤的搬迁过程中耗费了20,30分钟甚至长达数小时.

4.重启被更换掉主机名,IP的DataNode.

我在最近一段时间的DataNode迁移中就遇到了上述的场景,(感兴趣的同学可以查看这篇文章DataNode迁移方案)然后在我start新的DataNode之后,就发生了慢启动的现象,在我执行完了脚本之后,我发现NameNode的页面上迟迟没有这个新节点汇报上来的block块记总数信息.我用jps观察这个进程也的确还是在的,直到最后过了4,5分钟之后,页面上终于出现了新DN的记录信息了.然后datanode的log中也出现了block的receive,delete记录了.所以很显然,DataNode在启动的这4,5分钟一定卡在了什么操作上,否则不会出现这么大延时.千万不要小看了这4,5分钟,当你需要在短时间内恢复dn服务的时候,哪怕你多耽搁了1秒钟,影响了别人的使用,人家还是会认为这就是你的问题.既然目标已经锁定在dn启动的头4,5分钟,那么1个好的办法就是先看datanode的log日志,看看他在干嘛.经过多次尝试,我发现dn在每次打完下面这些信息的时候,就会停留相当长的时间.

2016-01-06 16:05:08,118 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Added new volume: DS-70097061-42f8-4c33-ac27-2a6ca21e60d4
2016-01-06 16:05:08,118 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Added volume - /home/data/data/hadoop/dfs/data/data12/current, StorageType: DISK
2016-01-06 16:05:08,176 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Registered FSDatasetState MBean
2016-01-06 16:05:08,177 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Adding block pool BP-1942012336-xx.xx.xx.xx-1406726500544
2016-01-06 16:05:08,178 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Scanning block pool BP-1942012336-xx.xx.xx.xx-1406726500544 on volume /home/data/data/hadoop/dfs/data/data2/current...
2016-01-06 16:05:08,179 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Scanning block pool BP-1942012336-xx.xx.xx.xx-1406726500544 on volume /home/data/data/hadoop/dfs/data/data3/current...
2016-01-06 16:05:08,179 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Scanning block pool BP-1942012336-xx.xx.xx.xx-1406726500544 on volume /home/data/data/hadoop/dfs/data/data4/current...
2016-01-06 16:05:08,179 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Scanning block pool BP-1942012336-xx.xx.xx.xx-1406726500544 on volume /home/data/data/hadoop/dfs/data/data5/current...
2016-01-06 16:05:08,180 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Scanning block pool BP-1942012336-xx.xx.xx.xx-1406726500544 on volume /home/data/data/hadoop/dfs/data/data6/current...
2016-01-06 16:05:08,180 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Scanning block pool BP-1942012336-xx.xx.xx.xx-1406726500544 on volume /home/data/data/hadoop/dfs/data/data7/current...
2016-01-06 16:05:08,180 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Scanning block pool BP-194201