hadoop-common-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From achilles852 <faheemk...@gmail.com>
Subject RE: last map task taking too long
Date Wed, 30 Sep 2009 08:46:08 GMT

Running Hadoop on EC2 using 32 bit small instances with 5 slaves. The job has
5 map tasks and 1 reduce task. Each map task is 5 minutes long.
After 5 minutes and 14 seconds, 4 map tasks completed but the last one is
now stalling the entire process.

Here are the logs for JobTracker:
----------------------------------------
[start of JobTracker Logs]
----------------------------------------
2009-09-30 04:31:24,468 INFO org.apache.hadoop.mapred.JobTracker: Adding
task 'attempt_200909300419_0001_m_000006_0' to tip
task_200909300419_0001_m_000006, for tracker
'tracker_domU-12-31-39-02-66-21.compute-1.internal:localhost.localdomain/127.0.0.1:58857'
2009-09-30 04:31:28,009 INFO org.apache.hadoop.mapred.JobInProgress: Task
'attempt_200909300419_0001_m_000006_0' has completed
task_200909300419_0001_m_000006 successfully.
2009-09-30 04:31:28,012 INFO org.apache.hadoop.mapred.JobTracker: Adding
task 'attempt_200909300419_0001_m_000001_0' to tip
task_200909300419_0001_m_000001, for tracker
'tracker_domU-12-31-39-02-66-21.compute-1.internal:localhost.localdomain/127.0.0.1:58857'
2009-09-30 04:31:28,015 INFO org.apache.hadoop.mapred.JobInProgress:
Choosing data-local task task_200909300419_0001_m_000001
2009-09-30 04:31:28,505 INFO org.apache.hadoop.mapred.JobTracker: Adding
task 'attempt_200909300419_0001_m_000002_0' to tip
task_200909300419_0001_m_000002, for tracker
'tracker_domU-12-31-39-02-F5-D8.compute-1.internal:localhost.localdomain/127.0.0.1:60031'
2009-09-30 04:31:28,505 INFO org.apache.hadoop.mapred.JobInProgress:
Choosing data-local task task_200909300419_0001_m_000002
2009-09-30 04:31:29,577 INFO org.apache.hadoop.mapred.JobTracker: Adding
task 'attempt_200909300419_0001_m_000000_0' to tip
task_200909300419_0001_m_000000, for tracker
'tracker_domU-12-31-39-03-BA-14.compute-1.internal:localhost.localdomain/127.0.0.1:54570'
2009-09-30 04:31:29,577 INFO org.apache.hadoop.mapred.JobInProgress:
Choosing data-local task task_200909300419_0001_m_000000
2009-09-30 04:31:30,851 INFO org.apache.hadoop.mapred.JobTracker: Adding
task 'attempt_200909300419_0001_m_000003_0' to tip
task_200909300419_0001_m_000003, for tracker
'tracker_domU-12-31-39-03-41-B6.compute-1.internal:localhost.localdomain/127.0.0.1:42359'
2009-09-30 04:31:30,851 INFO org.apache.hadoop.mapred.JobInProgress:
Choosing data-local task task_200909300419_0001_m_000003
2009-09-30 04:31:31,965 INFO org.apache.hadoop.mapred.JobTracker: Adding
task 'attempt_200909300419_0001_m_000004_0' to tip
task_200909300419_0001_m_000004, for tracker
'tracker_domU-12-31-39-02-25-A1.compute-1.internal:localhost.localdomain/127.0.0.1:56865'
2009-09-30 04:31:31,965 INFO org.apache.hadoop.mapred.JobInProgress:
Choosing data-local task task_200909300419_0001_m_000004
2009-09-30 04:31:33,095 INFO org.apache.hadoop.mapred.JobTracker: Adding
task 'attempt_200909300419_0001_r_000000_0' to tip
task_200909300419_0001_r_000000, for tracker
'tracker_domU-12-31-39-02-66-21.compute-1.internal:localhost.localdomain/127.0.0.1:58857'
2009-09-30 04:36:33,940 INFO org.apache.hadoop.mapred.JobInProgress: Task
'attempt_200909300419_0001_m_000000_0' has completed
task_200909300419_0001_m_000000 successfully.
2009-09-30 04:36:33,940 INFO org.apache.hadoop.mapred.ResourceEstimator:
measured blowup on task_200909300419_0001_m_000000 was 803/200 = 4.015
2009-09-30 04:36:33,941 INFO org.apache.hadoop.mapred.ResourceEstimator: new
estimate is blowup = 4.015
2009-09-30 04:36:33,945 INFO org.apache.hadoop.mapred.JobTracker: Adding
task 'attempt_200909300419_0001_m_000002_1' to tip
task_200909300419_0001_m_000002, for tracker
'tracker_domU-12-31-39-03-BA-14.compute-1.internal:localhost.localdomain/127.0.0.1:54570'
2009-09-30 04:36:33,945 INFO org.apache.hadoop.mapred.JobInProgress:
Choosing data-local task task_200909300419_0001_m_000002
2009-09-30 04:36:34,793 INFO org.apache.hadoop.mapred.JobInProgress: Task
'attempt_200909300419_0001_m_000002_0' has completed
task_200909300419_0001_m_000002 successfully.
2009-09-30 04:36:34,793 INFO org.apache.hadoop.mapred.ResourceEstimator:
measured blowup on task_200909300419_0001_m_000002 was 317/190 =
1.668421052631579
2009-09-30 04:36:34,794 INFO org.apache.hadoop.mapred.ResourceEstimator: new
estimate is blowup = 2.841710526315789
2009-09-30 04:36:34,796 INFO org.apache.hadoop.mapred.JobTracker: Adding
task 'attempt_200909300419_0001_m_000003_1' to tip
task_200909300419_0001_m_000003, for tracker
'tracker_domU-12-31-39-02-F5-D8.compute-1.internal:localhost.localdomain/127.0.0.1:60031'
2009-09-30 04:36:34,796 INFO org.apache.hadoop.mapred.JobInProgress:
Choosing data-local task task_200909300419_0001_m_000003
2009-09-30 04:36:35,170 INFO org.apache.hadoop.mapred.JobInProgress: Task
'attempt_200909300419_0001_m_000003_0' has completed
task_200909300419_0001_m_000003 successfully.
2009-09-30 04:36:35,170 INFO org.apache.hadoop.mapred.ResourceEstimator:
measured blowup on task_200909300419_0001_m_000003 was 73/189 =
0.3862433862433862
2009-09-30 04:36:35,170 INFO org.apache.hadoop.mapred.ResourceEstimator: new
estimate is blowup = 2.023221479624988
2009-09-30 04:36:35,171 INFO org.apache.hadoop.mapred.JobTracker: Adding
task 'attempt_200909300419_0001_m_000001_1' to tip
task_200909300419_0001_m_000001, for tracker
'tracker_domU-12-31-39-03-41-B6.compute-1.internal:localhost.localdomain/127.0.0.1:42359'
2009-09-30 04:36:35,171 INFO org.apache.hadoop.mapred.JobInProgress:
Choosing data-local task task_200909300419_0001_m_000001
2009-09-30 04:36:35,854 INFO org.apache.hadoop.mapred.JobTracker:
attempt_200909300419_0001_m_000002_1 is 1909 ms debug.
2009-09-30 04:36:36,038 INFO org.apache.hadoop.mapred.JobInProgress: Task
'attempt_200909300419_0001_m_000004_0' has completed
task_200909300419_0001_m_000004 successfully.
2009-09-30 04:36:36,039 INFO org.apache.hadoop.mapred.ResourceEstimator:
measured blowup on task_200909300419_0001_m_000004 was 918/187 =
4.909090909090909
2009-09-30 04:36:36,039 INFO org.apache.hadoop.mapred.ResourceEstimator: new
estimate is blowup = 2.744688836991468
2009-09-30 04:36:43,966 INFO org.apache.hadoop.mapred.JobTracker: Removed
completed task 'attempt_200909300419_0001_m_000002_1' from
'tracker_domU-12-31-39-03-BA-14.compute-1.internal:localhost.localdomain/127.0.0.1:54570'
2009-09-30 04:36:44,853 INFO org.apache.hadoop.mapred.JobTracker: Removed
completed task 'attempt_200909300419_0001_m_000003_1' from
'tracker_domU-12-31-39-02-F5-D8.compute-1.internal:localhost.localdomain/127.0.0.1:60031'
----------------------------------------
[End of JobTracker Logs]
----------------------------------------


