You are viewing a plain text version of this content. The canonical link for it is here.
Posted to hdfs-issues@hadoop.apache.org by "Manoj Govindassamy (JIRA)" <ji...@apache.org> on 2016/08/24 01:14:21 UTC
[jira] [Comment Edited] (HDFS-10780) Block replication not
happening on removing a volume when data being written to a datanode --
TestDataNodeHotSwapVolumes fails
[ https://issues.apache.org/jira/browse/HDFS-10780?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15433995#comment-15433995 ]
Manoj Govindassamy edited comment on HDFS-10780 at 8/24/16 1:14 AM:
--------------------------------------------------------------------
*Summary:*
-- I can see an issue in the current code where by the NameNode can miss out permantnetly to replicate a block to a DataNode.
-- If the write pipeline doesn’t have enough DataNodes to match the expected replication factor, then NameNode schedules replication of the block moments after the block has been COMMITTED or COMPLETED. But, if the block COMMIT at NameNode arrives/happens after all BlockManager::addStoredBlock() (happens when processing block reports from DataNodes in the current write pipeline) then NameNode totally misses out to replicate the block because of the way it manages the {{LowRedundancyBlocks}} and {{PendingReconstructionBlocks}}.
*Details:*
Here are the events and their rough timeline order I noticed in one of the failures.
1. Say the setup has 3 DataNodes ( DN(1..3) ) and the replication factor configured to be 3
2. Client is writing a block (BLK_xyz_GS1) with the constructed pipeline DN1 —> DN2 —> DN3
3. Say DN1 encounters an issue (like downstream communication, or interrupts or storage volume issue etc.,) before the block is FINALIZED
4. Client detects the pipeline issue and gets a new write pipeline DN2 —> DN3
5. Generation stamp for the current block is bumped up (BLK_xyz_GS2)
6. Client write (BLK_xyz_GS2) to DN2 and DN3
7. NameNode (NN) is getting Incremental Block Reports (IBR) from DN1, DN2 and DN3
8. NN sees a mix of (BLK_xyz_GS1) and (BLK_xyz_GS2) in IBRs from DN1, DN2 and DN3
9. NN marks (BLK_xyz_GS1) as corrupted and puts these DNs in invalidation list to remove that particular block
10. After seeing the first BLK_xyz_GS2 from one the DNs (say DN2)
— — NN adds BLK_xyz_GS2 to the respective {{DatanodeStorageInfo}} (Refer: {{BlockManager::addStoredBlock}} )
— — Since BLK_xyz_GS2 is not COMMITTED from the Client yet, NN cannot move BLK_xyz_GS2 to COMPLETE state
— — NN does not update the {{LowRedundancyBlocks}} neededReconstruction as it is done only after BLK_xyz_GS2 is COMMITTED by the Client
11. NN sees BLK_xyz_GS2 from the other DN (DN3)
— — NN adds BLK_xyz_GS2
— — At NN, BLK_xyz_GS2 is still in UNDER_CONSTRUCTION state as the Client has not COMMITTED yet. So, neededReconstruction is still not updated.
12. At this point, for BLK_xyz_GS2 the live replica count is 2 and the expected replica count is 3.
— — For the {{ReplicationMonitor}} to pick up a replica work, the intention must be available in {{LowRedundancyBlocks}} neededReconstruction
— — Since no event triggered the addition of intention yet, no block replication work scheduled yet to the missing DN1
13. Client closes the file
— — NN moves the block to COMMITTED state
— — Since there are already 2 love copies of the block, NN moves the block to COMPLETED state
— — But, before moving the block to COMPLETED state, NN does something like below
{{BlockManager.java}}
{noformat}
public boolean commitOrCompleteLastBlock(BlockCollection bc,
Block commitBlock) throws IOException {
...
final boolean committed = commitBlock(lastBlock, commitBlock);
if (committed && lastBlock.isStriped()) {
...
if (hasMinStorage(lastBlock)) {
if (committed) {
//XXX: Is adding to {{PendingReconstructionBlocks}} list without adding to
// {{LowRedundancyBlocks}} list right ?
// This fakes block replication task in progress without even
// any {{BlockReconstructionWork}} scheduled.
addExpectedReplicasToPending(lastBlock);
}
completeBlock(lastBlock, false);
}
...
}
{noformat}
— — Since the block is added the {{pendingReconstruction}} list without any actual reconstruction work, the follow on {{checkRedundancy}} mistakenly believes that there is sufficient redundancy for the block and does not trigger any further block reconstruction works.
{noformat}
839 2016-08-23 10:57:21,450 [IPC Server handler 4 on 57980] INFO blockmanagement.BlockManager (BlockManager.java:checkRedundancy(4046)) - CheckRedun Block: blk_1073741825_1002, exp: 3, replica: *LIVE=2*, READONLY=0, DECOMMISSIONING=0, DECOMMISSIONED=0, CORRUPT=0, EXCESS=0, STALESTORAGE= 0, REDUNDANT=0, *pending: 1*
840 2016-08-23 10:57:21,451 [IPC Server handler 4 on 57980] INFO blockmanagement.BlockManager (BlockManager.java:hasEnoughEffectiveReplicas(1685)) - Blk: blk_1073741825_1002, numEffectiveReplicas: 3, required: 3, pendingReplicaNum: 1, placementPolicy: true
{noformat}
— — {{ReplicationMonitor}} which runs once in every 3 seconds, is also unable to help here as {{LowRedundancyBlocks}} list {{neededReplication}} is empty.
— — So the test fails with following signature
{noformat}
Running org.apache.hadoop.hdfs.server.datanode.TestDataNodeHotSwapVolumes
Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 44.057 sec <<< FAILURE! - in org.apache.hadoop.hdfs.serv
testRemoveVolumeBeingWritten(org.apache.hadoop.hdfs.server.datanode.TestDataNodeHotSwapVolumes) Time elapsed: 43.927 se
java.util.concurrent.TimeoutException: Timed out waiting for /test to reach 3 replicas
Results :
Tests in error:
TestDataNodeHotSwapVolumes.testRemoveVolumeBeingWritten:637->testRemoveVolumeBeingWrittenForDatanode:714 » Timeout
Tests run: 1, Failures: 0, Errors: 1, Skipped: 0
[INFO] Apache Hadoop HDFS Client .......................... SUCCESS [ 2.345 s]
[INFO] Apache Hadoop HDFS ................................. FAILURE [ 45.878 s]
[INFO] BUILD FAILURE
[INFO] Total time: 48.995 s
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:2.17:test (default-test) on project hadoop
{noformat}
was (Author: manojg):
*Summary:*
-- I can see an issue in the current code where by the NameNode can miss out permantnetly to replicate a block to a DataNode.
-- If the write pipeline doesn’t have enough DataNodes to match the expected replication factor, then NameNode schedules replication of the block moments after the block has been COMMITTED or COMPLETED. But, if the block COMMIT at NameNode arrives/happens after all BlockManager::addStoredBlock() (happens when processing block reports from DataNodes in the current write pipeline) then NameNode totally misses out to replicate the block because of the way it manages the {[LowRedundancyBlocks}} and {{PendingReconstructionBlocks}}.
*Details:*
Here are the events and their rough timeline order I noticed in one of the failures.
1. Say the setup has 3 DataNodes ( DN(1..3) ) and the replication factor configured to be 3
2. Client is writing a block (BLK_xyz_GS1) with the constructed pipeline DN1 —> DN2 —> DN3
3. Say DN1 encounters an issue (like downstream communication, or interrupts or storage volume issue etc.,) before the block is FINALIZED
4. Client detects the pipeline issue and gets a new write pipeline DN2 —> DN3
5. Generation stamp for the current block is bumped up (BLK_xyz_GS2)
6. Client write (BLK_xyz_GS2) to DN2 and DN3
7. NameNode (NN) is getting Incremental Block Reports (IBR) from DN1, DN2 and DN3
8. NN sees a mix of (BLK_xyz_GS1) and (BLK_xyz_GS2) in IBRs from DN1, DN2 and DN3
9. NN marks (BLK_xyz_GS1) as corrupted and puts these DNs in invalidation list to remove that particular block
10. After seeing the first BLK_xyz_GS2 from one the DNs (say DN2)
— — NN adds BLK_xyz_GS2 to the respective {{DatanodeStorageInfo}} (Refer: {{BlockManager::addStoredBlock}} )
— — Since BLK_xyz_GS2 is not COMMITTED from the Client yet, NN cannot move BLK_xyz_GS2 to COMPLETE state
— — NN does not update the {{LowRedundancyBlocks}} neededReconstruction as it is done only after BLK_xyz_GS2 is COMMITTED by the Client
11. NN sees BLK_xyz_GS2 from the other DN (DN3)
— — NN adds BLK_xyz_GS2
— — At NN, BLK_xyz_GS2 is still in UNDER_CONSTRUCTION state as the Client has not COMMITTED yet. So, neededReconstruction is still not updated.
12. At this point, for BLK_xyz_GS2 the live replica count is 2 and the expected replica count is 3.
— — For the {{ReplicationMonitor}} to pick up a replica work, the intention must be available in {{LowRedundancyBlocks}} neededReconstruction
— — Since no event triggered the addition of intention yet, no block replication work scheduled yet to the missing DN1
13. Client closes the file
— — NN moves the block to COMMITTED state
— — Since there are already 2 love copies of the block, NN moves the block to COMPLETED state
— — But, before moving the block to COMPLETED state, NN does something like below
{{BlockManager.java}}
{noformat}
public boolean commitOrCompleteLastBlock(BlockCollection bc,
Block commitBlock) throws IOException {
...
final boolean committed = commitBlock(lastBlock, commitBlock);
if (committed && lastBlock.isStriped()) {
...
if (hasMinStorage(lastBlock)) {
if (committed) {
//XXX: Is adding to {{PendingReconstructionBlocks}} list without adding to
// {{LowRedundancyBlocks}} list right ?
// This fakes block replication task in progress without even
// any {{BlockReconstructionWork}} scheduled.
addExpectedReplicasToPending(lastBlock);
}
completeBlock(lastBlock, false);
}
...
}
{noformat}
— — Since the block is added the {{pendingReconstruction}} list without any actual reconstruction work, the follow on {{checkRedundancy}} mistakenly believes that there is sufficient redundancy for the block and does not trigger any further block reconstruction works.
{noformat}
839 2016-08-23 10:57:21,450 [IPC Server handler 4 on 57980] INFO blockmanagement.BlockManager (BlockManager.java:checkRedundancy(4046)) - CheckRedun Block: blk_1073741825_1002, exp: 3, replica: *LIVE=2*, READONLY=0, DECOMMISSIONING=0, DECOMMISSIONED=0, CORRUPT=0, EXCESS=0, STALESTORAGE= 0, REDUNDANT=0, *pending: 1*
840 2016-08-23 10:57:21,451 [IPC Server handler 4 on 57980] INFO blockmanagement.BlockManager (BlockManager.java:hasEnoughEffectiveReplicas(1685)) - Blk: blk_1073741825_1002, numEffectiveReplicas: 3, required: 3, pendingReplicaNum: 1, placementPolicy: true
{noformat}
— — {{ReplicationMonitor}} which runs once in every 3 seconds, is also unable to help here as {{LowRedundancyBlocks}} list {{neededReplication}} is empty.
— — So the test fails with following signature
{{noformat}}
Running org.apache.hadoop.hdfs.server.datanode.TestDataNodeHotSwapVolumes
Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 44.057 sec <<< FAILURE! - in org.apache.hadoop.hdfs.serv
testRemoveVolumeBeingWritten(org.apache.hadoop.hdfs.server.datanode.TestDataNodeHotSwapVolumes) Time elapsed: 43.927 se
java.util.concurrent.TimeoutException: Timed out waiting for /test to reach 3 replicas
Results :
Tests in error:
TestDataNodeHotSwapVolumes.testRemoveVolumeBeingWritten:637->testRemoveVolumeBeingWrittenForDatanode:714 » Timeout
Tests run: 1, Failures: 0, Errors: 1, Skipped: 0
[INFO] Apache Hadoop HDFS Client .......................... SUCCESS [ 2.345 s]
[INFO] Apache Hadoop HDFS ................................. FAILURE [ 45.878 s]
[INFO] BUILD FAILURE
[INFO] Total time: 48.995 s
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:2.17:test (default-test) on project hadoop
{{noformat}}
> Block replication not happening on removing a volume when data being written to a datanode -- TestDataNodeHotSwapVolumes fails
> ------------------------------------------------------------------------------------------------------------------------------
>
> Key: HDFS-10780
> URL: https://issues.apache.org/jira/browse/HDFS-10780
> Project: Hadoop HDFS
> Issue Type: Bug
> Components: hdfs
> Affects Versions: 3.0.0-alpha1
> Reporter: Manoj Govindassamy
> Assignee: Manoj Govindassamy
>
> TestDataNodeHotSwapVolumes occasionally fails in the unit test testRemoveVolumeBeingWrittenForDatanode. Data write pipeline can have issues as there could be timeouts, data node not reachable etc, and in this test case it was more of induced one as one of the volumes in a datanode is removed while block write is in progress. Digging further in the logs, when the problem happens in the write pipeline, the error recovery is not happening as expected leading to block replication never catching up.
> Running org.apache.hadoop.hdfs.server.datanode.TestDataNodeHotSwapVolumes
> Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 44.495 sec <<< FAILURE! - in org.apache.hadoop.hdfs.serv
> testRemoveVolumeBeingWritten(org.apache.hadoop.hdfs.server.datanode.TestDataNodeHotSwapVolumes) Time elapsed: 44.354 se
> java.util.concurrent.TimeoutException: Timed out waiting for /test to reach 3 replicas
> Results :
> Tests in error:
> TestDataNodeHotSwapVolumes.testRemoveVolumeBeingWritten:637->testRemoveVolumeBeingWrittenForDatanode:714 » Timeout
> Tests run: 1, Failures: 0, Errors: 1, Skipped: 0
> Following exceptions are not expected in this test run
> {noformat}
> 614 2016-08-10 12:30:11,269 [DataXceiver for client DFSClient_NONMAPREDUCE_-640082112_10 at /127.0.0.1:58805 [Receiving block BP-1852988604-172.16.3.66-1470857409044:blk_1073741825_1001]] DEBUG datanode.Da taNode (DataXceiver.java:run(320)) - 127.0.0.1:58789:Number of active connections is: 2
> 615 java.lang.IllegalMonitorStateException
> 616 at java.lang.Object.wait(Native Method)
> 617 at org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsVolumeList.waitVolumeRemoved(FsVolumeList.java:280)
> 618 at org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl.removeVolumes(FsDatasetImpl.java:517)
> 619 at org.apache.hadoop.hdfs.server.datanode.DataNode.removeVolumes(DataNode.java:832)
> 620 at org.apache.hadoop.hdfs.server.datanode.DataNode.removeVolumes(DataNode.java:798)
> {noformat}
> {noformat}
> 720 2016-08-10 12:30:11,287 [DataNode: [[[DISK]file:/Users/manoj/work/ups-hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1/, [DISK]file:/Users/manoj/work/ups-hadoop/hadoop-hdfs-projec t/hadoop-hdfs/target/test/data/dfs/data/data2/]] heartbeating to localhost/127.0.0.1:58788] ERROR datanode.DataNode (BPServiceActor.java:run(768)) - Exception in BPOfferService for Block pool BP-18529 88604-172.16.3.66-1470857409044 (Datanode Uuid 711d58ad-919d-4350-af1e-99fa0b061244) service to localhost/127.0.0.1:58788
> 721 java.lang.NullPointerException
> 722 at org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl.getBlockReports(FsDatasetImpl.java:1841)
> 723 at org.apache.hadoop.hdfs.server.datanode.BPServiceActor.blockReport(BPServiceActor.java:336)
> 724 at org.apache.hadoop.hdfs.server.datanode.BPServiceActor.offerService(BPServiceActor.java:624)
> 725 at org.apache.hadoop.hdfs.server.datanode.BPServiceActor.run(BPServiceActor.java:766)
> 726 at java.lang.Thread.run(Thread.java:745)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: hdfs-issues-unsubscribe@hadoop.apache.org
For additional commands, e-mail: hdfs-issues-help@hadoop.apache.org