Grokbase › Groups › Hadoop › common-dev › September 2009
FAQ
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.

Search Discussions

  • Ted Dunning at Sep 30, 2009 at 1:02 am ⇧
    Is that last map task actually running, or is it pending?
    On Tue, Sep 29, 2009 at 5:57 PM, achilles852 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
  • Achilles852 at Sep 30, 2009 at 1:08 am ⇧
    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 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.
  • Amogh Vasekar at Sep 30, 2009 at 5:32 am ⇧
    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
    Sent: Wednesday, September 30, 2009 6:38 AM
    To: [email protected]
    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 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.
  • Achilles852 at Sep 30, 2009 at 6:03 am ⇧
    Hi
    The input is a plain text file. I use the parameters specified in the input
    file to launch a process on each machine and then collect the results back.
    I am not using cached files. Everything needed is contained in the job jar
    file. Each map task is supposed to finish within one minute.

    Here's the output from the reduce phase, where things get stuck:
    Running Hadoop in Pseudo-distributed mode.

    [code]
    2009-09-30 06:27:38,601 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0 Need another 2 map output(s) where 0 is
    already in progress
    2009-09-30 06:27:38,603 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0: Got 0 new map-outputs
    2009-09-30 06:27:38,603 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0 Scheduled 0 outputs (0 slow hosts and0
    dup hosts)
    2009-09-30 06:28:33,623 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0: Got 1 new map-outputs
    2009-09-30 06:28:33,624 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0 Scheduled 1 outputs (0 slow hosts and0
    dup hosts)
    2009-09-30 06:28:33,628 INFO org.apache.hadoop.mapred.ReduceTask: Shuffling
    2 bytes (6 raw bytes) into RAM from attempt_200909292242_0017_m_000007_0
    2009-09-30 06:28:33,628 INFO org.apache.hadoop.mapred.ReduceTask: Read 2
    bytes from map-output for attempt_200909292242_0017_m_000007_0
    2009-09-30 06:28:33,629 INFO org.apache.hadoop.mapred.ReduceTask: Rec #1
    from attempt_200909292242_0017_m_000007_0 -> (-1, -1) from pc01
    2009-09-30 06:28:40,624 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0 Need another 1 map output(s) where 0 is
    already in progress
    2009-09-30 06:28:40,625 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0: Got 0 new map-outputs
    2009-09-30 06:28:40,626 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0 Scheduled 0 outputs (0 slow hosts and0
    dup hosts)
    2009-09-30 06:29:40,639 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0 Need another 1 map output(s) where 0 is
    already in progress
    2009-09-30 06:29:40,640 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0: Got 0 new map-outputs
    2009-09-30 06:29:40,641 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0 Scheduled 0 outputs (0 slow hosts and0
    dup hosts)
    2009-09-30 06:30:40,655 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0 Need another 1 map output(s) where 0 is
    already in progress
    2009-09-30 06:30:40,657 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0: Got 0 new map-outputs
    2009-09-30 06:30:40,657 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0 Scheduled 0 outputs (0 slow hosts and0
    dup hosts)
    2009-09-30 06:31:40,677 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0 Need another 1 map output(s) where 0 is
    already in progress
    2009-09-30 06:31:40,679 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0: Got 0 new map-outputs
    2009-09-30 06:31:40,679 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0 Scheduled 0 outputs (0 slow hosts and0
    dup hosts)
    2009-09-30 06:32:40,692 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0 Need another 1 map output(s) where 0 is
    already in progress
    2009-09-30 06:32:40,693 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0: Got 0 new map-outputs
    2009-09-30 06:32:40,694 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0 Scheduled 0 outputs (0 slow hosts and0
    dup hosts)
    2009-09-30 06:33:40,708 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0 Need another 1 map output(s) where 0 is
    already in progress
    2009-09-30 06:33:40,710 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0: Got 0 new map-outputs
    2009-09-30 06:33:40,710 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0 Scheduled 0 outputs (0 slow hosts and0
    dup hosts)
    2009-09-30 06:34:40,731 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0 Need another 1 map output(s) where 0 is
    already in progress
    2009-09-30 06:34:40,733 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0: Got 0 new map-outputs
    2009-09-30 06:34:40,733 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0 Scheduled 0 outputs (0 slow hosts and0
    dup hosts)
    2009-09-30 06:35:40,753 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0 Need another 1 map output(s) where 0 is
    already in progress
    2009-09-30 06:35:40,755 INFO org.apache.hadoop.mapred.ReduceTask:
    attempt_200909292242_0017_r_000000_0: Got 1 new map-outputs
    [/code]




    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
    Sent: Wednesday, September 30, 2009 6:38 AM
    To: [email protected]
    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 <[email protected]>
    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-tp25673359p25675439.html
    Sent from the Hadoop core-dev mailing list archive at Nabble.com.
  • Achilles852 at Sep 30, 2009 at 8:46 am ⇧
    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
    Sent: Wednesday, September 30, 2009 6:38 AM
    To: [email protected]
    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 <[email protected]>
    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.
  • Thushara Wijeratna at Sep 30, 2009 at 3:48 pm ⇧
    did you look for network-related errors in the logs. i've found instances
    when a VPN connection confused networking in hadoop. (could be a JVM issue,
    didn't spend the time to know for sure)

    thanks,
    thushara
    On Wed, Sep 30, 2009 at 1:46 AM, achilles852 wrote:


    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
    Sent: Wednesday, September 30, 2009 6:38 AM
    To: [email protected]
    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 <[email protected]>
    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.
  • Achilles852 at Oct 1, 2009 at 12:24 am ⇧
    Yes, I did everything I could think of, but nothing has worked so far. I even
    set the number of reducers to zero, just to be sure. What I don't understand
    is, if all of the map tasks are using the same code, then why do the first
    few tasks complete normally while the last one takes ages.
    Do you think using a different version of Hadoop would help?
    Any help will be highly appreciated.
    Thanks.


    thushw wrote:
    did you look for network-related errors in the logs. i've found instances
    when a VPN connection confused networking in hadoop. (could be a JVM
    issue,
    didn't spend the time to know for sure)

    thanks,
    thushara
    On Wed, Sep 30, 2009 at 1:46 AM, achilles852 wrote:


    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
    Sent: Wednesday, September 30, 2009 6:38 AM
    To: [email protected]
    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 <[email protected]>
    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.
    --
    View this message in context: http://www.nabble.com/last-map-task-taking-too-long-tp25673359p25691439.html
    Sent from the Hadoop core-dev mailing list archive at Nabble.com.

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
groupcommon-dev @
categorieshadoop
postedSep 30, '09 at 12:58a
activeOct 1, '09 at 12:24a
posts8
users4
websitehadoop.apache.org...
irc#hadoop

4 users in discussion

Achilles852: 5 posts Amogh Vasekar: 1 post Thushara Wijeratna: 1 post Ted Dunning: 1 post

Content

People

Support

Translate

site design / logo © 2023 Grokbase