See http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/24/changes
Changes:
[ddas] MAPREDUCE-18. Puts some checks for cross checking whether a reduce task
gets the correct shuffle data. Re-committed the same patch after talking to
Ravi.
[ddas] MAPREDUCE-18. Noticed that some optimization can be done in the patch.
Hence reverting.
[ddas] MAPREDUCE-18. Puts some checks for cross checking whether a reduce task
gets the correct shuffle data. Contributed by Ravi Gummadi.
[ddas] MAPREDUCE-353. Makes the shuffle read and connection timeouts
configurable. Contributed by Ravi Gummadi.
[ddas] MAPREDUCE-626. Improves the execution time of TestLostTracker.
Contributed by Jothi Padmanabhan.
[ddas] MAPREDUCE-630. Improves execution time of TestKillCompletedJob.
Contributed by Jothi Padmanabhan.
[ddas] MAPREDUCE-627. Improves execution time of
TestTrackerBlacklistAcrossJobs. Contributed by Jothi Padmanabhan.
[johan] MAPREDUCE-680. Fix so MRUnit can handle reuse of Writable objects.
(Aaron Kimball via johan)
------------------------------------------
[...truncated 122878 lines...]
[junit] 2009-07-16 18:23:20,670 INFO mapred.TaskTracker
(TaskTracker.java:run(1635)) - Trying to launch :
attempt_200907161822_0002_m_000003_0 which needs 1 slots
[junit] 2009-07-16 18:23:20,670 INFO mapred.TaskTracker
(TaskTracker.java:run(328)) - Received KillTaskAction for task:
attempt_200907161822_0002_r_000000_0
[junit] 2009-07-16 18:23:20,670 INFO mapred.TaskTracker
(TaskTracker.java:run(1646)) - In TaskLauncher, current free slots : 2 and
trying to launch attempt_200907161822_0002_m_000003_0 which needs 1 slots
[junit] 2009-07-16 18:23:20,670 INFO mapred.TaskTracker
(TaskTracker.java:purgeTask(1411)) - About to purge task:
attempt_200907161822_0002_r_000000_0
[junit] 2009-07-16 18:23:20,671 INFO mapred.TaskRunner
(ReduceTaskRunner.java:close(47)) - attempt_200907161822_0002_r_000000_0 done;
removing files.
[junit] 2009-07-16 18:23:20,713 INFO mapred.JvmManager
(JvmManager.java:<init>(383)) - In JvmRunner constructed JVM ID:
jvm_200907161822_0002_m_-603959473
[junit] 2009-07-16 18:23:20,714 INFO mapred.JvmManager
(JvmManager.java:spawnNewJvm(351)) - JVM Runner
jvm_200907161822_0002_m_-603959473 spawned.
[junit] 2009-07-16 18:23:20,815 INFO mapred.JobClient
(JobClient.java:monitorAndPrintJob(1349)) - Task Id :
attempt_200907161822_0002_r_000000_0, Status : SUCCEEDED
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:09,373 INFO
jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with
processName=SHUFFLE, sessionId=
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:09,497 INFO
mapred.ReduceTask (ReduceTask.java:<init>(1012)) - ShuffleRamManager:
MemoryLimit=141387360, MaxSingleShuffleLimit=35346840
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:09,504 INFO
mapred.ReduceTask (ReduceTask.java:run(2487)) -
attempt_200907161822_0002_r_000000_0 Thread started: Thread for merging on-disk
files
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:09,504 INFO
mapred.ReduceTask (ReduceTask.java:run(2586)) -
attempt_200907161822_0002_r_000000_0 Thread started: Thread for merging in
memory files
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:09,504 INFO
mapred.ReduceTask (ReduceTask.java:run(2492)) -
attempt_200907161822_0002_r_000000_0 Thread waiting: Thread for merging on-disk
files
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:09,506 INFO
mapred.ReduceTask (ReduceTask.java:fetchOutputs(1894)) -
attempt_200907161822_0002_r_000000_0 Need another 3 map output(s) where 0 is
already in progress
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:09,506 INFO
mapred.ReduceTask (ReduceTask.java:run(2688)) -
attempt_200907161822_0002_r_000000_0 Thread started: Thread for polling Map
Completion Events
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:09,506 INFO
mapred.ReduceTask (ReduceTask.java:fetchOutputs(2007)) -
attempt_200907161822_0002_r_000000_0 Scheduled 0 outputs (0 slow hosts and0 dup
hosts)
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:09,512 INFO
mapred.ReduceTask (ReduceTask.java:run(2694)) -
attempt_200907161822_0002_r_000000_0: Got 2 new map-outputs
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:13,517 INFO
mapred.ReduceTask (ReduceTask.java:run(2694)) -
attempt_200907161822_0002_r_000000_0: Got 1 new map-outputs
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:14,507 INFO
mapred.ReduceTask (ReduceTask.java:fetchOutputs(2007)) -
attempt_200907161822_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup
hosts)
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:14,558 INFO
mapred.ReduceTask (ReduceTask.java:getMapOutput(1425)) - header:
attempt_200907161822_0002_m_000000_0, compressed len: 11, decompressed len: 7
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:14,559 INFO
mapred.ReduceTask (ReduceTask.java:getMapOutput(1439)) - Shuffling 7 bytes (11
raw bytes) into RAM from attempt_200907161822_0002_m_000000_0
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:14,562 INFO
mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1568)) - Read 7 bytes from
map-output for attempt_200907161822_0002_m_000000_0
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:14,562 INFO
mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1627)) - Rec #1 from
attempt_200907161822_0002_m_000000_0 -> (2, 1) from localhost
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:14,567 INFO
mapred.ReduceTask (ReduceTask.java:fetchOutputs(2007)) -
attempt_200907161822_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup
hosts)
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:14,569 INFO
mapred.ReduceTask (ReduceTask.java:getMapOutput(1425)) - header:
attempt_200907161822_0002_m_000001_0, compressed len: 11, decompressed len: 7
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:14,569 INFO
mapred.ReduceTask (ReduceTask.java:getMapOutput(1439)) - Shuffling 7 bytes (11
raw bytes) into RAM from attempt_200907161822_0002_m_000001_0
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:14,569 INFO
mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1568)) - Read 7 bytes from
map-output for attempt_200907161822_0002_m_000001_0
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:14,569 INFO
mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1627)) - Rec #1 from
attempt_200907161822_0002_m_000001_0 -> (2, 1) from localhost
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:14,570 INFO
mapred.ReduceTask (ReduceTask.java:fetchOutputs(2007)) -
attempt_200907161822_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup
hosts)
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:14,573 INFO
mapred.ReduceTask (ReduceTask.java:getMapOutput(1425)) - header:
attempt_200907161822_0002_m_000002_0, compressed len: 11, decompressed len: 7
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:14,573 INFO
mapred.ReduceTask (ReduceTask.java:getMapOutput(1439)) - Shuffling 7 bytes (11
raw bytes) into RAM from attempt_200907161822_0002_m_000002_0
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:14,573 INFO
mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1568)) - Read 7 bytes from
map-output for attempt_200907161822_0002_m_000002_0
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:14,573 INFO
mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1627)) - Rec #1 from
attempt_200907161822_0002_m_000002_0 -> (2, 1) from localhost
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:15,518 INFO
mapred.ReduceTask (ReduceTask.java:run(2712)) - GetMapEventsThread exiting
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:15,519 INFO
mapred.ReduceTask (ReduceTask.java:fetchOutputs(2205)) - getMapsEventsThread
joined.
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:15,519 INFO
mapred.ReduceTask (ReduceTask.java:close(1118)) - Closed ram manager
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:15,520 INFO
mapred.ReduceTask (ReduceTask.java:fetchOutputs(2233)) - Interleaved on-disk
merge complete: 0 files left.
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:15,520 INFO
mapred.ReduceTask (ReduceTask.java:fetchOutputs(2238)) - In-memory merge
complete: 3 files left.
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:15,579 INFO
mapred.Merger (Merger.java:merge(469)) - Merging 3 sorted segments
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:15,579 INFO
mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass, with 3
segments left of total size: 9 bytes
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:15,588 INFO
mapred.ReduceTask (ReduceTask.java:createKVIterator(2351)) - Merged 3 segments,
21 bytes to disk to satisfy reduce memory limit
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:15,588 INFO
mapred.ReduceTask (ReduceTask.java:createKVIterator(2371)) - Merging 1 files,
21 bytes from disk
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:15,589 INFO
mapred.ReduceTask (ReduceTask.java:createKVIterator(2385)) - Merging 0
segments, 0 bytes from memory into reduce
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:15,589 INFO
mapred.Merger (Merger.java:merge(469)) - Merging 1 sorted segments
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:15,593 INFO
mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass, with 1
segments left of total size: 13 bytes
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:15,730 INFO
mapred.Task (Task.java:done(633)) - Task:attempt_200907161822_0002_r_000000_0
is done. And is in the process of commiting
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:17,738 INFO
mapred.Task (Task.java:commit(733)) - Task attempt_200907161822_0002_r_000000_0
is allowed to commit now
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:17,835 INFO
mapred.FileOutputCommitter (FileOutputCommitter.java:commitTask(92)) - Saved
output of task 'attempt_200907161822_0002_r_000000_0' to
hdfs://localhost:33702/user/hudson/mapout
[junit] attempt_200907161822_0002_r_000000_0: 2009-07-16 18:23:17,839 INFO
mapred.Task (Task.java:sendDone(704)) - Task
'attempt_200907161822_0002_r_000000_0' done.
[junit] 2009-07-16 18:23:21,148 INFO mapred.TaskTracker
(TaskTracker.java:getTask(2534)) - JVM with ID:
jvm_200907161822_0002_m_-603959473 given task:
attempt_200907161822_0002_m_000003_0
[junit] 2009-07-16 18:23:21,497 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1986)) - attempt_200907161822_0002_m_000003_0
0.0%
[junit] 2009-07-16 18:23:21,518 INFO FSNamesystem.audit
(FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1
cmd=delete src=/user/hudson/mapout/_temporary dst=null
perm=null
[junit] 2009-07-16 18:23:21,522 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1986)) - attempt_200907161822_0002_m_000003_0
0.0% cleanup > map
[junit] 2009-07-16 18:23:21,523 INFO mapred.TaskTracker
(TaskTracker.java:reportDone(2067)) - Task attempt_200907161822_0002_m_000003_0
is done.
[junit] 2009-07-16 18:23:21,523 INFO mapred.TaskTracker
(TaskTracker.java:reportDone(2068)) - reported output size for
attempt_200907161822_0002_m_000003_0 was 0
[junit] 2009-07-16 18:23:21,524 INFO mapred.TaskTracker
(TaskTracker.java:addFreeSlots(1618)) - addFreeSlot : current free slots : 2
[junit] 2009-07-16 18:23:21,745 WARN util.ProcessTree
(ProcessTree.java:terminateProcessGroup(136)) - Error executing shell command
org.apache.hadoop.util.Shell$ExitCodeException: kill: No such process
[junit]
[junit] 2009-07-16 18:23:21,745 INFO util.ProcessTree
(ProcessTree.java:terminateProcessGroup(138)) - Killing all processes in the
process group 30034 with SIGTERM. Exit code 1
[junit] 2009-07-16 18:23:21,820 INFO mapred.JobClient
(JobClient.java:monitorAndPrintJob(1300)) - map 100% reduce 100%
[junit] 2009-07-16 18:23:23,100 INFO mapred.JvmManager
(JvmManager.java:runChild(411)) - JVM : jvm_200907161822_0002_r_1993322859
exited. Number of tasks it ran: 1
[junit] 2009-07-16 18:23:23,669 INFO mapred.TaskTracker
(TaskTracker.java:tryToGetOutputSize(1570)) -
org.apache.hadoop.util.DiskChecker$DiskErrorException: Could not find
taskTracker/jobcache/job_200907161822_0002/attempt_200907161822_0002_m_000003_0/output/file.out
in any of the configured local directories
[junit] 2009-07-16 18:23:23,672 INFO mapred.JobInProgress
(JobInProgress.java:completedTask(2419)) - Task
'attempt_200907161822_0002_m_000003_0' has completed
task_200907161822_0002_m_000003 successfully.
[junit] 2009-07-16 18:23:23,672 INFO mapred.JobInProgress
(JobInProgress.java:jobComplete(2584)) - Job job_200907161822_0002 has
completed successfully.
[junit] 2009-07-16 18:23:23,684 INFO hdfs.StateChange
(FSNamesystem.java:allocateBlock(1286)) - BLOCK* NameSystem.allocateBlock:
/user/hudson/mapout/_logs/history/localhost_1247768544382_job_200907161822_0002_hudson_NA.
blk_5595778231255757424_1015
[junit] 2009-07-16 18:23:23,685 INFO datanode.DataNode
(DataXceiver.java:writeBlock(240)) - Receiving block
blk_5595778231255757424_1015 src: /127.0.0.1:44663 dest: /127.0.0.1:41127
[junit] 2009-07-16 18:23:23,686 INFO datanode.DataNode
(DataXceiver.java:writeBlock(240)) - Receiving block
blk_5595778231255757424_1015 src: /127.0.0.1:35359 dest: /127.0.0.1:38574
[junit] 2009-07-16 18:23:23,689 INFO DataNode.clienttrace
(BlockReceiver.java:lastDataNodeRun(807)) - src: /127.0.0.1:35359, dest:
/127.0.0.1:38574, bytes: 11461, op: HDFS_WRITE, cliID: DFSClient_-1690366389,
offset: 0, srvID: DS-1845947181-67.195.138.9-38574-1247768544069, blockid:
blk_5595778231255757424_1015, duration: 641400
[junit] 2009-07-16 18:23:23,689 INFO datanode.DataNode
(BlockReceiver.java:lastDataNodeRun(831)) - PacketResponder 0 for block
blk_5595778231255757424_1015 terminating
[junit] 2009-07-16 18:23:23,689 INFO hdfs.StateChange
(BlockManager.java:addStoredBlock(955)) - BLOCK* NameSystem.addStoredBlock:
blockMap updated: 127.0.0.1:38574 is added to blk_5595778231255757424_1015 size
11461
[junit] 2009-07-16 18:23:23,690 INFO DataNode.clienttrace
(BlockReceiver.java:run(933)) - src: /127.0.0.1:44663, dest: /127.0.0.1:41127,
bytes: 11461, op: HDFS_WRITE, cliID: DFSClient_-1690366389, offset: 0, srvID:
DS-1134249298-67.195.138.9-41127-1247768543455, blockid:
blk_5595778231255757424_1015, duration: 2334301
[junit] 2009-07-16 18:23:23,731 INFO datanode.DataNode
(BlockReceiver.java:run(997)) - PacketResponder 1 for block
blk_5595778231255757424_1015 terminating
[junit] 2009-07-16 18:23:23,731 INFO hdfs.StateChange
(BlockManager.java:addStoredBlock(955)) - BLOCK* NameSystem.addStoredBlock:
blockMap updated: 127.0.0.1:41127 is added to blk_5595778231255757424_1015 size
11461
[junit] 2009-07-16 18:23:23,732 INFO hdfs.StateChange
(FSNamesystem.java:completeFileInternal(1252)) - DIR* NameSystem.completeFile:
file
/user/hudson/mapout/_logs/history/localhost_1247768544382_job_200907161822_0002_hudson_NA
is closed by DFSClient_-1690366389
[junit] 2009-07-16 18:23:23,732 INFO namenode.FSNamesystem
(FSEditLog.java:printStatistics(876)) - Number of transactions: 87 Total time
for transactions(ms): 7Number of transactions batched in Syncs: 5 Number of
syncs: 60 SyncTimes(ms): 551 494
[junit] 2009-07-16 18:23:23,743 INFO mapred.JobHistory
(JobHistory.java:markCompleted(967)) - Moving completed job from
http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/localhost_1247768544382_job_200907161822_0002_hudson_NA
to
http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done/localhost_1247768544382_job_200907161822_0002_hudson_NA
[junit] 2009-07-16 18:23:23,744 INFO mapred.JobHistory
(JobHistory.java:markCompleted(977)) - Moving configuration of completed job
from
http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/localhost_1247768544382_job_200907161822_0002_conf.xml
to
http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done/localhost_1247768544382_job_200907161822_0002_conf.xml
[junit] 2009-07-16 18:23:23,746 INFO mapred.JobTracker
(JobTracker.java:removeMarkedTasks(2286)) - Removed completed task
'attempt_200907161822_0002_m_000000_0' from
'tracker_host1.foo.com:localhost/127.0.0.1:35098'
[junit] 2009-07-16 18:23:23,746 INFO mapred.JobTracker
(JobTracker.java:removeMarkedTasks(2286)) - Removed completed task
'attempt_200907161822_0002_m_000001_0' from
'tracker_host1.foo.com:localhost/127.0.0.1:35098'
[junit] 2009-07-16 18:23:23,746 INFO mapred.JobTracker
(JobTracker.java:removeMarkedTasks(2286)) - Removed completed task
'attempt_200907161822_0002_m_000003_0' from
'tracker_host1.foo.com:localhost/127.0.0.1:35098'
[junit] 2009-07-16 18:23:23,747 INFO mapred.JobTracker
(JobTracker.java:removeMarkedTasks(2286)) - Removed completed task
'attempt_200907161822_0002_m_000004_0' from
'tracker_host1.foo.com:localhost/127.0.0.1:35098'
[junit] 2009-07-16 18:23:23,747 INFO mapred.JobTracker
(JobTracker.java:removeMarkedTasks(2286)) - Removed completed task
'attempt_200907161822_0002_r_000000_0' from
'tracker_host1.foo.com:localhost/127.0.0.1:35098'
[junit] 2009-07-16 18:23:23,748 INFO hdfs.StateChange
(BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates:
blk_8996806860709677683 is added to invalidSet of 127.0.0.1:41127
[junit] 2009-07-16 18:23:23,748 INFO hdfs.StateChange
(BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates:
blk_8996806860709677683 is added to invalidSet of 127.0.0.1:38574
[junit] 2009-07-16 18:23:23,748 INFO hdfs.StateChange
(BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates:
blk_-4832991487946677349 is added to invalidSet of 127.0.0.1:41127
[junit] 2009-07-16 18:23:23,748 INFO hdfs.StateChange
(BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates:
blk_-4832991487946677349 is added to invalidSet of 127.0.0.1:38574
[junit] 2009-07-16 18:23:23,749 INFO mapred.TaskTracker
(TaskTracker.java:purgeJob(1366)) - Received 'KillJobAction' for job:
job_200907161822_0002
[junit] 2009-07-16 18:23:23,749 INFO mapred.TaskRunner
(MapTaskRunner.java:close(43)) - attempt_200907161822_0002_m_000001_0 done;
removing files.
[junit] 2009-07-16 18:23:23,750 INFO mapred.TaskRunner
(MapTaskRunner.java:close(43)) - attempt_200907161822_0002_m_000003_0 done;
removing files.
[junit] 2009-07-16 18:23:23,750 INFO mapred.IndexCache
(IndexCache.java:removeMap(140)) - Map ID attempt_200907161822_0002_m_000003_0
not found in cache
[junit] 2009-07-16 18:23:23,750 INFO mapred.TaskRunner
(MapTaskRunner.java:close(43)) - attempt_200907161822_0002_m_000000_0 done;
removing files.
[junit] 2009-07-16 18:23:23,762 INFO FSNamesystem.audit
(FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1
cmd=delete src=/tmp/hadoop-hudson/mapred/system/job_200907161822_0002
dst=null perm=null
[junit] 2009-07-16 18:23:23,825 INFO mapred.JobClient
(JobClient.java:monitorAndPrintJob(1349)) - Task Id :
attempt_200907161822_0002_m_000003_0, Status : SUCCEEDED
[junit] attempt_200907161822_0002_m_000003_0: 2009-07-16 18:23:21,380 INFO
jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with
processName=MAP, sessionId=
[junit] attempt_200907161822_0002_m_000003_0: 2009-07-16 18:23:21,519 INFO
mapred.Task (Task.java:done(633)) - Task:attempt_200907161822_0002_m_000003_0
is done. And is in the process of commiting
[junit] attempt_200907161822_0002_m_000003_0: 2009-07-16 18:23:21,524 INFO
mapred.Task (Task.java:sendDone(704)) - Task
'attempt_200907161822_0002_m_000003_0' done.
[junit] 2009-07-16 18:23:23,827 INFO mapred.JobClient
(JobClient.java:monitorAndPrintJob(1355)) - Job complete: job_200907161822_0002
[junit] 2009-07-16 18:23:23,829 INFO mapred.JobClient
(Counters.java:log(534)) - Counters: 18
[junit] 2009-07-16 18:23:23,829 INFO mapred.JobClient
(Counters.java:log(536)) - Job Counters
[junit] 2009-07-16 18:23:23,829 INFO mapred.JobClient
(Counters.java:log(538)) - Launched reduce tasks=1
[junit] 2009-07-16 18:23:23,829 INFO mapred.JobClient
(Counters.java:log(538)) - Rack-local map tasks=3
[junit] 2009-07-16 18:23:23,830 INFO mapred.JobClient
(Counters.java:log(538)) - Launched map tasks=3
[junit] 2009-07-16 18:23:23,830 INFO mapred.JobClient
(Counters.java:log(536)) - FileInputFormatCounters
[junit] 2009-07-16 18:23:23,830 INFO mapred.JobClient
(Counters.java:log(538)) - BYTES_READ=3
[junit] 2009-07-16 18:23:23,830 INFO mapred.JobClient
(Counters.java:log(536)) - FileSystemCounters
[junit] 2009-07-16 18:23:23,830 INFO mapred.JobClient
(Counters.java:log(538)) - FILE_BYTES_READ=21
[junit] 2009-07-16 18:23:23,830 INFO mapred.JobClient
(Counters.java:log(538)) - HDFS_BYTES_READ=828
[junit] 2009-07-16 18:23:23,830 INFO mapred.JobClient
(Counters.java:log(538)) - FILE_BYTES_WRITTEN=150
[junit] 2009-07-16 18:23:23,831 INFO mapred.JobClient
(Counters.java:log(538)) - HDFS_BYTES_WRITTEN=6
[junit] 2009-07-16 18:23:23,831 INFO mapred.JobClient
(Counters.java:log(536)) - Map-Reduce Framework
[junit] 2009-07-16 18:23:23,831 INFO mapred.JobClient
(Counters.java:log(538)) - Reduce input groups=3
[junit] 2009-07-16 18:23:23,831 INFO mapred.JobClient
(Counters.java:log(538)) - Combine output records=0
[junit] 2009-07-16 18:23:23,831 INFO mapred.JobClient
(Counters.java:log(538)) - Map input records=3
[junit] 2009-07-16 18:23:23,831 INFO mapred.JobClient
(Counters.java:log(538)) - Reduce shuffle bytes=33
[junit] 2009-07-16 18:23:23,831 INFO mapred.JobClient
(Counters.java:log(538)) - Reduce output records=3
[junit] 2009-07-16 18:23:23,832 INFO mapred.JobClient
(Counters.java:log(538)) - Spilled Records=6
[junit] 2009-07-16 18:23:23,832 INFO mapred.JobClient
(Counters.java:log(538)) - Map output bytes=9
[junit] 2009-07-16 18:23:23,832 INFO mapred.JobClient
(Counters.java:log(538)) - Combine input records=0
[junit] 2009-07-16 18:23:23,832 INFO mapred.JobClient
(Counters.java:log(538)) - Map output records=3
[junit] 2009-07-16 18:23:23,832 INFO mapred.JobClient
(Counters.java:log(538)) - Reduce input records=3
[junit] 2009-07-16 18:23:23,836 INFO FSNamesystem.audit
(FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1
cmd=listStatus src=/user/hudson/mapout dst=null perm=null
[junit] Found 2 items
[junit] drwxr-xr-x - hudson supergroup 0 2009-07-16 18:23
/user/hudson/mapout/_logs
[junit] -rw-r--r-- 3 hudson supergroup 6 2009-07-16 18:23
/user/hudson/mapout/part-00000
[junit] 2009-07-16 18:23:23,838 INFO FSNamesystem.audit
(FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1
cmd=listStatus src=/user/hudson/mapout dst=null perm=null
[junit] 2009-07-16 18:23:23,839 INFO FSNamesystem.audit
(FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1
cmd=open src=/user/hudson/mapout/part-00000 dst=null
perm=null
[junit] 2009-07-16 18:23:23,841 INFO DataNode.clienttrace
(BlockSender.java:sendBlock(417)) - src: /127.0.0.1:41127, dest:
/127.0.0.1:44665, bytes: 10, op: HDFS_READ, cliID: DFSClient_-1690366389,
offset: 0, srvID: DS-1134249298-67.195.138.9-41127-1247768543455, blockid:
blk_6388699410795499958_1015, duration: 239140
[junit] 2009-07-16 18:23:23,841 INFO mapred.MiniMRCluster
(MiniMRCluster.java:waitTaskTrackers(306)) - Waiting for task tracker
tracker_host0.foo.com:localhost/127.0.0.1:45291 to be idle.
[junit] 2009-07-16 18:23:24,631 INFO mapred.JobTracker
(JobTracker.java:removeMarkedTasks(2286)) - Removed completed task
'attempt_200907161822_0002_m_000002_0' from
'tracker_host0.foo.com:localhost/127.0.0.1:45291'
[junit] 2009-07-16 18:23:24,632 INFO mapred.TaskTracker
(TaskTracker.java:purgeJob(1366)) - Received 'KillJobAction' for job:
job_200907161822_0002
[junit] 2009-07-16 18:23:24,633 INFO mapred.TaskRunner
(MapTaskRunner.java:close(43)) - attempt_200907161822_0002_m_000002_0 done;
removing files.
[junit] 2009-07-16 18:23:24,842 INFO mapred.TaskTracker
(TaskTracker.java:run(623)) - Shutting down: Map-events fetcher for all reduce
tasks on tracker_host0.foo.com:localhost/127.0.0.1:45291
[junit] 2009-07-16 18:23:24,843 INFO ipc.Server (Server.java:stop(1103)) -
Stopping server on 45291
[junit] 2009-07-16 18:23:24,843 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 0 on 45291: exiting
[junit] 2009-07-16 18:23:24,843 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 2 on 45291: exiting
[junit] 2009-07-16 18:23:24,843 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 1 on 45291: exiting
[junit] 2009-07-16 18:23:24,844 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 3 on 45291: exiting
[junit] 2009-07-16 18:23:24,844 INFO ipc.Server (Server.java:run(352)) -
Stopping IPC Server listener on 45291
[junit] 2009-07-16 18:23:24,844 INFO ipc.Server (Server.java:run(539)) -
Stopping IPC Server Responder
[junit] 2009-07-16 18:23:24,844 INFO mapred.TaskTracker
(TaskTracker.java:shutdown(855)) - Shutting down StatusHttpServer
[junit] 2009-07-16 18:23:24,947 INFO mapred.TaskTracker
(TaskTracker.java:offerService(1134)) - Interrupted. Closing down.
[junit] 2009-07-16 18:23:24,948 INFO mapred.TaskTracker
(TaskTracker.java:run(623)) - Shutting down: Map-events fetcher for all reduce
tasks on tracker_host1.foo.com:localhost/127.0.0.1:35098
[junit] 2009-07-16 18:23:24,949 INFO ipc.Server (Server.java:stop(1103)) -
Stopping server on 35098
[junit] 2009-07-16 18:23:24,949 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 0 on 35098: exiting
[junit] 2009-07-16 18:23:24,949 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 1 on 35098: exiting
[junit] 2009-07-16 18:23:24,949 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 2 on 35098: exiting
[junit] 2009-07-16 18:23:24,949 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 3 on 35098: exiting
[junit] 2009-07-16 18:23:24,950 INFO ipc.Server (Server.java:run(352)) -
Stopping IPC Server listener on 35098
[junit] 2009-07-16 18:23:24,950 INFO ipc.Server (Server.java:run(539)) -
Stopping IPC Server Responder
[junit] 2009-07-16 18:23:24,951 INFO mapred.TaskTracker
(TaskTracker.java:shutdown(855)) - Shutting down StatusHttpServer
[junit] 2009-07-16 18:23:25,063 INFO mapred.TaskTracker
(TaskTracker.java:offerService(1134)) - Interrupted. Closing down.
[junit] 2009-07-16 18:23:25,063 INFO mapred.JobTracker
(JobTracker.java:close(2104)) - Stopping infoServer
[junit] 2009-07-16 18:23:25,064 INFO mapred.JobTracker
(JobTracker.java:close(2112)) - Stopping interTrackerServer
[junit] 2009-07-16 18:23:25,065 INFO ipc.Server (Server.java:stop(1103)) -
Stopping server on 52986
[junit] 2009-07-16 18:23:25,065 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 0 on 52986: exiting
[junit] 2009-07-16 18:23:25,065 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 6 on 52986: exiting
[junit] 2009-07-16 18:23:25,065 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 8 on 52986: exiting
[junit] 2009-07-16 18:23:25,065 INFO ipc.Server (Server.java:run(352)) -
Stopping IPC Server listener on 52986
[junit] 2009-07-16 18:23:25,065 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 1 on 52986: exiting
[junit] 2009-07-16 18:23:25,065 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 7 on 52986: exiting
[junit] 2009-07-16 18:23:25,065 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 4 on 52986: exiting
[junit] 2009-07-16 18:23:25,065 INFO mapred.JobTracker
(JobTracker.java:offerService(2099)) - Stopped interTrackerServer
[junit] 2009-07-16 18:23:25,065 INFO mapred.JobTracker
(JobTracker.java:stopExpireTrackersThread(2155)) - Stopping expireTrackers
[junit] 2009-07-16 18:23:25,065 INFO ipc.Server (Server.java:run(539)) -
Stopping IPC Server Responder
[junit] 2009-07-16 18:23:25,065 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 9 on 52986: exiting
[junit] 2009-07-16 18:23:25,065 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 5 on 52986: exiting
[junit] 2009-07-16 18:23:25,067 INFO mapred.JobTracker
(JobTracker.java:close(2119)) - Stopping retirer
[junit] 2009-07-16 18:23:25,066 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 3 on 52986: exiting
[junit] 2009-07-16 18:23:25,066 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 2 on 52986: exiting
[junit] 2009-07-16 18:23:25,067 INFO
mapred.EagerTaskInitializationListener
(EagerTaskInitializationListener.java:terminate(106)) - Stopping Job Init
Manager thread
[junit] 2009-07-16 18:23:25,068 INFO
mapred.EagerTaskInitializationListener
(EagerTaskInitializationListener.java:run(60)) - JobInitManagerThread
interrupted.
[junit] 2009-07-16 18:23:25,068 INFO
mapred.EagerTaskInitializationListener
(EagerTaskInitializationListener.java:run(64)) - Shutting down thread pool
[junit] 2009-07-16 18:23:25,068 INFO mapred.JobTracker
(JobTracker.java:close(2131)) - Stopping expireLaunchingTasks
[junit] 2009-07-16 18:23:25,069 INFO mapred.JobTracker
(JobTracker.java:close(2149)) - stopped all jobtracker services
[junit] Shutting down the Mini HDFS Cluster
[junit] Shutting down DataNode 1
[junit] 2009-07-16 18:23:25,170 INFO ipc.Server (Server.java:stop(1103)) -
Stopping server on 49270
[junit] 2009-07-16 18:23:25,170 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 2 on 49270: exiting
[junit] 2009-07-16 18:23:25,170 INFO ipc.Server (Server.java:run(352)) -
Stopping IPC Server listener on 49270
[junit] 2009-07-16 18:23:25,170 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 0 on 49270: exiting
[junit] 2009-07-16 18:23:25,170 INFO ipc.Server (Server.java:run(539)) -
Stopping IPC Server Responder
[junit] 2009-07-16 18:23:25,171 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 1 on 49270: exiting
[junit] 2009-07-16 18:23:25,171 INFO datanode.DataNode
(DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads
is 1
[junit] 2009-07-16 18:23:25,171 WARN datanode.DataNode
(DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:38574,
storageID=DS-1845947181-67.195.138.9-38574-1247768544069, infoPort=53703,
ipcPort=49270):DataXceiveServer: java.nio.channels.AsynchronousCloseException
[junit] at
java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
[junit] at
sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
[junit] at
sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
[junit] at
org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
[junit] at java.lang.Thread.run(Thread.java:619)
[junit]
[junit] 2009-07-16 18:23:25,173 INFO datanode.DataNode
(DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads
is 0
[junit] 2009-07-16 18:23:25,174 INFO datanode.DataBlockScanner
(DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-07-16 18:23:25,174 INFO datanode.DataNode
(DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:38574,
storageID=DS-1845947181-67.195.138.9-38574-1247768544069, infoPort=53703,
ipcPort=49270):Finishing DataNode in:
FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Mapreduce-trunk/trunk/build/test/data/dfs/data/data4/current'}
[junit] 2009-07-16 18:23:25,174 INFO ipc.Server (Server.java:stop(1103)) -
Stopping server on 49270
[junit] 2009-07-16 18:23:25,175 INFO datanode.DataNode
(DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads
is 0
[junit] Shutting down DataNode 0
[junit] 2009-07-16 18:23:25,276 INFO ipc.Server (Server.java:stop(1103)) -
Stopping server on 53696
[junit] 2009-07-16 18:23:25,276 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 0 on 53696: exiting
[junit] 2009-07-16 18:23:25,276 INFO ipc.Server (Server.java:run(352)) -
Stopping IPC Server listener on 53696
[junit] 2009-07-16 18:23:25,276 INFO ipc.Server (Server.java:run(539)) -
Stopping IPC Server Responder
[junit] 2009-07-16 18:23:25,276 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 1 on 53696: exiting
[junit] 2009-07-16 18:23:25,277 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 2 on 53696: exiting
[junit] 2009-07-16 18:23:25,277 INFO datanode.DataNode
(DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads
is 1
[junit] 2009-07-16 18:23:25,277 WARN datanode.DataNode
(DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:41127,
storageID=DS-1134249298-67.195.138.9-41127-1247768543455, infoPort=42069,
ipcPort=53696):DataXceiveServer: java.nio.channels.AsynchronousCloseException
[junit] at
java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
[junit] at
sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
[junit] at
sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
[junit] at
org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
[junit] at java.lang.Thread.run(Thread.java:619)
[junit]
[junit] 2009-07-16 18:23:25,279 INFO datanode.DataNode
(DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads
is 0
[junit] 2009-07-16 18:23:25,280 INFO datanode.DataBlockScanner
(DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-07-16 18:23:25,280 INFO datanode.DataNode
(DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:41127,
storageID=DS-1134249298-67.195.138.9-41127-1247768543455, infoPort=42069,
ipcPort=53696):Finishing DataNode in:
FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/data/dfs/data/data1/current,/home/hudson/hudson-slave/workspace/Hadoop-Mapreduce-trunk/trunk/build/test/data/dfs/data/data2/current'}
[junit] 2009-07-16 18:23:25,280 INFO ipc.Server (Server.java:stop(1103)) -
Stopping server on 53696
[junit] 2009-07-16 18:23:25,281 INFO datanode.DataNode
(DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads
is 0
[junit] 2009-07-16 18:23:25,282 WARN namenode.DecommissionManager
(DecommissionManager.java:run(67)) - Monitor interrupted:
java.lang.InterruptedException: sleep interrupted
[junit] 2009-07-16 18:23:25,282 INFO namenode.FSNamesystem
(FSEditLog.java:printStatistics(876)) - Number of transactions: 88 Total time
for transactions(ms): 7Number of transactions batched in Syncs: 5 Number of
syncs: 62 SyncTimes(ms): 564 504
[junit] 2009-07-16 18:23:25,283 WARN namenode.FSNamesystem
(FSNamesystem.java:run(2057)) - ReplicationMonitor thread received
InterruptedException.java.lang.InterruptedException: sleep interrupted
[junit] 2009-07-16 18:23:25,347 INFO ipc.Server (Server.java:stop(1103)) -
Stopping server on 33702
[junit] 2009-07-16 18:23:25,347 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 1 on 33702: exiting
[junit] 2009-07-16 18:23:25,347 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 4 on 33702: exiting
[junit] 2009-07-16 18:23:25,347 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 2 on 33702: exiting
[junit] 2009-07-16 18:23:25,347 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 8 on 33702: exiting
[junit] 2009-07-16 18:23:25,347 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 3 on 33702: exiting
[junit] 2009-07-16 18:23:25,347 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 7 on 33702: exiting
[junit] 2009-07-16 18:23:25,348 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 9 on 33702: exiting
[junit] 2009-07-16 18:23:25,347 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 6 on 33702: exiting
[junit] 2009-07-16 18:23:25,347 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 5 on 33702: exiting
[junit] 2009-07-16 18:23:25,348 INFO ipc.Server (Server.java:run(539)) -
Stopping IPC Server Responder
[junit] 2009-07-16 18:23:25,348 INFO ipc.Server (Server.java:run(352)) -
Stopping IPC Server listener on 33702
[junit] 2009-07-16 18:23:25,347 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 0 on 33702: exiting
[junit] Tests run: 1, Failures: 0, Errors: 0, Time elapsed: 64.006 sec
[junit] Running org.apache.hadoop.util.TestReflectionUtils
[junit] Tests run: 5, Failures: 0, Errors: 0, Time elapsed: 0.583 sec
[junit] Running org.apache.hadoop.util.TestRunJar
[junit] Creating
filehttp://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/data/out
[junit] Tests run: 1, Failures: 0, Errors: 0, Time elapsed: 0.169 sec
checkfailure:
[touch] Creating
http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/testsfailed
BUILD FAILED
http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build.xml
:614: Tests failed!
Total time: 137 minutes 31 seconds
Publishing Javadoc
Recording test results
Recording fingerprints
Publishing Clover coverage report...
