Hi Hadoopers,

We are experiencing a strange problem on Hadoop 0.20.203

Our cluster has 58 nodes, everything is started from a fresh
HDFS (we deleted all local folders on datanodes and
reformatted the namenode).  After running some small jobs, the
HDFS becomes behaving abnormally and the jobs become very
slow.  The namenode log is crushed by Gigabytes of errors like
is:

2012-02-21 00:00:38,632 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addToInvalidates: blk_4524177823306792294 is added
to invalidSet of 10.105.19.31:50010
2012-02-21 00:00:38,632 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addToInvalidates: blk_4524177823306792294 is added
to invalidSet of 10.105.19.18:50010
2012-02-21 00:00:38,632 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addToInvalidates: blk_4524177823306792294 is added
to invalidSet of 10.105.19.32:50010
2012-02-21 00:00:38,632 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addToInvalidates: blk_2884522252507300332 is added
to invalidSet of 10.105.19.35:50010
2012-02-21 00:00:38,632 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addToInvalidates: blk_2884522252507300332 is added
to invalidSet of 10.105.19.27:50010
2012-02-21 00:00:38,632 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addToInvalidates: blk_2884522252507300332 is added
to invalidSet of 10.105.19.33:50010
2012-02-21 00:00:38,632 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addStoredBlock: blockMap updated:
10.105.19.21:50010 is added to blk_-
6843171124277753504_2279882 size 124490
2012-02-21 00:00:38,632 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.allocateBlock:
/syu/output/naive/iter5_partout1/_temporary/_attempt_201202202
043_0013_m_000313_0/result_stem-m-00313. blk_-
6379064588594672168_2279890
2012-02-21 00:00:38,633 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addStoredBlock: blockMap updated:
10.105.19.26:50010 is added to blk_5338983375361999760_2279887
size 1476
2012-02-21 00:00:38,633 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addStoredBlock: blockMap updated:
10.105.19.29:50010 is added to blk_-977828927900581074_2279887
size 13818
2012-02-21 00:00:38,633 INFO
org.apache.hadoop.hdfs.StateChange: DIR*
NameSystem.completeFile: file
/syu/output/naive/iter5_partout1/_temporary/_attempt_201202202
043_0013_m_000364_0/result_stem-m-00364 is closed by
DFSClient_attempt_201202202043_0013_m_000364_0
2012-02-21 00:00:38,633 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addStoredBlock: blockMap updated:
10.105.19.23:50010 is added to blk_5338983375361999760_2279887
size 1476
2012-02-21 00:00:38,633 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addStoredBlock: blockMap updated:
10.105.19.20:50010 is added to blk_5338983375361999760_2279887
size 1476
2012-02-21 00:00:38,633 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.allocateBlock:
/syu/output/naive/iter5_partout1/_temporary/_attempt_201202202
043_0013_m_000364_0/result_suffix-m-00364.
blk_1921685366929756336_2279890
2012-02-21 00:00:38,634 INFO
org.apache.hadoop.hdfs.StateChange: DIR*
NameSystem.completeFile: file
/syu/output/naive/iter5_partout1/_temporary/_attempt_201202202
043_0013_m_000279_0/result_suffix-m-00279 is closed by
DFSClient_attempt_201202202043_0013_m_000279_0
2012-02-21 00:00:38,635 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addToInvalidates: blk_495061820035691700 is added
to invalidSet of 10.105.19.20:50010
2012-02-21 00:00:38,635 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addToInvalidates: blk_495061820035691700 is added
to invalidSet of 10.105.19.25:50010
2012-02-21 00:00:38,635 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addToInvalidates: blk_495061820035691700 is added
to invalidSet of 10.105.19.33:50010
2012-02-21 00:00:38,635 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.allocateBlock:
/syu/output/naive/iter5_partout1/_temporary/_attempt_201202202
043_0013_m_000284_0/result_stem-m-00284.
blk_8796188324642771330_2279891
2012-02-21 00:00:38,638 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addStoredBlock: blockMap updated:
10.105.19.34:50010 is added to blk_-977828927900581074_2279887
size 13818
2012-02-21 00:00:38,638 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.allocateBlock:
/syu/output/naive/iter5_partout1/_temporary/_attempt_201202202
043_0013_m_000296_0/result_stem-m-00296. blk_-
6800409224007034579_2279891
2012-02-21 00:00:38,638 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addStoredBlock: blockMap updated:
10.105.19.29:50010 is added to blk_1921685366929756336_2279890
size 1511
2012-02-21 00:00:38,638 INFO
org.apache.hadoop.hdfs.StateChange: BLOCK*
NameSystem.addStoredBlock: blockMap updated:
10.105.19.25:50010 is added to blk_-
2982099629304436976_2279752 size 569

In Map/Reduce job, tasks got killing because of timeout error
"

Task attempt_201202202043_0014_m_000019_0 failed to report
status for 600 seconds. Killing!

"
and finally all the jobs executed after a specific time point
will definitely all failed.  All HDFS commands get stalled.  
Then we have to reformat and delete data from HDFS all again.

In the jobtracker-namenode.log file, information is like:

