hadoop-common-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Karim Awara <karim.aw...@kaust.edu.sa>
Subject Reduce phase freezes
Date Thu, 17 Apr 2014 09:38:30 GMT
Hi,

I am running a normal map-reduce job. The map phases finishes but the
reduce phases does not start. However, the job is still running but seems
it is just halting at the reduce phase.


Note: I am running hadoop 1.2 pseudo-dsitributed on a single node.


below is a snap of the log file for


2014-04-17 11:58:54,939 INFO org.apache.hadoop.mapred.TaskTracker:
TaskTracker up at: localhost/127.0.0.1:50584
2014-04-17 11:58:54,940 INFO org.apache.hadoop.mapred.TaskTracker: Starting
tracker tracker_kw2261.rc.kaust.edu.sa:localhost/127.0.0.1:50584
2014-04-17 11:58:54,980 INFO org.apache.hadoop.mapred.TaskTracker: Starting
thread: Map-events fetcher for all reduce tasks on
tracker_kw2261.rc.kaust.edu.sa:localhost/127.0.0.1:50584
2014-04-17 11:58:54,988 INFO org.apache.hadoop.util.ProcessTree: setsid
exited with exit code 0
2014-04-17 11:58:54,992 INFO org.apache.hadoop.mapred.TaskTracker:  Using
ResourceCalculatorPlugin :
org.apache.hadoop.util.LinuxResourceCalculatorPlugin@1ce3570c
2014-04-17 11:58:54,994 WARN org.apache.hadoop.mapred.TaskTracker:
TaskTracker's totalMemoryAllottedForTasks is -1. TaskMemoryManager is
disabled.
2014-04-17 11:58:54,997 INFO org.apache.hadoop.mapred.IndexCache:
IndexCache created with max memory = 10485760
2014-04-17 11:58:55,003 INFO
org.apache.hadoop.metrics2.impl.MetricsSourceAdapter: MBean for source
ShuffleServerMetrics registered.
2014-04-17 11:58:55,005 INFO org.apache.hadoop.http.HttpServer: Port
returned by webServer.getConnectors()[0].getLocalPort() before open() is
-1. Opening the listener on 50060
2014-04-17 11:58:55,005 INFO org.apache.hadoop.http.HttpServer:
listener.getLocalPort() returned 50060
webServer.getConnectors()[0].getLocalPort() returned 50060
2014-04-17 11:58:55,005 INFO org.apache.hadoop.http.HttpServer: Jetty bound
to port 50060
2014-04-17 11:58:55,006 INFO org.mortbay.log: jetty-6.1.26
2014-04-17 11:58:55,189 INFO org.mortbay.log: Started
SelectChannelConnector@0.0.0.0:50060
2014-04-17 11:58:55,189 INFO org.apache.hadoop.mapred.TaskTracker:
FILE_CACHE_SIZE for mapOutputServlet set to : 2000
2014-04-17 12:01:40,711 INFO org.apache.hadoop.mapred.TaskTracker:
LaunchTaskAction (registerTask): attempt_201404171158_0001_m_000003_0
task's state:UNASSIGNED
2014-04-17 12:01:40,714 INFO org.apache.hadoop.mapred.TaskTracker: Trying
to launch : attempt_201404171158_0001_m_000003_0 which needs 1 slots
2014-04-17 12:01:40,714 INFO org.apache.hadoop.mapred.TaskTracker: In
TaskLauncher, current free slots : 2 and trying to launch
attempt_201404171158_0001_m_000003_0 which needs 1 slots
2014-04-17 12:01:40,921 INFO org.apache.hadoop.mapred.JobLocalizer:
Initializing user awaraka on this TT.
2014-04-17 12:01:41,103 INFO org.apache.hadoop.mapred.JvmManager: In
JvmRunner constructed JVM ID: jvm_201404171158_0001_m_-2007628880
2014-04-17 12:01:41,104 INFO org.apache.hadoop.mapred.JvmManager: JVM
Runner jvm_201404171158_0001_m_-2007628880 spawned.
2014-04-17 12:01:41,106 INFO org.apache.hadoop.mapred.TaskController:
Writing commands to
/home/awaraka/data/hadoop-1.2.1_data/hadoop_local-awaraka/ttprivate/taskTracker/awaraka/jobcache/job_201404171158
_0001/attempt_201404171158_0001_m_000003_0/taskjvm.sh
2014-04-17 12:01:41,564 INFO org.apache.hadoop.mapred.TaskTracker: JVM with
ID: jvm_201404171158_0001_m_-2007628880 given task:
attempt_201404171158_0001_m_000003_0
2014-04-17 12:01:42,046 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_m_000003_0 0.0% setup
2014-04-17 12:01:42,047 INFO org.apache.hadoop.mapred.TaskTracker: Task
attempt_201404171158_0001_m_000003_0 is done.
2014-04-17 12:01:42,047 INFO org.apache.hadoop.mapred.TaskTracker: reported
output size for attempt_201404171158_0001_m_000003_0  was -1
2014-04-17 12:01:42,048 INFO org.apache.hadoop.mapred.TaskTracker:
addFreeSlot : current free slots : 2
2014-04-17 12:01:42,212 INFO org.apache.hadoop.mapred.JvmManager: JVM :
jvm_201404171158_0001_m_-2007628880 exited with exit code 0. Number of
tasks it ran: 1
2014-04-17 12:01:42,250 INFO org.apache.hadoop.io.nativeio.NativeIO:
Initialized cache for UID to User mapping with a cache timeout of 14400
seconds.
2014-04-17 12:01:42,251 INFO org.apache.hadoop.io.nativeio.NativeIO: Got
UserName awaraka for UID 100000 from the native implementation
2014-04-17 12:01:42,271 INFO org.apache.hadoop.mapred.TaskTracker:
LaunchTaskAction (registerTask): attempt_201404171158_0001_m_000000_0
task's state:UNASSIGNED
2014-04-17 12:01:42,271 INFO org.apache.hadoop.mapred.TaskTracker:
LaunchTaskAction (registerTask): attempt_201404171158_0001_m_000001_0
task's state:UNASSIGNED
2014-04-17 12:01:42,273 INFO org.apache.hadoop.mapred.TaskTracker: Trying
to launch : attempt_201404171158_0001_m_000000_0 which needs 1 slots
2014-04-17 12:01:42,273 INFO org.apache.hadoop.mapred.TaskTracker: In
TaskLauncher, current free slots : 2 and trying to launch
attempt_201404171158_0001_m_000000_0 which needs 1 slots
2014-04-17 12:01:42,274 INFO org.apache.hadoop.mapred.TaskTracker: Trying
to launch : attempt_201404171158_0001_m_000001_0 which needs 1 slots
2014-04-17 12:01:42,274 INFO org.apache.hadoop.mapred.TaskTracker: In
TaskLauncher, current free slots : 1 and trying to launch
attempt_201404171158_0001_m_000001_0 which needs 1 slots
2014-04-17 12:01:42,279 INFO org.apache.hadoop.mapred.JvmManager: In
JvmRunner constructed JVM ID: jvm_201404171158_0001_m_298746358
2014-04-17 12:01:42,279 INFO org.apache.hadoop.mapred.JvmManager: JVM
Runner jvm_201404171158_0001_m_298746358 spawned.
2014-04-17 12:01:42,282 INFO org.apache.hadoop.mapred.JvmManager: In
JvmRunner constructed JVM ID: jvm_201404171158_0001_m_-1495095563
2014-04-17 12:01:42,282 INFO org.apache.hadoop.mapred.JvmManager: JVM
Runner jvm_201404171158_0001_m_-1495095563 spawned.
2014-04-17 12:01:42,282 INFO org.apache.hadoop.mapred.TaskController:
Writing commands to
/home/awaraka/data/hadoop-1.2.1_data/hadoop_local-awaraka/ttprivate/taskTracker/awaraka/jobcache/job_201404171158
_0001/attempt_201404171158_0001_m_000001_0/taskjvm.sh
2014-04-17 12:01:42,284 INFO org.apache.hadoop.mapred.TaskController:
Writing commands to
/home/awaraka/data/hadoop-1.2.1_data/hadoop_local-awaraka/ttprivate/taskTracker/awaraka/jobcache/job_201404171158
_0001/attempt_201404171158_0001_m_000000_0/taskjvm.sh
2014-04-17 12:01:42,770 INFO org.apache.hadoop.mapred.TaskTracker: JVM with
ID: jvm_201404171158_0001_m_-1495095563 given task:
attempt_201404171158_0001_m_000000_0
2014-04-17 12:01:42,773 INFO org.apache.hadoop.mapred.TaskTracker: JVM with
ID: jvm_201404171158_0001_m_298746358 given task:
attempt_201404171158_0001_m_000001_0
2014-04-17 12:01:43,206 INFO org.apache.hadoop.mapred.TaskTracker: Received
KillTaskAction for task: attempt_201404171158_0001_m_000003_0
2014-04-17 12:01:43,206 INFO org.apache.hadoop.mapred.TaskTracker: About to
purge task: attempt_201404171158_0001_m_000003_0
2014-04-17 12:01:43,206 INFO org.apache.hadoop.mapred.IndexCache: Map ID
attempt_201404171158_0001_m_000003_0 not found in cache
2014-04-17 12:01:49,222 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_m_000001_0 1.0%
2014-04-17 12:01:49,225 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_m_000000_0 0.1479132%
2014-04-17 12:01:50,455 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_m_000001_0 1.0%
2014-04-17 12:01:50,457 INFO org.apache.hadoop.mapred.TaskTracker: Task
attempt_201404171158_0001_m_000001_0 is done.
2014-04-17 12:01:50,457 INFO org.apache.hadoop.mapred.TaskTracker: reported
output size for attempt_201404171158_0001_m_000001_0  was 15476534
2014-04-17 12:01:50,457 INFO org.apache.hadoop.mapred.TaskTracker:
addFreeSlot : current free slots : 1
2014-04-17 12:01:50,516 INFO org.apache.hadoop.mapred.TaskTracker:
LaunchTaskAction (registerTask): attempt_201404171158_0001_r_000000_0
task's state:UNASSIGNED
2014-04-17 12:01:50,516 INFO org.apache.hadoop.mapred.TaskTracker: Trying
to launch : attempt_201404171158_0001_r_000000_0 which needs 1 slots
2014-04-17 12:01:50,516 INFO org.apache.hadoop.mapred.TaskTracker: In
TaskLauncher, current free slots : 2 and trying to launch
attempt_201404171158_0001_r_000000_0 which needs 1 slots
2014-04-17 12:01:50,520 INFO org.apache.hadoop.mapred.JvmManager: In
JvmRunner constructed JVM ID: jvm_201404171158_0001_r_-2007628880
2014-04-17 12:01:50,520 INFO org.apache.hadoop.mapred.JvmManager: JVM
Runner jvm_201404171158_0001_r_-2007628880 spawned.
2014-04-17 12:01:50,522 INFO org.apache.hadoop.mapred.TaskController:
Writing commands to
/home/awaraka/data/hadoop-1.2.1_data/hadoop_local-awaraka/ttprivate/taskTracker/awaraka/jobcache/job_201404171158
_0001/attempt_201404171158_0001_r_000000_0/taskjvm.sh
2014-04-17 12:01:50,656 INFO org.apache.hadoop.mapred.JvmManager: JVM :
jvm_201404171158_0001_m_298746358 exited with exit code 0. Number of tasks
it ran: 1
2014-04-17 12:01:51,007 INFO org.apache.hadoop.mapred.TaskTracker: JVM with
ID: jvm_201404171158_0001_r_-2007628880 given task:
attempt_201404171158_0001_r_000000_0
2014-04-17 12:01:52,261 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_m_000000_0 0.20643327%
2014-04-17 12:01:55,295 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_m_000000_0 0.2850715%
2014-04-17 12:01:57,404 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_r_000000_0 0.0% reduce > copy >
2014-04-17 12:01:58,428 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_m_000000_0 0.34942606%
2014-04-17 12:02:00,449 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_r_000000_0 0.0% reduce > copy >
2014-04-17 12:02:01,463 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_m_000000_0 0.43121892%
2014-04-17 12:02:04,494 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_m_000000_0 0.4922323%
2014-04-17 12:02:06,492 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_r_000000_0 0.0% reduce > copy >
2014-04-17 12:02:07,526 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_m_000000_0 0.57880783%
2014-04-17 12:02:10,561 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_m_000000_0 0.6370768%
2014-04-17 12:02:12,553 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_r_000000_0 0.0% reduce > copy >
2014-04-17 12:02:13,598 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_m_000000_0 0.70603764%
2014-04-17 12:02:15,596 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_r_000000_0 0.0% reduce > copy >
2014-04-17 12:02:16,628 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_m_000000_0 0.782714%
2014-04-17 12:02:19,658 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_m_000000_0 0.840947%
2014-04-17 12:02:21,634 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_r_000000_0 0.0% reduce > copy >
2014-04-17 12:02:22,687 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_m_000000_0 0.91763073%
2014-04-17 12:02:24,670 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_r_000000_0 0.0% reduce > copy >
2014-04-17 12:02:25,715 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_m_000000_0 0.98650074%
2014-04-17 12:02:28,743 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_m_000000_0 1.0%
2014-04-17 12:02:30,707 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_r_000000_0 0.0% reduce > copy >
2014-04-17 12:02:31,771 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_m_000000_0 1.0%
2014-04-17 12:02:34,798 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_m_000000_0 1.0%
2014-04-17 12:02:35,315 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_m_000000_0 1.0%
2014-04-17 12:02:35,316 INFO org.apache.hadoop.mapred.TaskTracker: Task
attempt_201404171158_0001_m_000000_0 is done.
2014-04-17 12:02:35,316 INFO org.apache.hadoop.mapred.TaskTracker: reported
output size for attempt_201404171158_0001_m_000000_0  was 126033710
2014-04-17 12:02:35,316 INFO org.apache.hadoop.mapred.TaskTracker:
addFreeSlot : current free slots : 2
2014-04-17 12:02:35,489 INFO org.apache.hadoop.mapred.JvmManager: JVM :
jvm_201404171158_0001_m_-1495095563 exited with exit code 0. Number of
tasks it ran: 1
2014-04-17 12:02:36,768 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_r_000000_0 0.0% reduce > copy >
2014-04-17 12:02:39,805 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_r_000000_0 0.0% reduce > copy >
2014-04-17 12:02:45,840 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_r_000000_0 0.0% reduce > copy >
2014-04-17 12:02:51,877 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_r_000000_0 0.0% reduce > copy >
2014-04-17 12:02:54,909 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_r_000000_0 0.0% reduce > copy >
2014-04-17 12:03:00,941 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201404171158_0001_r_000000_0 0.0% reduce > copy >

....

*That last line gets repeated forever. *
--
Best Regards,
Karim Ahmed Awara

-- 

------------------------------
This message and its contents, including attachments are intended solely 
for the original recipient. If you are not the intended recipient or have 
received this message in error, please notify me immediately and delete 
this message from your computer system. Any unauthorized use or 
distribution is prohibited. Please consider the environment before printing 
this email.

Mime
View raw message