Hadoop - map tasks continue after reduce tasks completed

Question

I'm running Hadoop version 1.0.0 on a cluster of about 500 nodes. My job has about 3000 map tasks and 10 reduce tasks. The map tasks complete after about 4 hours (as expected). The reduce tasks each complete then soon after and the results are all available in my output directory. However, the jobtracker then thinks that some of the map tasks have failed and starts re-executing them. The number of executing and pending reduce tasks remains at zero. Eventually about 8 hours later the last of these map tasks finally complete successfully and the job is marked as successfully completed.

Any ideas???

The following is a extract of some of the jobtracker log file:

// map tasks all complete, eg:
2013-05-20 10:50:59,742 INFO org.apache.hadoop.mapred.JobInProgress:   
Task 'attempt_201305131710_0007_m_000430_0' has completed task_201305131710_0007_m_000430 successfully.

//reduce tasks all complete:

2013-05-20 13:38:34,040 INFO org.apache.hadoop.mapred.JobInProgress:         Task 'attempt_201305131710_0007_r_000009_0' has completed task_201305131710_0007_r_000009 successfully.
2013-05-20 13:38:34,142 INFO org.apache.hadoop.mapred.JobInProgress:    
Task 'attempt_201305131710_0007_r_000004_0' has completed task_201305131710_0007_r_000004 successfully.
2013-05-20 13:38:34,204 INFO org.apache.hadoop.mapred.JobInProgress:    
Task 'attempt_201305131710_0007_r_000008_0' has completed task_201305131710_0007_r_000008 successfully.
2013-05-20 13:38:34,745 INFO org.apache.hadoop.mapred.JobInProgress:   
Task 'attempt_201305131710_0007_r_000002_0' has completed task_201305131710_0007_r_000002 successfully.
2013-05-20 13:38:35,521 INFO org.apache.hadoop.mapred.JobInProgress:    
Task 'attempt_201305131710_0007_r_000003_0' has completed task_201305131710_0007_r_000003 successfully.
2013-05-20 13:38:36,196 INFO org.apache.hadoop.mapred.JobInProgress:   
Task 'attempt_201305131710_0007_r_000007_0' has completed task_201305131710_0007_r_000007 successfully.
2013-05-20 13:38:36,276 INFO org.apache.hadoop.mapred.JobTracker: Adding tracker tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:1295 to host HN301-1657.labs.edu.au
2013-05-20 13:38:36,469 INFO org.apache.hadoop.mapred.JobInProgress:   
Task 'attempt_201305131710_0007_r_000005_0' has completed task_201305131710_0007_r_000005 successfully.
2013-05-20 13:38:36,598 INFO org.apache.hadoop.mapred.JobInProgress:  
Task 'attempt_201305131710_0007_r_000006_0' has completed task_201305131710_0007_r_000006 successfully.
2013-05-20 13:38:36,612 INFO org.apache.hadoop.mapred.JobInProgress:   
Task 'attempt_201305131710_0007_r_000000_0' has completed task_201305131710_0007_r_000000 successfully.
2013-05-20 13:38:40,388 INFO org.apache.hadoop.mapred.JobInProgress:  
Task 'attempt_201305131710_0007_r_000001_0' has completed task_201305131710_0007_r_000001 successfully.
2013-05-20 13:44:12,795 INFO org.apache.hadoop.mapred.JobTracker: Lost tracker 'tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:3896'