08403,firstReduceTaskLaunchTime=1329808089070,firstJobSetupTas
kLaunchTime=1329806700863,firstJobCleanupTaskLaunchTime=132981
4093350,finishTime=1329814099359,numMaps=467,numSlotsPerMap=1,
numReduces=89,numSlotsPerReduce=1,user=syu,queue=default,statu
s=FAILED,mapSlotSeconds=522658,reduceSlotsSeconds=324155,clust
erMapCapacity=160,clusterReduceCapacity=60
2012-02-21 02:48:19,361 INFO
org.apache.hadoop.mapred.JobHistory: Moving
file:/opt/hadoop/logs/history/job_201202202043_0015_1329806700
027_syu_EM%5Fnaive%5Fbayes%5Fstep3 to
file:/opt/hadoop/logs/history/done/version-
1/namenode_1329792199074_/2

Hi,
 Did you formatted the HDFS?

On Tue, Feb 21, 2012 at 7:40 PM, Shi Yu <[EMAIL PROTECTED]> wrote:

> Hi Hadoopers,
>
> We are experiencing a strange problem on Hadoop 0.20.203
>
> Our cluster has 58 nodes, everything is started from a fresh
> HDFS (we deleted all local folders on datanodes and
> reformatted the namenode).  After running some small jobs, the
> HDFS becomes behaving abnormally and the jobs become very
> slow.  The namenode log is crushed by Gigabytes of errors like
> is:
>
> 2012-02-21 00:00:38,632 INFO
> org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addToInvalidates: blk_4524177823306792294 is added
> to invalidSet of 10.105.19.31:50010
> 2012-02-21 00:00:38,632 INFO
> org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addToInvalidates: blk_4524177823306792294 is added
> to invalidSet of 10.105.19.18:50010
> 2012-02-21 00:00:38,632 INFO
> org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addToInvalidates: blk_4524177823306792294 is added
> to invalidSet of 10.105.19.32:50010
> 2012-02-21 00:00:38,632 INFO
> org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addToInvalidates: blk_2884522252507300332 is added
> to invalidSet of 10.105.19.35:50010
> 2012-02-21 00:00:38,632 INFO
> org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addToInvalidates: blk_2884522252507300332 is added
> to invalidSet of 10.105.19.27:50010
> 2012-02-21 00:00:38,632 INFO
> org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addToInvalidates: blk_2884522252507300332 is added
> to invalidSet of 10.105.19.33:50010
> 2012-02-21 00:00:38,632 INFO
> org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addStoredBlock: blockMap updated:
> 10.105.19.21:50010 is added to blk_-
> 6843171124277753504_2279882 size 124490
> 2012-02-21 00:00:38,632 INFO
> org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.allocateBlock:
> /syu/output/naive/iter5_partout1/_temporary/_attempt_201202202
> 043_0013_m_000313_0/result_stem-m-00313. blk_-
> 6379064588594672168_2279890
> 2012-02-21 00:00:38,633 INFO
> org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addStoredBlock: blockMap updated:
> 10.105.19.26:50010 is added to blk_5338983375361999760_2279887
> size 1476
> 2012-02-21 00:00:38,633 INFO
> org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addStoredBlock: blockMap updated:
> 10.105.19.29:50010 is added to blk_-977828927900581074_2279887
> size 13818
> 2012-02-21 00:00:38,633 INFO
> org.apache.hadoop.hdfs.StateChange: DIR*
> NameSystem.completeFile: file
> /syu/output/naive/iter5_partout1/_temporary/_attempt_201202202
> 043_0013_m_000364_0/result_stem-m-00364 is closed by
> DFSClient_attempt_201202202043_0013_m_000364_0
> 2012-02-21 00:00:38,633 INFO
> org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addStoredBlock: blockMap updated:
> 10.105.19.23:50010 is added to blk_5338983375361999760_2279887
> size 1476
> 2012-02-21 00:00:38,633 INFO
> org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addStoredBlock: blockMap updated:
> 10.105.19.20:50010 is added to blk_5338983375361999760_2279887
> size 1476
> 2012-02-21 00:00:38,633 INFO
> org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.allocateBlock:
> /syu/output/naive/iter5_partout1/_temporary/_attempt_201202202
> 043_0013_m_000364_0/result_suffix-m-00364.
> blk_1921685366929756336_2279890
> 2012-02-21 00:00:38,634 INFO
> org.apache.hadoop.hdfs.StateChange: DIR*
> NameSystem.completeFile: file
> /syu/output/naive/iter5_partout1/_temporary/_attempt_201202202
> 043_0013_m_000279_0/result_suffix-m-00279 is closed by
> DFSClient_attempt_201202202043_0013_m_000279_0
> 2012-02-21 00:00:38,635 INFO
> org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addToInvalidates: blk_495061820035691700 is added
> to invalidSet of 10.105.19.20:50010
> 2012-02-21 00:00:38,635 INFO
> org.apache.hadoop.hdfs.StateChange: BLOCK*
> NameSystem.addToInvalidates: blk_495061820035691700 is added
> to invalidSet of 10.105.19.25:50010
> 2012-02-21 00:00:38,635 INFO
Join me at http://hadoopworkshop.eventbrite.com/