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 "Todd Lipcon (JIRA)" <ji...@apache.org> on 2010/01/23 01:02:21 UTC
[jira] Created: (HDFS-915) Hung DN stalls write pipeline for far
longer than its timeout
Hung DN stalls write pipeline for far longer than its timeout
-------------------------------------------------------------
Key: HDFS-915
URL: https://issues.apache.org/jira/browse/HDFS-915
Project: Hadoop HDFS
Issue Type: Bug
Components: hdfs client
Affects Versions: 0.20.1
Reporter: Todd Lipcon
After running kill -STOP on the datanode in the middle of a write pipeline, the client takes far longer to recover than it should. The ResponseProcessor times out in the correct interval, but doesn't interrupt the DataStreamer, which appears to not be subject to the same timeout. The client only recovers once the OS actually declares the TCP stream dead, which can take a very long time.
I've experienced this on 0.20.1, haven't tried it yet on trunk or 0.21.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HDFS-915) Hung DN stalls write pipeline for far
longer than its timeout
Posted by "Todd Lipcon (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HDFS-915?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12803970#action_12803970 ]
Todd Lipcon commented on HDFS-915:
----------------------------------
This still happens on trunk, and actually a little worse:
[todd@monster01 hadoop-combined]$ top -d 0.1 -b | ./bin/hadoop fs -put - top-foo-9
======> I issue kill -STOP. Around a minute later (read timeout time) I get, as expected:
10/01/22 16:23:31 WARN hdfs.DFSClient: DFSOutputStream ResponseProcessor exception for block blk_-5990414986184221392_1107java.io.IOException: Bad response ERROR for block blk_-5990414986184221392_1107 from datanode 192.168.42.41:42060
at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream$DataStreamer$ResponseProcessor.run(DFSClient.java:3071)
======> I hit C-\ to get a thread dump (elided the JVM threads which arent important)
2010-01-22 16:24:31
Full thread dump Java HotSpot(TM) 64-Bit Server VM (14.0-b16 mixed mode):
"LeaseChecker" daemon prio=10 tid=0x00000000578eb800 nid=0x6fbe waiting on condition [0x0000000042c02000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at org.apache.hadoop.hdfs.DFSClient$LeaseChecker.run(DFSClient.java:1289)
at java.lang.Thread.run(Thread.java:619)
"DataStreamer for file /user/todd/top-foo-9 block blk_-5990414986184221392_1107" daemon prio=10 tid=0x00000000578eb000 nid=0x6fbd runnable [0x0000000040803000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:215)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
- locked <0x00002aaadd18dc30> (a sun.nio.ch.Util$1)
- locked <0x00002aaadd18dc18> (a java.util.Collections$UnmodifiableSet)
- locked <0x00002aaadd18d8b8> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
at org.apache.hadoop.net.SocketIOWithTimeout$SelectorPool.select(SocketIOWithTimeout.java:332)
at org.apache.hadoop.net.SocketIOWithTimeout.doIO(SocketIOWithTimeout.java:157)
at org.apache.hadoop.net.SocketOutputStream.write(SocketOutputStream.java:146)
at org.apache.hadoop.net.SocketOutputStream.write(SocketOutputStream.java:107)
at java.io.BufferedOutputStream.write(BufferedOutputStream.java:105)
- locked <0x00002aaaddaf9318> (a java.io.BufferedOutputStream)
at java.io.DataOutputStream.write(DataOutputStream.java:90)
- locked <0x00002aaaddaf92e8> (a java.io.DataOutputStream)
at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream$DataStreamer.run(DFSClient.java:2924)
"main" prio=10 tid=0x00000000574e0800 nid=0x6f9a in Object.wait() [0x0000000040209000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00002aaab34b0dd0> (a java.util.LinkedList)
at java.lang.Object.wait(Object.java:485)
at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream.waitAndQueuePacket(DFSClient.java:3561)
- locked <0x00002aaab34b0dd0> (a java.util.LinkedList)
at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream.writeChunk(DFSClient.java:3620)
- locked <0x00002aaaddaf97a0> (a org.apache.hadoop.hdfs.DFSClient$DFSOutputStream)
at org.apache.hadoop.fs.FSOutputSummer.writeChecksumChunk(FSOutputSummer.java:150)
at org.apache.hadoop.fs.FSOutputSummer.write1(FSOutputSummer.java:100)
at org.apache.hadoop.fs.FSOutputSummer.write(FSOutputSummer.java:86)
- locked <0x00002aaaddaf97a0> (a org.apache.hadoop.hdfs.DFSClient$DFSOutputStream)
at org.apache.hadoop.fs.FSDataOutputStream$PositionCache.write(FSDataOutputStream.java:49)
at java.io.DataOutputStream.write(DataOutputStream.java:90)
- locked <0x00002aaaddb32eb8> (a org.apache.hadoop.fs.FSDataOutputStream)
at org.apache.hadoop.io.IOUtils.copyBytes(IOUtils.java:68)
at org.apache.hadoop.io.IOUtils.copyBytes(IOUtils.java:45)
at org.apache.hadoop.io.IOUtils.copyBytes(IOUtils.java:97)
at org.apache.hadoop.fs.FsShell.copyFromStdin(FsShell.java:101)
at org.apache.hadoop.fs.FsShell.copyFromLocal(FsShell.java:127)
at org.apache.hadoop.fs.FsShell.run(FsShell.java:1846)
at org.apache.hadoop.util.ToolRunner.run(ToolRunner.java:65)
at org.apache.hadoop.util.ToolRunner.run(ToolRunner.java:79)
at org.apache.hadoop.fs.FsShell.main(FsShell.java:1977)
======> 6 minutes later, the TCP connection itself times out, and error recovery kicks in
10/01/22 16:30:33 WARN hdfs.DFSClient: Error Recovery for block blk_-5990414986184221392_1107 in pipeline 192.168.42.40:47076, 192.168.42.41:42060, 192.168.42.42:34557: bad datanode 192.168.42.41:42060
======> and fails in some bizarre way - the writer is still writing into fs -put, but it dumps me back to my prompt
[todd@monster01 hadoop-combined]$
> Hung DN stalls write pipeline for far longer than its timeout
> -------------------------------------------------------------
>
> Key: HDFS-915
> URL: https://issues.apache.org/jira/browse/HDFS-915
> Project: Hadoop HDFS
> Issue Type: Bug
> Components: hdfs client
> Affects Versions: 0.20.1
> Reporter: Todd Lipcon
>
> After running kill -STOP on the datanode in the middle of a write pipeline, the client takes far longer to recover than it should. The ResponseProcessor times out in the correct interval, but doesn't interrupt the DataStreamer, which appears to not be subject to the same timeout. The client only recovers once the OS actually declares the TCP stream dead, which can take a very long time.
> I've experienced this on 0.20.1, haven't tried it yet on trunk or 0.21.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HDFS-915) Hung DN stalls write pipeline for far
longer than its timeout
Posted by "Todd Lipcon (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HDFS-915?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12835055#action_12835055 ]
Todd Lipcon commented on HDFS-915:
----------------------------------
I haven't had a chance to run that test, but do you agree that, when the ResponseProcessor catches any exception, it should also interrupt the writer? It should be receiving ack heartbeats every READ_TIMEOUT/2 millis, and if it doesn't, that seems like grounds to kill off both sides of the stream.
> Hung DN stalls write pipeline for far longer than its timeout
> -------------------------------------------------------------
>
> Key: HDFS-915
> URL: https://issues.apache.org/jira/browse/HDFS-915
> Project: Hadoop HDFS
> Issue Type: Bug
> Components: hdfs client
> Affects Versions: 0.20.1
> Reporter: Todd Lipcon
> Assignee: Todd Lipcon
> Attachments: local-dn.log
>
>
> After running kill -STOP on the datanode in the middle of a write pipeline, the client takes far longer to recover than it should. The ResponseProcessor times out in the correct interval, but doesn't interrupt the DataStreamer, which appears to not be subject to the same timeout. The client only recovers once the OS actually declares the TCP stream dead, which can take a very long time.
> I've experienced this on 0.20.1, haven't tried it yet on trunk or 0.21.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HDFS-915) Hung DN stalls write pipeline for far
longer than its timeout
Posted by "dhruba borthakur (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HDFS-915?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12835048#action_12835048 ]
dhruba borthakur commented on HDFS-915:
---------------------------------------
I agree with Todd that the default value of HdfsConstants.WRITE_TIMEOUT is somewhat in the order of 8 to 10 minutes. But this is a configurable value and you can set it lower if necessary, isn't it? If you set it to a smaller value, then does your kill -STOP experiment generate an error in the client quicker than 10 minutes?
> Hung DN stalls write pipeline for far longer than its timeout
> -------------------------------------------------------------
>
> Key: HDFS-915
> URL: https://issues.apache.org/jira/browse/HDFS-915
> Project: Hadoop HDFS
> Issue Type: Bug
> Components: hdfs client
> Affects Versions: 0.20.1
> Reporter: Todd Lipcon
> Assignee: Todd Lipcon
> Attachments: local-dn.log
>
>
> After running kill -STOP on the datanode in the middle of a write pipeline, the client takes far longer to recover than it should. The ResponseProcessor times out in the correct interval, but doesn't interrupt the DataStreamer, which appears to not be subject to the same timeout. The client only recovers once the OS actually declares the TCP stream dead, which can take a very long time.
> I've experienced this on 0.20.1, haven't tried it yet on trunk or 0.21.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HDFS-915) Hung DN stalls write pipeline for far
longer than its timeout
Posted by "ryan rawson (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HDFS-915?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12848029#action_12848029 ]
ryan rawson commented on HDFS-915:
----------------------------------
i got this, i was doing a 3 TB distcp from a hftp:// url to the target cluster. It was running hadoop 0.20.1+169.56, with patches of HDFS-200, HDFS-826 as well.
nothing super interesting in the logs, just:
java.net.SocketTimeoutException: 480000 millis timeout while waiting for channel to be ready for write. ch : java.nio.channels.SocketChannel[connected local=/10.10.21.27:50010 remote=/10.10.21.17:33970]
at org.apache.hadoop.net.SocketIOWithTimeout.waitForIO(SocketIOWithTimeout.java:246)
at org.apache.hadoop.net.SocketOutputStream.waitForWritable(SocketOutputStream.java:159)
at org.apache.hadoop.net.SocketOutputStream.transferToFully(SocketOutputStream.java:198)
at org.apache.hadoop.hdfs.server.datanode.BlockSender.sendChunks(BlockSender.java:313)
at org.apache.hadoop.hdfs.server.datanode.BlockSender.sendBlock(BlockSender.java:401)
at org.apache.hadoop.hdfs.server.datanode.DataXceiver.readBlock(DataXceiver.java:180)
at org.apache.hadoop.hdfs.server.datanode.DataXceiver.run(DataXceiver.java:95)
at java.lang.Thread.run(Thread.java:619)
and errors in my distcp job every now and again.
> Hung DN stalls write pipeline for far longer than its timeout
> -------------------------------------------------------------
>
> Key: HDFS-915
> URL: https://issues.apache.org/jira/browse/HDFS-915
> Project: Hadoop HDFS
> Issue Type: Bug
> Components: hdfs client
> Affects Versions: 0.20.1
> Reporter: Todd Lipcon
> Assignee: Todd Lipcon
> Attachments: local-dn.log
>
>
> After running kill -STOP on the datanode in the middle of a write pipeline, the client takes far longer to recover than it should. The ResponseProcessor times out in the correct interval, but doesn't interrupt the DataStreamer, which appears to not be subject to the same timeout. The client only recovers once the OS actually declares the TCP stream dead, which can take a very long time.
> I've experienced this on 0.20.1, haven't tried it yet on trunk or 0.21.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HDFS-915) Hung DN stalls write pipeline for far
longer than its timeout
Posted by "Todd Lipcon (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HDFS-915?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12835087#action_12835087 ]
Todd Lipcon commented on HDFS-915:
----------------------------------
bq. This was important because the client had to correctly detect which datanode in the pipeline was dead. I am unable to recollect that scenario as of now
I think these issues were identified and fixed by HDFS-793 and HDFS-101, no?
bq. But the better way to solve this issue (as done in trunk) is for the client to send a ping message periodically
I agree - the pipeline heartbeats should ideally originate from the clients. In the current implementation, they originate from the last node in the pipeline, though, so at least we are detecting that each ResponseProcessor is alive. Since DataStreamer will interrupt ResponseProcessor in the case of an error, we're also indirectly verifying the DataStreamers are alive. So while end-to-end heartbeat would be a little better, the current mechanism should also work.
If the heartbeat doesn't arrive on a node in the pipeline, its reader times out. This causes an IOException which makes the ResponseProcessor shut down. But it's not interrupting the DataStreamer - instead we have to wait the much longer write timeout.
> Hung DN stalls write pipeline for far longer than its timeout
> -------------------------------------------------------------
>
> Key: HDFS-915
> URL: https://issues.apache.org/jira/browse/HDFS-915
> Project: Hadoop HDFS
> Issue Type: Bug
> Components: hdfs client
> Affects Versions: 0.20.1
> Reporter: Todd Lipcon
> Assignee: Todd Lipcon
> Attachments: local-dn.log
>
>
> After running kill -STOP on the datanode in the middle of a write pipeline, the client takes far longer to recover than it should. The ResponseProcessor times out in the correct interval, but doesn't interrupt the DataStreamer, which appears to not be subject to the same timeout. The client only recovers once the OS actually declares the TCP stream dead, which can take a very long time.
> I've experienced this on 0.20.1, haven't tried it yet on trunk or 0.21.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (HDFS-915) Hung DN stalls write pipeline for far
longer than its timeout
Posted by "Todd Lipcon (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HDFS-915?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Todd Lipcon updated HDFS-915:
-----------------------------
Attachment: local-dn.log
Here's the log from the localhost DN. The DN I kill -STOPed was .41 (downstream) and I never CONTed it.
> Hung DN stalls write pipeline for far longer than its timeout
> -------------------------------------------------------------
>
> Key: HDFS-915
> URL: https://issues.apache.org/jira/browse/HDFS-915
> Project: Hadoop HDFS
> Issue Type: Bug
> Components: hdfs client
> Affects Versions: 0.20.1
> Reporter: Todd Lipcon
> Attachments: local-dn.log
>
>
> After running kill -STOP on the datanode in the middle of a write pipeline, the client takes far longer to recover than it should. The ResponseProcessor times out in the correct interval, but doesn't interrupt the DataStreamer, which appears to not be subject to the same timeout. The client only recovers once the OS actually declares the TCP stream dead, which can take a very long time.
> I've experienced this on 0.20.1, haven't tried it yet on trunk or 0.21.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HDFS-915) Hung DN stalls write pipeline for far
longer than its timeout
Posted by "dhruba borthakur (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HDFS-915?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12835061#action_12835061 ]
dhruba borthakur commented on HDFS-915:
---------------------------------------
when I first wrote some of this code in 0.16 or so, there were subtle issues on how the client detected this failure. This was important because the client had to correctly detect which datanode in the pipeline was dead. I am unable to recollect that scenario as of now.
But the better way to solve this issue (as done in trunk) is for the client to send a ping message periodically, it travels all the way to the last datanode in the pipeline... the last datanode then sends an ack back which travels all the way back the client. This round-trip tests that all DataStreamers and ResponseProcessors are alive and kicking. If the ack for the ping message does not arrive, then the the client can start recovery?
> Hung DN stalls write pipeline for far longer than its timeout
> -------------------------------------------------------------
>
> Key: HDFS-915
> URL: https://issues.apache.org/jira/browse/HDFS-915
> Project: Hadoop HDFS
> Issue Type: Bug
> Components: hdfs client
> Affects Versions: 0.20.1
> Reporter: Todd Lipcon
> Assignee: Todd Lipcon
> Attachments: local-dn.log
>
>
> After running kill -STOP on the datanode in the middle of a write pipeline, the client takes far longer to recover than it should. The ResponseProcessor times out in the correct interval, but doesn't interrupt the DataStreamer, which appears to not be subject to the same timeout. The client only recovers once the OS actually declares the TCP stream dead, which can take a very long time.
> I've experienced this on 0.20.1, haven't tried it yet on trunk or 0.21.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HDFS-915) Hung DN stalls write pipeline for far
longer than its timeout
Posted by "Todd Lipcon (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HDFS-915?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12803978#action_12803978 ]
Todd Lipcon commented on HDFS-915:
----------------------------------
Looking closer, I think the crux of this issue is that the DFSClient uses HdfsConstants.WRITE_TIMEOUT to time its writes out, and this value defaults to something like 8 minutes. If the reader sees an error, it should probably interrupt() the writer, which should treat the interrupt identically to IOException.
> Hung DN stalls write pipeline for far longer than its timeout
> -------------------------------------------------------------
>
> Key: HDFS-915
> URL: https://issues.apache.org/jira/browse/HDFS-915
> Project: Hadoop HDFS
> Issue Type: Bug
> Components: hdfs client
> Affects Versions: 0.20.1
> Reporter: Todd Lipcon
> Attachments: local-dn.log
>
>
> After running kill -STOP on the datanode in the middle of a write pipeline, the client takes far longer to recover than it should. The ResponseProcessor times out in the correct interval, but doesn't interrupt the DataStreamer, which appears to not be subject to the same timeout. The client only recovers once the OS actually declares the TCP stream dead, which can take a very long time.
> I've experienced this on 0.20.1, haven't tried it yet on trunk or 0.21.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HDFS-915) Hung DN stalls write pipeline for far
longer than its timeout
Posted by "dhruba borthakur (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HDFS-915?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12835102#action_12835102 ]
dhruba borthakur commented on HDFS-915:
---------------------------------------
My suggestion would be to set the timeout small of required and then see if this problem still exists in trunk.
> Hung DN stalls write pipeline for far longer than its timeout
> -------------------------------------------------------------
>
> Key: HDFS-915
> URL: https://issues.apache.org/jira/browse/HDFS-915
> Project: Hadoop HDFS
> Issue Type: Bug
> Components: hdfs client
> Affects Versions: 0.20.1
> Reporter: Todd Lipcon
> Assignee: Todd Lipcon
> Attachments: local-dn.log
>
>
> After running kill -STOP on the datanode in the middle of a write pipeline, the client takes far longer to recover than it should. The ResponseProcessor times out in the correct interval, but doesn't interrupt the DataStreamer, which appears to not be subject to the same timeout. The client only recovers once the OS actually declares the TCP stream dead, which can take a very long time.
> I've experienced this on 0.20.1, haven't tried it yet on trunk or 0.21.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Assigned: (HDFS-915) Hung DN stalls write pipeline for far
longer than its timeout
Posted by "Todd Lipcon (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HDFS-915?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Todd Lipcon reassigned HDFS-915:
--------------------------------
Assignee: Todd Lipcon
> Hung DN stalls write pipeline for far longer than its timeout
> -------------------------------------------------------------
>
> Key: HDFS-915
> URL: https://issues.apache.org/jira/browse/HDFS-915
> Project: Hadoop HDFS
> Issue Type: Bug
> Components: hdfs client
> Affects Versions: 0.20.1
> Reporter: Todd Lipcon
> Assignee: Todd Lipcon
> Attachments: local-dn.log
>
>
> After running kill -STOP on the datanode in the middle of a write pipeline, the client takes far longer to recover than it should. The ResponseProcessor times out in the correct interval, but doesn't interrupt the DataStreamer, which appears to not be subject to the same timeout. The client only recovers once the OS actually declares the TCP stream dead, which can take a very long time.
> I've experienced this on 0.20.1, haven't tried it yet on trunk or 0.21.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.