//As the reduce tasks are reporting success, the job tracker detects that one of the job trackers has died and so restarts it.
//Each of the jobs previously completed successfully by that task tracker are then reexecuted
2013-05-20 13:44:12,795 INFO org.apache.hadoop.mapred.TaskInProgress: Error from attempt_201305131710_0007_m_000430_0: Lost task tracker: tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:3896
2013-05-20 13:44:12,795 INFO org.apache.hadoop.mapred.TaskInProgress: Error from attempt_201305131710_0007_m_000571_0: Lost task tracker: tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:3896
2013-05-20 13:44:12,796 INFO org.apache.hadoop.mapred.TaskInProgress: Error from attempt_201305131710_0007_m_001612_0: Lost task tracker: tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:3896
2013-05-20 13:44:12,796 INFO org.apache.hadoop.mapred.TaskInProgress: Error from attempt_201305131710_0007_m_001629_0: Lost task tracker: tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:3896
2013-05-20 13:44:12,796 INFO org.apache.hadoop.mapred.TaskInProgress: Error from attempt_201305131710_0007_m_001892_0: Lost task tracker: tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:3896
2013-05-20 13:44:12,796 INFO org.apache.hadoop.mapred.TaskInProgress: Error from attempt_201305131710_0007_m_002424_0: Lost task tracker: tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:3896
2013-05-20 13:44:12,796 INFO org.apache.hadoop.mapred.TaskInProgress: Error from attempt_201305131710_0007_m_002437_0: Lost task tracker: tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:3896
2013-05-20 13:44:12,796 INFO org.apache.hadoop.mapred.TaskInProgress: Error from attempt_201305131710_0007_m_002696_0: Lost task tracker: tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:3896
2013-05-20 13:44:12,796 INFO org.apache.hadoop.mapred.TaskInProgress: Error from attempt_201305131710_0007_m_003130_0: Lost task tracker: tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:3896
2013-05-20 13:44:12,796 INFO org.apache.hadoop.mapred.TaskInProgress: Error from attempt_201305131710_0007_m_003149_0: Lost task tracker: tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:3896
2013-05-20 13:44:12,796 INFO org.apache.hadoop.mapred.TaskInProgress: Error from attempt_201305131710_0007_m_003187_0: Lost task tracker: tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:3896
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.TaskInProgress: Error from attempt_201305131710_0007_m_003275_0: Lost task tracker: tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:3896
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.TaskInProgress: Error from attempt_201305131710_0007_m_003358_0: Lost task tracker: tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:3896
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.TaskInProgress: Error from attempt_201305131710_0007_m_003437_0: Lost task tracker: tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:3896
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.TaskInProgress: Error from attempt_201305131710_0007_m_003451_0: Lost task tracker: tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:3896
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.TaskInProgress: Error from attempt_201305131710_0007_m_003478_0: Lost task tracker: tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:3896
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.TaskInProgress: Error from attempt_201305131710_0007_m_003506_0: Lost task tracker: tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:3896
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.TaskInProgress: Error from attempt_201305131710_0010_m_000021_0: Lost task tracker: tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:3896
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201305131710_0010_m_000021_0'
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201305131710_0007_m_000430_0'
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201305131710_0007_m_000571_0'
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201305131710_0007_m_001612_0'
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201305131710_0007_m_001629_0'
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201305131710_0007_m_001892_0'
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201305131710_0007_m_002424_0'
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201305131710_0007_m_002437_0'
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201305131710_0007_m_002696_0'
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201305131710_0007_m_003130_0'
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201305131710_0007_m_003149_0'
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201305131710_0007_m_003187_0'
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201305131710_0007_m_003275_0'
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201305131710_0007_m_003358_0'
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201305131710_0007_m_003437_0'
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201305131710_0007_m_003451_0'
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201305131710_0007_m_003478_0'
2013-05-20 13:44:12,797 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201305131710_0007_m_003506_0'
2013-05-20 13:44:12,917 INFO org.apache.hadoop.mapred.JobTracker: Adding task (TASK_CLEANUP) 'attempt_201305131710_0010_m_000021_0' to tip task_201305131710_0010_m_000021, for   tracker 'tracker_HN301-1654.labs.edu.au:127.0.0.1/127.0.0.1:1100'
2013-05-20 13:44:13,760 INFO org.apache.hadoop.mapred.JobInProgress: Choosing a failed task task_201305131710_0007_m_000430
2013-05-20 13:44:13,761 INFO org.apache.hadoop.mapred.JobTracker: Adding task (MAP) 'attempt_201305131710_0007_m_000430_1' to tip task_201305131710_0007_m_000430, for tracker 'tracker_ZC329-0001.labs.edu.au:127.0.0.1/127.0.0.1:1113'

Chris White Chris White · Accepted Answer · 2013-05-20T10:30:13

You might want to check your configuration of each cluster node:

tracker_HN301-1657.labs.edu.au:127.0.0.1/127.0.0.1:3896

The jobTracker is trying to contact a TaskTracker node via a loop back address. Check the contents of each nodes /etc/hosts file to check they are correct (and preferably know about each other node in the cluster so you can avoid DNS lookup costs).

I'm not saying this is the cause of your problem, but it certainly isn't right, and should be something you track down

Hadoop - map tasks continue after reduce tasks completed

1 Answers