Amogh Vasekar-2 wrote:
> 
> Hi,
> Can you provide info on the input like compression etc? Also, are you
> using cached files in your map tasks? It might be helpful if you paste the
> logs here after blanking your system specific info., as then one can find
> out where till the reduce it went or if the copy phase started at all.
> 
> Thanks,
> Amogh
> 
> -----Original Message-----
> From: achilles852 [mailto:faheemkhan@gmail.com] 
> Sent: Wednesday, September 30, 2009 6:38 AM
> To: core-dev@hadoop.apache.org
> Subject: Re: last map task taking too long
> 
> 
> Basically, it finishes what it is supposed to do (I view the logs to find
> out), but does not move onto the reduce stage.
> 
> 
> Ted Dunning wrote:
>> 
>> Is that last map task actually running, or is it pending?
>> 
>> On Tue, Sep 29, 2009 at 5:57 PM, achilles852 <faheemkhan@gmail.com>
>> wrote:
>> 
>>>
>>> Hey.. I am trying to write a small mapreduce program. I launch a few map
>>> tasks, each of which should complete within a certain time (say 5
>>> minutes)... all the tasks complete within 5 minutes except the last one
>>> -
>>> which takes around 10 times more the time taken by all other map
>>> tasks.....any idea why this is happening?
>>>
>>> I am using Hadoop version 0.19.2, tried running it locally as well as on
>>> EC2.
>>> --
>>> View this message in context:
>>> http://www.nabble.com/last-map-task-taking-too-long-tp25673359p25673359.html
>>> Sent from the Hadoop core-dev mailing list archive at Nabble.com.
>>>
>>>
>> 
>> 
>> -- 
>> Ted Dunning, CTO
>> DeepDyve
>> 
>> 
> 
> -- 
> View this message in context:
> http://www.nabble.com/last-map-task-taking-too-long-tp25673359p25673431.html
> Sent from the Hadoop core-dev mailing list archive at Nabble.com.
> 
> 
> 

-- 
View this message in context: http://www.nabble.com/last-map-task-taking-too-long-tp25673359p25677160.html
Sent from the Hadoop core-dev mailing list archive at Nabble.com.


Mime
View raw message