hadoop-hdfs-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Allan Wilson (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (HDFS-7453) Namenode does not recognize block is missing on a datanode
Date Fri, 09 Jan 2015 20:12:35 GMT

    [ https://issues.apache.org/jira/browse/HDFS-7453?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14271809#comment-14271809
] 

Allan Wilson commented on HDFS-7453:
------------------------------------

I see this same behavior in our cluster (Hadoop 2.0.0) CDH4.7.  These are for files with a
replica count of 3.

> Namenode does not recognize block is missing on a datanode
> ----------------------------------------------------------
>
>                 Key: HDFS-7453
>                 URL: https://issues.apache.org/jira/browse/HDFS-7453
>             Project: Hadoop HDFS
>          Issue Type: Bug
>          Components: namenode
>    Affects Versions: 2.4.1
>            Reporter: Dmitry Bugaychenko
>            Priority: Critical
>
> We got a severe datalose due to the fact that namenode didn't recognized block it thinks
exist are not actually exist on the datanodes. The senario is something as follows:
> # A disk fails on one of the datanodes
> # The datanode is forced to decommiss and shut down
> # The disk is replaced and datanode is back again
> # fsck shows everything is fine
> # Repeat 1-4 for few weeks
> # Restart the namenode
> # It suddenly sees tens of thousands under-replicated blocks and hundreds missing blocks
> During the next disk failure we analysed situation a bit more and found particular block
on particular datanode that is missing: there is no file for block and if we try to read it,
we got
> {code}
> java.io.IOException: Got error for OP_READ_BLOCK, self=/XXX:33817, remote=XXX/X.X.X.X:50010,
for file XXX/X.X.X.X:50010:BP-879324367-YYY-1404837025894:1083356878, for pool BP-879324367-YYY-1404837025894
block 1083356878_9644290
> {code}
> We restarted the datanode and in the log we can see that it did scan all the directories
and send the report to namenode:
> {code}
> 2014-11-27 17:06:34,174  INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/, [DISK]file:/mnt/hadoop/1/dfs/data/,
[DISK]file:/mnt/hadoop/2/dfs/data/]]  heartbeating to /YYY:8020] FsDatasetImpl - Adding block
pool BP-879324367-YYY-1404837025894
> 2014-11-27 17:06:34,175  INFO [Thread-41] FsDatasetImpl - Scanning block pool BP-879324367-YYY-1404837025894
on volume /mnt/hadoop/0/dfs/data/current...
> 2014-11-27 17:06:34,176  INFO [Thread-43] FsDatasetImpl - Scanning block pool BP-879324367-YYY-1404837025894
on volume /mnt/hadoop/2/dfs/data/current...
> 2014-11-27 17:06:34,176  INFO [Thread-42] FsDatasetImpl - Scanning block pool BP-879324367-YYY-1404837025894
on volume /mnt/hadoop/1/dfs/data/current...
> 2014-11-27 17:06:34,279  INFO [Thread-42] FsDatasetImpl - Cached dfsUsed found for /mnt/hadoop/1/dfs/data/current/BP-879324367-YYY-1404837025894/current:
62677866794
> 2014-11-27 17:06:34,282  INFO [Thread-42] FsDatasetImpl - Time taken to scan block pool
BP-879324367-YYY-1404837025894 on /mnt/hadoop/1/dfs/data/current: 105ms
> 2014-11-27 17:06:34,744  INFO [Thread-41] FsDatasetImpl - Cached dfsUsed found for /mnt/hadoop/0/dfs/data/current/BP-879324367-YYY-1404837025894/current:
2465590681232
> 2014-11-27 17:06:34,744  INFO [Thread-41] FsDatasetImpl - Time taken to scan block pool
BP-879324367-YYY-1404837025894 on /mnt/hadoop/0/dfs/data/current: 568ms
> 2014-11-27 17:06:34,856  INFO [Thread-43] FsDatasetImpl - Cached dfsUsed found for /mnt/hadoop/2/dfs/data/current/BP-879324367-YYY-1404837025894/current:
2475580099468
> 2014-11-27 17:06:34,857  INFO [Thread-43] FsDatasetImpl - Time taken to scan block pool
BP-879324367-YYY-1404837025894 on /mnt/hadoop/2/dfs/data/current: 680ms
> 2014-11-27 17:06:34,857  INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/, [DISK]file:/mnt/hadoop/1/dfs/data/,
[DISK]file:/mnt/hadoop/2/dfs/data/]]  heartbeating to /YYY:8020] 
> 2014-11-27 17:06:34,858  INFO [Thread-44] FsDatasetImpl - Adding replicas to map for
block pool BP-879324367-YYY-1404837025894 on volume /mnt/hadoop/0/dfs/data/current...
> 2014-11-27 17:06:34,890  INFO [Thread-46] FsDatasetImpl - Adding replicas to map for
block pool BP-879324367-YYY-1404837025894 on volume /mnt/hadoop/2/dfs/data/current...
> 2014-11-27 17:06:34,890  INFO [Thread-45] FsDatasetImpl - Adding replicas to map for
block pool BP-879324367-YYY-1404837025894 on volume /mnt/hadoop/1/dfs/data/current...
> 2014-11-27 17:06:34,961  INFO [Thread-45] FsDatasetImpl - Time to add replicas to map
for block pool BP-879324367-YYY-1404837025894 on volume /mnt/hadoop/1/dfs/data/current: 70ms
> 2014-11-27 17:06:36,083  INFO [Thread-44] FsDatasetImpl - Time to add replicas to map
for block pool BP-879324367-YYY-1404837025894 on volume /mnt/hadoop/0/dfs/data/current: 1193ms
> 2014-11-27 17:06:36,162  INFO [Thread-46] FsDatasetImpl - Time to add replicas to map
for block pool BP-879324367-YYY-1404837025894 on volume /mnt/hadoop/2/dfs/data/current: 1271ms
> 2014-11-27 17:06:36,162  INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/, [DISK]file:/mnt/hadoop/1/dfs/data/,
[DISK]file:/mnt/hadoop/2/dfs/data/]]  heartbeating to /YYY:8020] FsDatasetImpl - Total time
to add all replicas to map: 1304ms
> 2014-11-27 17:06:36,167  INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/, [DISK]file:/mnt/hadoop/1/dfs/data/,
[DISK]file:/mnt/hadoop/2/dfs/data/]]  heartbeating to /YYY:8020] DataNode - Block pool BP-879324367-YYY-1404837025894
(Datanode Uuid null) service to /YYY:8020 beginning handshake with NN
> 2014-11-27 17:06:36,167  INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/, [DISK]file:/mnt/hadoop/1/dfs/data/,
[DISK]file:/mnt/hadoop/2/dfs/data/]]  heartbeating to /XXX:8020] DataNode - Block pool BP-879324367-YYY-1404837025894
(Datanode Uuid null) service to /XXX:8020 beginning handshake with NN
> 2014-11-27 17:06:36,185  INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/, [DISK]file:/mnt/hadoop/1/dfs/data/,
[DISK]file:/mnt/hadoop/2/dfs/data/]]  heartbeating to /YYY:8020] DataNode - Block pool Block
pool BP-879324367-YYY-1404837025894 (Datanode Uuid null) service to /YYY:8020 successfully
registered with NN
> 2014-11-27 17:06:36,185  INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/, [DISK]file:/mnt/hadoop/1/dfs/data/,
[DISK]file:/mnt/hadoop/2/dfs/data/]]  heartbeating to /XXX:8020] DataNode - Block pool Block
pool BP-879324367-YYY-1404837025894 (Datanode Uuid null) service to /XXX:8020 successfully
registered with NN
> 2014-11-27 17:06:36,186  INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/, [DISK]file:/mnt/hadoop/1/dfs/data/,
[DISK]file:/mnt/hadoop/2/dfs/data/]]  heartbeating to /YYY:8020] DataNode - For namenode /YYY:8020
using DELETEREPORT_INTERVAL of 300000 msec  BLOCKREPORT_INTERVAL of 21600000msec CACHEREPORT_INTERVAL
of 10000msec Initial delay: 0msec; heartBeatInterval=3000
> 2014-11-27 17:06:36,186  INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/, [DISK]file:/mnt/hadoop/1/dfs/data/,
[DISK]file:/mnt/hadoop/2/dfs/data/]]  heartbeating to /XXX:8020] DataNode - For namenode /XXX:8020
using DELETEREPORT_INTERVAL of 300000 msec  BLOCKREPORT_INTERVAL of 21600000msec CACHEREPORT_INTERVAL
of 10000msec Initial delay: 0msec; heartBeatInterval=3000
> 2014-11-27 17:06:36,264  INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/, [DISK]file:/mnt/hadoop/1/dfs/data/,
[DISK]file:/mnt/hadoop/2/dfs/data/]]  heartbeating to /YYY:8020] DataNode - Namenode Block
pool BP-879324367-YYY-1404837025894 (Datanode Uuid 91e8deeb-7030-4e7b-af14-a3f35cf65bd2) service
to /YYY:8020 trying to claim ACTIVE state with txid=114828921
> 2014-11-27 17:06:36,265  INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/, [DISK]file:/mnt/hadoop/1/dfs/data/,
[DISK]file:/mnt/hadoop/2/dfs/data/]]  heartbeating to /YYY:8020] DataNode - Acknowledging
ACTIVE Namenode Block pool BP-879324367-YYY-1404837025894 (Datanode Uuid 91e8deeb-7030-4e7b-af14-a3f35cf65bd2)
service to /YYY:8020
> 2014-11-27 17:06:36,511  INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/, [DISK]file:/mnt/hadoop/1/dfs/data/,
[DISK]file:/mnt/hadoop/2/dfs/data/]]  heartbeating to /XXX:8020] DataNode - Sent 1 blockreports
49708 blocks total. Took 72 msec to generate and 174 msecs for RPC and NN processing.  Got
back commands none
> 2014-11-27 17:06:36,511  INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/, [DISK]file:/mnt/hadoop/1/dfs/data/,
[DISK]file:/mnt/hadoop/2/dfs/data/]]  heartbeating to /YYY:8020] DataNode - Sent 1 blockreports
49708 blocks total. Took 76 msec to generate and 170 msecs for RPC and NN processing.  Got
back commands org.apache.hadoop.hdfs.server.protocol.FinalizeCommand@464c42e6
> 2014-11-27 17:06:36,512  INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/, [DISK]file:/mnt/hadoop/1/dfs/data/,
[DISK]file:/mnt/hadoop/2/dfs/data/]]  heartbeating to /YYY:8020] DataNode - Got finalize command
for block pool BP-879324367-YYY-1404837025894
> 2014-11-27 17:06:36,519  INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/, [DISK]file:/mnt/hadoop/1/dfs/data/,
[DISK]file:/mnt/hadoop/2/dfs/data/]]  heartbeating to /XXX:8020] GSet - Computing capacity
for map BlockMap
> 2014-11-27 17:06:36,523  INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/, [DISK]file:/mnt/hadoop/1/dfs/data/,
[DISK]file:/mnt/hadoop/2/dfs/data/]]  heartbeating to /XXX:8020] GSet - capacity      = 2^20
= 1048576 entries
> 2014-11-27 17:06:36,520  INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/, [DISK]file:/mnt/hadoop/1/dfs/data/,
[DISK]file:/mnt/hadoop/2/dfs/data/]]  heartbeating to /XXX:8020] GSet - VM type       = 64-bit
> 2014-11-27 17:06:36,522  INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/, [DISK]file:/mnt/hadoop/1/dfs/data/,
[DISK]file:/mnt/hadoop/2/dfs/data/]]  heartbeating to /XXX:8020] GSet - 0.5% max memory 1.9
GB = 9.9 MB
> 2014-11-27 17:06:36,524  INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/, [DISK]file:/mnt/hadoop/1/dfs/data/,
[DISK]file:/mnt/hadoop/2/dfs/data/]]  heartbeating to /XXX:8020] BlockPoolSliceScanner - Periodic
Block Verification Scanner initialized with interval 504 hours for block pool BP-879324367-YYY-1404837025894
> {code}
> But block is sitll reported with two replicas, one of those is assigned to datanode which
hasn't it:
> {code}
> <block_info>
> <block_id>1083356878</block_id>
> <block_name>blk_1083356878</block_name>
> <file>
> <local_name>commons-lang-2.6.jar</local_name>
> <local_directory>/user/user/analysis</local_directory>
> <user_name>user</user_name>
> <group_name>supergroup</group_name>
> <is_directory>false</is_directory>
> <access_time>1417094143429</access_time>
> <is_under_construction>false</is_under_construction>
> <ds_quota>-1</ds_quota>
> <permission_status>user:supergroup:rw-r--r--</permission_status>
> <replication>2</replication>
> <disk_space_consumed>568440</disk_space_consumed>
> <preferred_block_size>134217728</preferred_block_size>
> </file>
> <replicas>
> <replica>
> <host_name>bad_node</host_name>
> <is_corrupt>false</is_corrupt>
> </replica>
> <replica>
> <host_name>good_node</host_name>
> <is_corrupt>false</is_corrupt>
> </replica>
> </replicas>
> </block_info>
> {code}
> fsck does not change the situation, ony the namenode restart force it to recognize that
block replica as missing.
> As a result it is required to restart namenode after each disk failure which is not very
practical...



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Mime
View raw message