You are viewing a plain text version of this content. The canonical link for it is here.
Posted to common-dev@hadoop.apache.org by "Srikanth Kakani (JIRA)" <ji...@apache.org> on 2007/08/23 01:02:31 UTC
[jira] Created: (HADOOP-1763) Too man lost task trackers - Job
failures
Too man lost task trackers - Job failures
-----------------------------------------
Key: HADOOP-1763
URL: https://issues.apache.org/jira/browse/HADOOP-1763
Project: Hadoop
Issue Type: Bug
Components: mapred
Environment: Version: 0.15.0-dev, r565628
Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
1400 Node cluster
Reporter: Srikanth Kakani
Priority: Blocker
Steps to reproduce:
1 .Run a map reduce application running more than 3000 mappers, each running longer than
2. Observe the lost task trackers.
Observations:
1. Most of the lost taskTracker messages correspond to maps that have already completed
2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
One example:
task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
Counters:
Map-Reduce Framework
Map input records 28,861
Map output records 1,349,114
Map input bytes 200,018,562
Map output bytes 714,878,712
Node 1 task tracker logs:
2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
.
.
.
2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
.
.
.
2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
at org.apache.hadoop.ipc.Client.call(Client.java:472)
at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
.
.
.
2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
Tasktracker is pretty active otherwise:
tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
JobTracker logs:
2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
.
2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
.
2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
.
2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
.
2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
.
2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
.
2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
Notes:
1. I do not see the taskTracker dying during that period
2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
4. TaskTracker:
CPU usage: 9:10-9:20 50%
9:20-9:40 0%
Network Usage: 6M incl dfs operations
5. JobTracker
CPU udage: Avg: 9%
Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Devaraj Das (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Devaraj Das updated HADOOP-1763:
--------------------------------
Assignee: Devaraj Das
Status: Patch Available (was: Open)
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Assignee: Devaraj Das
> Priority: Blocker
> Attachments: 1763.patch, 1763.try.patch
>
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Srikanth Kakani (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#action_12522952 ]
Srikanth Kakani commented on HADOOP-1763:
-----------------------------------------
I am using trunk version, but I will analyze the logs for this possibility.
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Priority: Blocker
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Raghu Angadi (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#action_12524889 ]
Raghu Angadi commented on HADOOP-1763:
--------------------------------------
> If, e.g., responses are large, and/or clients are slow to read them, then more handler threads will increase throughput.
true, more threads can help in this case. Do you think this is the cause of failure in this jira? I doubt it.
Handling slow clients with more threads is inherently problematic and not scalable IMHO. IPC already has all the serialized data, IPC could write data asynchrnously (with future enhancement).
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Assignee: Devaraj Das
> Priority: Blocker
> Attachments: 1763.patch, 1763.try.patch
>
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Hadoop QA (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#action_12523932 ]
Hadoop QA commented on HADOOP-1763:
-----------------------------------
+1
http://issues.apache.org/jira/secure/attachment/12364832/1763.patch applied and successfully tested against trunk revision r571275.
Test results: http://lucene.zones.apache.org:8080/hudson/job/Hadoop-Patch/659/testReport/
Console output: http://lucene.zones.apache.org:8080/hudson/job/Hadoop-Patch/659/console
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Assignee: Devaraj Das
> Priority: Blocker
> Attachments: 1763.patch, 1763.try.patch
>
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Arun C Murthy (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#action_12524572 ]
Arun C Murthy commented on HADOOP-1763:
---------------------------------------
I'm usually scared about doing smart/dynamic scaling of threads/handlers, clearly once we have something well thought out and tested I'd tag along.
I'll go with the current patch for now. +1
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Assignee: Devaraj Das
> Priority: Blocker
> Attachments: 1763.patch, 1763.try.patch
>
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Raghu Angadi (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#action_12524578 ]
Raghu Angadi commented on HADOOP-1763:
--------------------------------------
As part of another jira, I think we should make RPC Q length configurable. There is nothing magical about 100 per thread. I am pretty sure if we half the number of threads and double the max q length we get exactly same benifit. On a 8 cpu node, CPU wise, 60 threads cann't do any more work than 20 threads can.
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Assignee: Devaraj Das
> Priority: Blocker
> Attachments: 1763.patch, 1763.try.patch
>
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Arun C Murthy (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#action_12524624 ]
Arun C Murthy commented on HADOOP-1763:
---------------------------------------
Enis, please raise a jira for it either way.
We can discuss things there and it will be easier to track/record... thanks!
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Assignee: Devaraj Das
> Priority: Blocker
> Attachments: 1763.patch, 1763.try.patch
>
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Devaraj Das (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#action_12522959 ]
Devaraj Das commented on HADOOP-1763:
-------------------------------------
Enis, are you saying that the jetty issue cause lost tasktrackers. That doesn't seem to be the case since the tasktrackers, in fact, are doing the heartbeats and hence they won't be lost.
So I think Srikanth is not hitting HADOOP-1158. IMHO we might be hitting some scalability issue - it might help in the short term to see how things behave with an increased number of JobTracker RPC server handlers. In the code, the number of RPC handlers is hardcoded to 10. It would be interesting to see if things become better with 40.
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Priority: Blocker
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Owen O'Malley (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#action_12524623 ]
Owen O'Malley commented on HADOOP-1763:
---------------------------------------
+1
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Assignee: Devaraj Das
> Priority: Blocker
> Attachments: 1763.patch, 1763.try.patch
>
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Enis Soztutar (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#action_12522938 ]
Enis Soztutar commented on HADOOP-1763:
---------------------------------------
I have mentioned a similar problem (with the same stack trace) in HADOOP-1158.
I suspect the cause might be :
1. Tasktrackers run the maps successfully
2. Map outputs are served by jetty servers on the TTs.
3. All the reduce tasks connects to all the TT where maps are run.
4. since there are lots of reduces wanting to connect the map output server, the jetty servers run out of threads (default 40)
5. tasktrackers continue to make periodic heartbeats to JT, so that they are not dead, but their jetty servers are (temporarily) down.
Are you using trunk version (including HADOOP-1158 )? If not, could you please give it a try.
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Priority: Blocker
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Devaraj Das (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#action_12524549 ]
Devaraj Das commented on HADOOP-1763:
-------------------------------------
Enis, I think we should close this for now by having the JobTracker's handlers configurable. The number of NameNode's RPC server's handlers can be configured with dfs.namenode.handler.count. This patch introduces this feature in the JobTracker's server. We could open a new jira issue to investigate making the #handlers dynamic and handle the problem for all servers (NameNode, JobTracker and maybe TaskTracker).
What do others think?
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Assignee: Devaraj Das
> Priority: Blocker
> Attachments: 1763.patch, 1763.try.patch
>
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Enis Soztutar (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#action_12524620 ]
Enis Soztutar commented on HADOOP-1763:
---------------------------------------
I also give +1 for this patch to be committed, but just wondered if things could have been made easier. I just wanted to raise some discussions before opening another issue, to ensure that dynamic number of handler threads is reasonable.
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Assignee: Devaraj Das
> Priority: Blocker
> Attachments: 1763.patch, 1763.try.patch
>
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Doug Cutting (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#action_12524899 ]
Doug Cutting commented on HADOOP-1763:
--------------------------------------
> Do you think this is the cause of failure in this jira? I doubt it.
Probably not, but I don't really know. With 2000 nodes, if even 1% get bogged down simultaneously then the jobtracker would run out of handler threads. And hadoop can slam nodes pretty hard, so they're often not very responsive. Or if a switch is temporarily saturated, all responses to it might get hung up for a bit.
Perhaps this could be improved by buffering entire responses in handler threads, then having a separate, non-handler thread that uses non-blocking writes to asynchronously write queued responses.
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Assignee: Devaraj Das
> Priority: Blocker
> Attachments: 1763.patch, 1763.try.patch
>
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Enis Soztutar (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#action_12524497 ]
Enis Soztutar commented on HADOOP-1763:
---------------------------------------
Devaraj, have you checked ipc call queue sizes?
{{Server.Listener#doAccept()}} method prints this info as debug log.
It seems configuring the right number of IPC/RPC server handler will always be a fragile design issue. But alternatively I think we could make the number of handlers dynamic. We can monitor the queue usage and opt for best number of handlers? any thoughts ?
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Assignee: Devaraj Das
> Priority: Blocker
> Attachments: 1763.patch, 1763.try.patch
>
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Enis Soztutar (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#action_12524639 ]
Enis Soztutar commented on HADOOP-1763:
---------------------------------------
Here we go : HADOOP-1830
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Assignee: Devaraj Das
> Priority: Blocker
> Attachments: 1763.patch, 1763.try.patch
>
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Christian Kunz (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#action_12524573 ]
Christian Kunz commented on HADOOP-1763:
----------------------------------------
Could this patch be committed? We are waiting for this one.
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Assignee: Devaraj Das
> Priority: Blocker
> Attachments: 1763.patch, 1763.try.patch
>
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Doug Cutting (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#action_12524883 ]
Doug Cutting commented on HADOOP-1763:
--------------------------------------
> On a 8 cpu node, CPU wise, 60 threads can't do any more work than 20 threads can.
Not quite. The ipc.Server reads requests asynchronously in the listener thread, but responses are written synchronously in handler threads. So handler threads are not just doing computation, they're also doing i/o, writing responses. If, e.g., responses are large, and/or clients are slow to read them, then more handler threads will increase throughput.
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Assignee: Devaraj Das
> Priority: Blocker
> Attachments: 1763.patch, 1763.try.patch
>
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Devaraj Das (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Devaraj Das updated HADOOP-1763:
--------------------------------
Attachment: 1763.patch
This patch makes the number of RPC server handlers in the JobTracker configurable. I personally found that configuring the number of RPC server handlers to 50 for a 1400 node cluster worked pretty well - the sort benchmark ran to successful completion.
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Priority: Blocker
> Attachments: 1763.patch, 1763.try.patch
>
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Devaraj Das (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Devaraj Das updated HADOOP-1763:
--------------------------------
Resolution: Fixed
Status: Resolved (was: Patch Available)
I just committed this.
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Assignee: Devaraj Das
> Priority: Blocker
> Attachments: 1763.patch, 1763.try.patch
>
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Srikanth Kakani (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Srikanth Kakani updated HADOOP-1763:
------------------------------------
Summary: Too many lost task trackers - Job failures (was: Too man lost task trackers - Job failures)
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Priority: Blocker
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Devaraj Das (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Devaraj Das updated HADOOP-1763:
--------------------------------
Attachment: 1763.try.patch
Attached is a straightforward patch that increases the number of rpc server handlers from 10 to 40. Pls try things out with this patch and let us know the results.
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Priority: Blocker
> Attachments: 1763.try.patch
>
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HADOOP-1763) Too many lost task trackers - Job
failures
Posted by "Devaraj Das (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HADOOP-1763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#action_12524973 ]
Devaraj Das commented on HADOOP-1763:
-------------------------------------
bq. Perhaps this could be improved by buffering entire responses in handler threads, then having a separate, non-handler thread that uses non-blocking writes to asynchronously write queued responses.
+1 to this. Just like we have selectors for reading data, we should write data via selectors too.
> Too many lost task trackers - Job failures
> ------------------------------------------
>
> Key: HADOOP-1763
> URL: https://issues.apache.org/jira/browse/HADOOP-1763
> Project: Hadoop
> Issue Type: Bug
> Components: mapred
> Environment: Version: 0.15.0-dev, r565628
> Compiled: Tue Aug 14 20:55:37 UTC 2007 by hadoopqa
> 1400 Node cluster
> Reporter: Srikanth Kakani
> Assignee: Devaraj Das
> Priority: Blocker
> Attachments: 1763.patch, 1763.try.patch
>
>
> Steps to reproduce:
> 1 .Run a map reduce application running more than 3000 mappers, each running longer than
> 2. Observe the lost task trackers.
> Observations:
> 1. Most of the lost taskTracker messages correspond to maps that have already completed
> 2. Based on the logs below the taskTracker is unable to connect to the job tracker and so the jobTracker deletes the job after 20 minutes
> One example:
> task_200708210155_0003_m_000000_0 node1 KILLED 0.00% 21-Aug-2007 09:39:09 Lost task tracker <-- Please note the time
> Counters:
> Map-Reduce Framework
> Map input records 28,861
> Map output records 1,349,114
> Map input bytes 200,018,562
> Map output bytes 714,878,712
> Node 1 task tracker logs:
> 2007-08-21 09:08:51,109 INFO org.apache.hadoop.mapred.TaskTracker: Task task_200708210155_0003_m_000000_0 is done. <-- Please note the time
> .
> .
> .
> 2007-08-21 09:08:52,212 INFO org.mortbay.http.SocketListener: LOW ON THREADS ((40-40+0)<1) on SocketListener0@0.0.0.0:50060
> 2007-08-21 09:08:52,217 WARN org.mortbay.http.SocketListener: OUT OF THREADS: SocketListener0@0.0.0.0:50060
> .
> .
> .
> 2007-08-21 09:18:53,877 ERROR org.apache.hadoop.mapred.TaskTracker: Caught exception: java.net.SocketTimeoutException: timed out waiting for rpc response
> at org.apache.hadoop.ipc.Client.call(Client.java:472)
> at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:165)
> at org.apache.hadoop.mapred.$Proxy0.heartbeat(Unknown Source)
> at org.apache.hadoop.mapred.TaskTracker.transmitHeartBeat(TaskTracker.java:941)
> at org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:840)
> at org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:1227)
> at org.apache.hadoop.mapred.TaskTracker.main(TaskTracker.java:1911)
> .
> .
> .
> 2007-08-21 09:47:45,207 INFO org.apache.hadoop.mapred.TaskTracker: Resending 'status' to 'wm501219' with reponseId '5247
> 2007-08-21 09:47:46,023 INFO org.apache.hadoop.mapred.TaskTracker: Recieved RenitTrackerAction from JobTracker
> 2007-08-21 09:47:46,041 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_000000_0 done; removing files.
> 2007-08-21 09:47:46,240 INFO org.apache.hadoop.mapred.TaskRunner: task_200708210155_0003_m_002237_0 done; removing files.
> Tasktracker is pretty active otherwise:
> tracker_wm511293.inktomisearch.com:50050 wm511293.inktomisearch.com 1 6 3
> JobTracker logs:
> 2007-08-21 09:01:11,951 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_0' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:06:27,745 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200708210155_0003_m_000000_1' to tip tip_200708210155_0003_m_000000, for tracker 'tracker_wm511783.inktomisearch.com:50050'
> .
> 2007-08-21 09:08:51,212 INFO org.apache.hadoop.mapred.JobInProgress: Task 'task_200708210155_0003_m_000000_0' has completed tip_200708210155_0003_m_000000 successfully.
> 2007-08-21 09:08:51,213 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has completed succesfully
> .
> 2007-08-21 09:11:27,227 INFO org.apache.hadoop.mapred.TaskInProgress: Already complete TIP tip_200708210155_0003_m_000000 has completed task task_200708210155_0003_m_000000_1
> .
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_0: Lost task tracker
> 2007-08-21 09:39:09,014 INFO org.apache.hadoop.mapred.TaskInProgress: Task 'task_200708210155_0003_m_000000_0' has been lost.
> .
> 2007-08-21 09:39:09,348 INFO org.apache.hadoop.mapred.JobTracker: Removed completed task 'task_200708210155_0003_m_000000_0' from 'tracker_wm511293.inktomisearch.com:50050'
> .
> 2007-08-21 09:47:20,855 INFO org.apache.hadoop.mapred.TaskInProgress: Error from task_200708210155_0003_m_000000_1: Lost task tracker
> 2007-08-21 09:47:20,855 WARN org.apache.hadoop.mapred.TaskInProgress: Recieved duplicate status update of 'KILLED' for 'task_200708210155_0003_m_000000_1' of TIP 'tip_200708210155_0003_m_000000'
> Notes:
> 1. I do not see the taskTracker dying during that period
> 2. Is retry logic not accurate/agressive enough? (did something change recently, this behavior is more evident in 0.15)
> 3. Inconsistencies with jobTracker logs? Lost task tracker detection bad?
> 4. TaskTracker:
> CPU usage: 9:10-9:20 50%
> 9:20-9:40 0%
> Network Usage: 6M incl dfs operations
> 5. JobTracker
> CPU udage: Avg: 9%
> Network Usage: Negligible
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.