hadoop-common-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Nikos Stasinopoulos <stasino.li...@gmail.com>
Subject Hadoop map task initialization takes too long (3 minutes, 10 seconds to be exact)
Date Wed, 11 Apr 2012 18:54:48 GMT
Greetings people,

Well, lately, in any Hadoop flow I'm running, I encounter a 3 minutes, 10
second delay for a certain map node (master working as slave). After that
initialization delay, it goes back to normal and executes instantly.

For example, when running QuasiMonteCarlo example:

Task Id Start Time Finish Time
attempt_201204101957_0006_m_000003_0 10/04 20:14:54 10/04 20:18:05 (3mins,
10sec) /default-rack/master

2012-04-10 20:18:04,470 INFO org.apache.hadoop.util.NativeCodeLoader:
Loaded the native-hadoop library
2012-04-10 20:18:04,646 INFO org.apache.hadoop.metrics.jvm.JvmMetrics:
Initializing JVM Metrics with processName=MAP, sessionId=
2012-04-10 20:18:04,647 WARN org.apache.hadoop.conf.Configuration:
user.nameis deprecated. Instead, use
mapreduce.job.user.name
2012-04-10 20:18:04,751 INFO org.apache.hadoop.mapreduce.util.ProcessTree:
setsid exited with exit code 0
2012-04-10 20:18:04,754 INFO org.apache.hadoop.mapred.Task: Using
ResourceCalculatorPlugin :
org.apache.hadoop.mapreduce.util.LinuxResourceCalculatorPlugin@79ee2c2c
2012-04-10 20:18:04,912 INFO org.apache.hadoop.mapred.MapTask: (EQUATOR) 0
kvi 26214396(104857584)
2012-04-10 20:18:04,912 INFO org.apache.hadoop.mapred.MapTask:
mapreduce.task.io.sort.mb: 100
2012-04-10 20:18:04,912 INFO org.apache.hadoop.mapred.MapTask: soft limit
at 83886080
2012-04-10 20:18:04,912 INFO org.apache.hadoop.mapred.MapTask: bufstart =
0; bufvoid = 104857600
2012-04-10 20:18
:04,912 INFO org.apache.hadoop.mapred.MapTask: kvstart = 26214396; length =
6553600 2012-04-10 20:18:04,939 INFO org.apache.hadoop.mapred.MapTask:
Starting flush of map output
2012-04-10 20:18:04,940 INFO org.apache.hadoop.mapred.MapTask: Spilling map
output
2012-04-10 20:18:04,940 INFO org.apache.hadoop.mapred.MapTask: bufstart =
0; bufend = 18; bufvoid = 104857600
2012-04-10 20:18:04,940 INFO org.apache.hadoop.mapred.MapTask: kvstart =
26214396(104857584); kvend = 26214392(104857568); length = 5/6553600
2012-04-10 20:18:04,972 INFO org.apache.hadoop.mapred.MapTask: Finished
spill 0
2012-04-10 20:18:04,975 INFO org.apache.hadoop.mapred.Task:
Task:attempt_201204101957_0006_m_000003_0 is done. And is in the process of
commiting
2012-04-10 20:18:05,058 INFO org.apache.hadoop.mapred.Task: Task
'attempt_201204101957_0006_m_000003_0' done.

Task tracker log is more telling:

2012-04-10 *20:14:54,615* INFO org.apache.hadoop.mapred.TaskTracker: In
TaskLauncher, current free slots : 1 and trying to launch
attempt_201204101957_0006_m_000003_0 which needs 1 slots
2012-04-10 20:14:54,685 INFO org.apache.hadoop.mapred.JvmManager: JVM
Runner jvm_201204101957_0006_m_377512887 spawned.
2012-04-10 20:16:34,041 INFO org.apache.hadoop.mapred.TaskTracker:
addFreeSlot : current free slots : 1
2012-04-10 *20:18:04,433* INFO org.apache.hadoop.mapred.TaskTracker: JVM
with ID: jvm_201204101957_0006_m_377512887 given task:
attempt_201204101957_0006_m_000003_0
2012-04-10 20:18:04,938 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201204101957_0006_m_000003_0 0.0%
2012-04-10 20:18:05,056 INFO org.apache.hadoop.mapred.TaskTracker:
attempt_201204101957_0006_m_000003_0 0.667% Generated 1000 samples.

sort
2012-04-10 20:18:05,058 INFO org.apache.hadoop.mapred.TaskTracker: Task
attempt_201204101957_0006_m_000003_0 is done.
2012-04-10 20:18:05,058 INFO org.apache.hadoop.mapred.TaskTracker: reported
output size for attempt_201204101957_0006_m_000003_0 was 28
2012-04-10 20:18:05,058 INFO org.apache.hadoop.mapred.TaskTracker:
addFreeSlot : current free slots : 2
2012-04-10 20:18:05,213 INFO org.apache.hadoop.mapreduce.util.ProcessTree:
Sending signal to all members of process group -23030: SIGTERM. Exit code 1
2012-04-10 20:18:08,478 INFO org.apache.hadoop.mapred.TaskTracker: Sent out
28 bytes to reduce 0 from map: attempt_201204101957_0006_m_000003_0 given
28/24
2012-04-10 20:18:08,478 INFO org.apache.hadoop.mapred.TaskTracker: Shuffled
1maps (mapIds=attempt_201204101957_0006_m_000003_0) to reduce 0 in 29s
2012-04-10 20:18:08,478 INFO
org.apache.hadoop.mapred.TaskTracker.clienttrace: src: 147.102.7.173:50060,
dest: 147.102.7.175:57289, maps: 1, op: MAPRED_SHUFFLE, reduceID: 0,
duration: 29
2012-04-10 20:18:10,217 INFO org.apache.hadoop.mapred.JvmManager: JVM :
jvm_201204101957_0006_m_377512887 exited with exit code 0. Number of tasks
it ran: 1

I suspect a network issue here, but I can ping and ssh with no problem.


Thank you in advance,

Nikos Stasinopoulos

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message