Datanode Exception:
2008-10-23 17:30:21,703 INFO org.apache.hadoop.dfs.DataNode: writeBlock blk_4622591820056312866_6335826 received exception java.io.EOFException: while trying to read 65625 bytes
2008-10-23 17:30:21,703 ERROR org.apache.hadoop.dfs.DataNode: DatanodeRegistration(xxx.yyy.zzz.uuu:50010, storageID=DS-1873593537-xx.yyy.zzz.uuu-vvvv-1216412543041, infoPort=50075, ipcPort=50020):DataXceiver: java.io.EOFException: while trying to read 65625 bytes
at org.apache.hadoop.dfs.DataNode$BlockReceiver.readToBuf(DataNode.java:2464)
at org.apache.hadoop.dfs.DataNode$BlockReceiver.readNextPacket(DataNode.java:2508)
at org.apache.hadoop.dfs.DataNode$BlockReceiver.receivePacket(DataNode.java:2572)
at org.apache.hadoop.dfs.DataNode$BlockReceiver.receiveBlock(DataNode.java:2698)
at org.apache.hadoop.dfs.DataNode$DataXceiver.writeBlock(DataNode.java:1283)
at org.apache.hadoop.dfs.DataNode$DataXceiver.run(DataNode.java:1045)
at java.lang.Thread.run(Thread.java:619)

Is it possible that this is a configuration issue?

Main concern is, of course, the loss of data blocks. So far they could be recovered by restarting the dead datanodes.

When was the jstack you attached taken? It looks like following thread is blocking most of the other threads :

Not sure if this is the cause or a side effect. I wonder why there are so many blocks under recovery.

The thread dump was taken long time (about 10 hrs) after the last log message containing above exception for this datanode.

In general, from what I observed for the whole job there was an unsually high number of write errors including reduce task failures compared to 0.17.2. In the 12 hours leading up to the last exception there were 300+ exceptions like above on this datanode alone. I checked a datanode which did not become dead. It showed similar order of magnitude of exceptions.

Seems like a deadlock in Datanode. This essentially freezes the datanode and eventually it will marked dead.

The deadlock is between the threads nid=0xf05 (A) and nid=0x6a81 (B). B is waiting for A to exit, but A is trying to acquire a lock held by B. It seems to be new append related code in 0.18. I don't think the exceptions are related.

• A :

   "org.apache.hadoop.dfs.DataNode$DataXceiver@1ccd900" daemon prio=10 tid=0x09368000 nid=0xf05 waiting for monitor entry [0x9bb21000..0x9bb21ea0]
     java.lang.Thread.State: BLOCKED (on object monitor)
  	at org.apache.hadoop.dfs.FSDataset.setChannelPosition(FSDataset.java:977)
  	- waiting to lock <0xb64e9c20> (a org.apache.hadoop.dfs.FSDataset)
  	at org.apache.hadoop.dfs.DataNode$BlockReceiver.setBlockPosition(DataNode.java:2791)
  	at org.apache.hadoop.dfs.DataNode$BlockReceiver.receivePacket(DataNode.java:2596)
  	at org.apache.hadoop.dfs.DataNode$BlockReceiver.receiveBlock(DataNode.java:2698)
  	at org.apache.hadoop.dfs.DataNode$DataXceiver.writeBlock(DataNode.java:1283)
  	at org.apache.hadoop.dfs.DataNode$DataXceiver.run(DataNode.java:1045)
  	at java.lang.Thread.run(Thread.java:619)
  

• B :

  "org.apache.hadoop.dfs.DataNode$DataXceiver@1ccd900" daemon prio=10 tid=0x09368000 nid=0xf05 waiting for monitor entry [0x9bb21000..0x9bb21ea0]
     java.lang.Thread.State: BLOCKED (on object monitor)
  	at org.apache.hadoop.dfs.FSDataset.setChannelPosition(FSDataset.java:977)
  	- waiting to lock <0xb64e9c20> (a org.apache.hadoop.dfs.FSDataset)
  	at org.apache.hadoop.dfs.DataNode$BlockReceiver.setBlockPosition(DataNode.java:2791)
  	at org.apache.hadoop.dfs.DataNode$BlockReceiver.receivePacket(DataNode.java:2596)
  	at org.apache.hadoop.dfs.DataNode$BlockReceiver.receiveBlock(DataNode.java:2698)
  	at org.apache.hadoop.dfs.DataNode$DataXceiver.writeBlock(DataNode.java:1283)
  	at org.apache.hadoop.dfs.DataNode$DataXceiver.run(DataNode.java:1045)
  	at java.lang.Thread.run(Thread.java:619)
  

> It looks like following thread is blocking most of the other threads ...

This seems a deadlock: Server handler 8 is holding the lock 0xb64e9c20 but waiting for some thread t to complete. I guess the thread t is blocked by same lock 0xb64e9c20.

Yet another case that shows why interrupting a thread for thread communication is not recommended.

I should note that thread 'A' above need not be nid=0xf05, it could be one of many other threads.

4517_20081024.patch: release the lock when calling join().

4517_20081024b_0.18.patch: for 0.18

Christian, could you try the patch and see whether it works?

4517_20081024c_0.18.patch: refactored the codes.

4517_20081024d_0.18.patch: fixed a bug.

4517_20081024d.patch: for trunk

     [exec] -1 overall.  

     [exec]     +1 @author.  The patch does not contain any @author tags.

     [exec]     -1 tests included.  The patch doesn't appear to include any new or modified tests.
     [exec]                         Please justify why no tests are needed for this patch.

     [exec]     +1 javadoc.  The javadoc tool did not generate any warning messages.

     [exec]     +1 javac.  The applied patch does not increase the total number of javac compiler warnings.

     [exec]     +1 findbugs.  The patch does not introduce any new Findbugs warnings.

     [exec]     +1 Eclipse classpath. The patch retains Eclipse classpath integrity.

Passed all unit tests locally. Don't know how to add new tests for this.

Dhruba: Will you take a peek at this? Given the difficulty of doing a test, another person's inspection would be helpful!

Looks good. Couple of rename suggestions :

• {{ getOngoingCreatesOrUpdateBlock()}} could be called tryUpdateBlock(). I think JavaDoc should be better.
• findAndUpdatedBlock() could be folded in to tryUpdateBlock().

I think it will be better to get a confirmation from Christian's load before committing it.. or at least before 0.18.2 is released.

Had a offline conversation with Nicholas. The latest patch could run into a problem if there is a race with a new competing writer. The activeThreads cannot be cleared before joining them. Nicholas will probably put up a slightly modified patch.

Sorry about the late response.

As a matter of fact, before the patch was available (although it was done very fast, thank you, Nicholas), the 3rd attempt was successful because I restarted DataNodes periodically.
Our batch of jobs continued without the patch with no problem, indicating that the dead-lock situation is not easily reproducible. It seems to require a much higher number of simultaneous writing clients than Datanode servers.
The specific job doing this kind of intensive writing will be re-executed in about 3 days. Then I will try out the patch. Can you wait so long?

4517_20081027.patch:

• only remove dead thread instead of all threads.
• re-arranged the codes according to Raghu's comments.

Thanks Raghu and Dhruba for reviewing.

This looks good. I do not know of a unit test than can trigger this race. It might be tough to trigger this race in a standalone unit test.

4517_20081027_0.18.patch: for 0.18

+1.

     [exec] -1 overall.  

     [exec]     +1 @author.  The patch does not contain any @author tags.

     [exec]     -1 tests included.  The patch doesn't appear to include any new or modified tests.
     [exec]                         Please justify why no tests are needed for this patch.

     [exec]     +1 javadoc.  The javadoc tool did not generate any warning messages.

     [exec]     +1 javac.  The applied patch does not increase the total number of javac compiler warnings.

     [exec]     +1 findbugs.  The patch does not introduce any new Findbugs warnings.

     [exec]     +1 Eclipse classpath. The patch retains Eclipse classpath integrity.

I am running unit tests locally. Will commit them once they passed the tests.

I just committed this.

Integrated in Hadoop-trunk #645 (See http://hudson.zones.apache.org/hudson/job/Hadoop-trunk/645/)
. Release FSDataset lock before joining ongoing create threads. (szetszwo)