Mailing-List: contact mapreduce-issues-help@hadoop.apache.org; run by ezmlm
Precedence: bulk
Reply-To: mapreduce-issues@hadoop.apache.org
Message-ID: <1067166438.94371264641394778.JavaMail.jira@brutus.apache.org>
Date: Thu, 28 Jan 2010 01:16:34 +0000 (UTC)
From: "dhruba borthakur (JIRA)" <jira@apache.org>
To: mapreduce-issues@hadoop.apache.org
Subject: [jira] Commented: (MAPREDUCE-1420) TestTTResourceReporting failing
 in trunk
In-Reply-To: <1163799286.78331264594115708.JavaMail.jira@brutus.apache.org>
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: quoted-printable


    [ https://issues.apache.org/jira/browse/MAPREDUCE-1420?page=3Dcom.atlas=
sian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=3D=
12805737#action_12805737 ]=20

dhruba borthakur commented on MAPREDUCE-1420:
---------------------------------------------

+1, change looks good.

> TestTTResourceReporting failing in trunk
> ----------------------------------------
>
>                 Key: MAPREDUCE-1420
>                 URL: https://issues.apache.org/jira/browse/MAPREDUCE-1420
>             Project: Hadoop Map/Reduce
>          Issue Type: Bug
>    Affects Versions: 0.22.0
>            Reporter: Iyappan Srinivasan
>            Assignee: Scott Chen
>         Attachments: MAPREDUCE-1420-v1.patch
>
>
> TestTTResourceReporting failing in trunk.=20
> The most specific issue from the logs seems to be : Error executing shell=
 command org.apache.hadoop.util.Shell$ExitCodeException: kill: No such proc=
ess=20
> Link :
> http://hudson.zones.apache.org/hudson/view/Hadoop/job/Hadoop-Mapreduce-tr=
unk/217/
> Giving the complete raw output:
> [junit] 2010-01-26 14:49:47,885 INFO mapred.JobQueueTaskScheduler (TestTT=
ResourceReporting.java:assignTasks(159)) - expected memory values : (totalV=
irtualMemoryOnTT, totalPhysicalMemoryOnTT, availableVirtualMemoryOnTT, avai=
lablePhysicalMemoryOnTT, mapSlotMemSize, reduceSlotMemorySize, cumulativeCp=
uTime, cpuFrequency, numProcessors) =3D (-1, -1,-1, -1,-1,-1,-1,-1,-1,-1.0)=
 [junit] reported memory values : (totalVirtualMemoryOnTT, totalPhysicalMem=
oryOnTT, availableVirtualMemoryOnTT, availablePhysicalMemoryOnTT, reportedM=
apSlotMemorySize, reportedReduceSlotMemorySize, reportedCumulativeCpuTime, =
reportedCpuFrequency, reportedNumProcessors) =3D (-1, -1,-1, -1,-1,-1,-1,-1=
,-1,-1.0) [junit] 2010-01-26 14:49:47,930 WARN conf.Configuration (Configur=
ation.java:set(601)) - jobclient.output.filter is deprecated. Instead, use =
mapreduce.client.output.filter [junit] 2010-01-26 14:49:47,943 WARN conf.Co=
nfiguration (Configuration.java:set(601)) - mapred.used.genericoptionsparse=
r is deprecated. Instead, use mapreduce.client.genericoptionsparser.used [j=
unit] 2010-01-26 14:49:48,013 WARN mapreduce.JobSubmitter (JobSubmitter.jav=
a:copyAndConfigureFiles(226)) - No job jar file set. User classes may not b=
e found. See Job or Job#setJar(String). [junit] 2010-01-26 14:49:48,088 WAR=
N conf.Configuration (Configuration.java:set(601)) - mapred.map.tasks is de=
precated. Instead, use mapreduce.job.maps [junit] 2010-01-26 14:49:48,088 I=
NFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(351)) - num=
ber of splits:1 [junit] 2010-01-26 14:49:48,293 WARN conf.Configuration (Co=
nfiguration.java:handleDeprecation(332)) - mapred.committer.job.setup.clean=
up.needed is deprecated. Instead, use mapreduce.job.committer.setup.cleanup=
.needed [junit] 2010-01-26 14:49:48,327 INFO mapred.JobTracker (JobTracker.=
java:addJob(3017)) - Job job_20100126144930543_0001 added successfully for =
user 'hudson' to queue 'default' [junit] 2010-01-26 14:49:48,328 INFO mapre=
d.JobTracker (JobTracker.java:initJob(3192)) - Initializing job_20100126144=
930543_0001 [junit] 2010-01-26 14:49:48,330 INFO mapreduce.Job (Job.java:mo=
nitorAndPrintJob(999)) - Running job: job_20100126144930543_0001 [junit] 20=
10-01-26 14:49:48,333 INFO mapred.JobInProgress (JobInProgress.java:initTas=
ks(591)) - Initializing job_20100126144930543_0001 [junit] 2010-01-26 14:49=
:48,369 INFO jobhistory.JobHistory (JobHistory.java:setupEventWriter(242)) =
- SetupWriter, creating file file:/grid/0/hudson/hudson-slave/workspace/Had=
oop-Mapreduce-trunk/trunk/build/test/logs/history/job_20100126144930543_000=
1_hudson [junit] 2010-01-26 14:49:48,549 INFO jobhistory.JobHistory (JobHis=
tory.java:setupEventWriter(256)) - LogDirConfPath is file:/grid/0/hudson/hu=
dson-slave/workspace/Hadoop-Mapreduce-trunk/trunk/build/test/logs/history/j=
ob_20100126144930543_0001_conf.xml [junit] about to write out: token =3D 1;=
 sec =3D 0 [junit] 2010-01-26 14:49:48,638 INFO mapred.JobInProgress (JobIn=
Progress.java:generateAndStoreTokens(3567)) - jobToken generated and stored=
 with users keys in /tmp/hadoop-hudson/mapred/system/job_20100126144930543_=
0001/jobToken [junit] 2010-01-26 14:49:48,645 INFO mapred.JobInProgress (Jo=
bInProgress.java:createMapTasks(722)) - Input size for job job_201001261449=
30543_0001 =3D 0. Number of splits =3D 1 [junit] 2010-01-26 14:49:48,647 IN=
FO mapred.JobInProgress (JobInProgress.java:initTasks(653)) - Job job_20100=
126144930543_0001 initialized successfully with 1 map tasks and 1 reduce ta=
sks. [junit] 2010-01-26 14:49:49,335 INFO mapreduce.Job (Job.java:monitorAn=
dPrintJob(1013)) - map 0% reduce 0% [junit] 2010-01-26 14:49:50,906 INFO ma=
pred.JobTracker (JobTracker.java:createTaskEntry(1770)) - Adding task (JOB_=
SETUP) 'attempt_20100126144930543_0001_m_000002_0' to tip task_201001261449=
30543_0001_m_000002, for tracker 'tracker_host0.foo.com:localhost/127.0.0.1=
:41432' [junit] 2010-01-26 14:49:50,915 INFO mapred.TaskTracker (TaskTracke=
r.java:registerTask(2059)) - LaunchTaskAction (registerTask): attempt_20100=
126144930543_0001_m_000002_0 task's state:UNASSIGNED [junit] 2010-01-26 14:=
49:50,917 INFO mapred.TaskTracker (TaskTracker.java:run(2017)) - Trying to =
launch : attempt_20100126144930543_0001_m_000002_0 which needs 1 slots [jun=
it] 2010-01-26 14:49:50,917 INFO mapred.TaskTracker (TaskTracker.java:run(2=
028)) - In TaskLauncher, current free slots : 2 and trying to launch attemp=
t_20100126144930543_0001_m_000002_0 which needs 1 slots [junit] 2010-01-26 =
14:49:50,918 INFO tasktracker.Localizer (Localizer.java:initializeUserDirs(=
202)) - Initializing user hudson on this TT. [junit] 2010-01-26 14:49:50,99=
5 INFO security.TokenCache (TokenCache.java:loadTokens(142)) - Task: Loaded=
 jobTokenFile from: /tmp/hadoop-hudson/mapred/local/0_0/taskTracker/hudson/=
jobcache/job_20100126144930543_0001/jobToken; num of sec keys =3D 0 [junit]=
 2010-01-26 14:49:51,052 INFO mapred.JvmManager (JvmManager.java:<init>(430=
)) - In JvmRunner constructed JVM ID: jvm_20100126144930543_0001_m_35331837=
 [junit] 2010-01-26 14:49:51,053 INFO mapred.JvmManager (JvmManager.java:sp=
awnNewJvm(398)) - JVM Runner jvm_20100126144930543_0001_m_35331837 spawned.=
 [junit] 2010-01-26 14:49:51,635 INFO security.Groups (Groups.java:getGroup=
s(76)) - Returning cached groups for 'hudson' [junit] 2010-01-26 14:49:51,6=
36 INFO security.SecurityUtil (SecurityUtil.java:getSubject(130)) - Groups =
for 'hudson': <hudson > [junit] 2010-01-26 14:49:51,657 INFO mapred.TaskTra=
cker (TaskTracker.java:getTask(2927)) - JVM with ID: jvm_20100126144930543_=
0001_m_35331837 given task: attempt_20100126144930543_0001_m_000002_0 [juni=
t] 2010-01-26 14:49:51,910 INFO mapred.TaskTracker (TaskTracker.java:report=
Progress(2360)) - attempt_20100126144930543_0001_m_000002_0 0.0% setup > ma=
p [junit] 2010-01-26 14:49:51,912 INFO mapred.TaskTracker (TaskTracker.java=
:reportDone(2441)) - Task attempt_20100126144930543_0001_m_000002_0 is done=
. [junit] 2010-01-26 14:49:51,912 INFO mapred.TaskTracker (TaskTracker.java=
:reportDone(2442)) - reported output size for attempt_20100126144930543_000=
1_m_000002_0 was 0 [junit] 2010-01-26 14:49:51,913 INFO mapred.TaskTracker =
(TaskTracker.java:addFreeSlots(2000)) - addFreeSlot : current free slots : =
2 [junit] 2010-01-26 14:49:52,076 WARN util.ProcessTree (ProcessTree.java:s=
endSignal(130)) - Error executing shell command org.apache.hadoop.util.Shel=
l$ExitCodeException: kill: No such process [junit] [junit] 2010-01-26 14:49=
:52,076 INFO util.ProcessTree (ProcessTree.java:sendSignal(133)) - Sending =
signal to all members of process group -16962: SIGTERM. Exit code 1 [junit]=
 2010-01-26 14:49:53,915 INFO mapred.TaskTracker (TaskTracker.java:tryToGet=
OutputSize(1952)) - org.apache.hadoop.util.DiskChecker$DiskErrorException: =
Could not find output/file.out in any of the configured local directories [=
junit] 2010-01-26 14:49:53,922 INFO mapred.JobInProgress (JobInProgress.jav=
a:completedTask(2563)) - Task 'attempt_20100126144930543_0001_m_000002_0' h=
as completed task_20100126144930543_0001_m_000002 successfully. [junit] 201=
0-01-26 14:49:53,939 INFO mapred.JobQueueTaskScheduler (TestTTResourceRepor=
ting.java:assignTasks(159)) - expected memory values : (totalVirtualMemoryO=
nTT, totalPhysicalMemoryOnTT, availableVirtualMemoryOnTT, availablePhysical=
MemoryOnTT, mapSlotMemSize, reduceSlotMemorySize, cumulativeCpuTime, cpuFre=
quency, numProcessors) =3D (-1, -1,-1, -1,-1,-1,-1,-1,-1,-1.0) [junit] repo=
rted memory values : (totalVirtualMemoryOnTT, totalPhysicalMemoryOnTT, avai=
lableVirtualMemoryOnTT, availablePhysicalMemoryOnTT, reportedMapSlotMemoryS=
ize, reportedReduceSlotMemorySize, reportedCumulativeCpuTime, reportedCpuFr=
equency, reportedNumProcessors) =3D (-1, -1,-1, -1,-1,-1,-1,-1,-1,-1.0) [ju=
nit] 2010-01-26 14:49:53,939 INFO mapred.JobInProgress (JobInProgress.java:=
findNewMapTask(2224)) - Choosing a non-local task task_20100126144930543_00=
01_m_000000 [junit] 2010-01-26 14:49:53,940 INFO mapred.JobTracker (JobTrac=
ker.java:createTaskEntry(1770)) - Adding task (MAP) 'attempt_20100126144930=
543_0001_m_000000_0' to tip task_20100126144930543_0001_m_000000, for track=
er 'tracker_host0.foo.com:localhost/127.0.0.1:41432' [junit] 2010-01-26 14:=
49:53,942 INFO mapred.TaskTracker (TaskTracker.java:registerTask(2059)) - L=
aunchTaskAction (registerTask): attempt_20100126144930543_0001_m_000000_0 t=
ask's state:UNASSIGNED [junit] 2010-01-26 14:49:53,942 INFO mapred.TaskTrac=
ker (TaskTracker.java:run(2017)) - Trying to launch : attempt_2010012614493=
0543_0001_m_000000_0 which needs 1 slots [junit] 2010-01-26 14:49:53,943 IN=
FO mapred.TaskTracker (TaskTracker.java:run(383)) - Received KillTaskAction=
 for task: attempt_20100126144930543_0001_m_000002_0 [junit] 2010-01-26 14:=
49:53,943 INFO mapred.TaskTracker (TaskTracker.java:run(2028)) - In TaskLau=
ncher, current free slots : 2 and trying to launch attempt_2010012614493054=
3_0001_m_000000_0 which needs 1 slots [junit] 2010-01-26 14:49:53,943 INFO =
mapred.TaskTracker (TaskTracker.java:purgeTask(1794)) - About to purge task=
: attempt_20100126144930543_0001_m_000002_0 [junit] 2010-01-26 14:49:53,943=
 INFO tasktracker.Localizer (Localizer.java:initializeUserDirs(197)) - User=
-directories for the user hudson are already initialized on this TT. Not do=
ing anything. [junit] 2010-01-26 14:49:53,944 INFO mapred.TaskRunner (MapTa=
skRunner.java:close(44)) - attempt_20100126144930543_0001_m_000002_0 done; =
removing files. [junit] 2010-01-26 14:49:53,950 INFO mapred.IndexCache (Ind=
exCache.java:removeMap(141)) - Map ID attempt_20100126144930543_0001_m_0000=
02_0 not found in cache [junit] 2010-01-26 14:49:54,024 INFO mapred.JvmMana=
ger (JvmManager.java:<init>(430)) - In JvmRunner constructed JVM ID: jvm_20=
100126144930543_0001_m_331720839 [junit] 2010-01-26 14:49:54,028 INFO mapre=
d.JvmManager (JvmManager.java:spawnNewJvm(398)) - JVM Runner jvm_2010012614=
4930543_0001_m_331720839 spawned. [junit] 2010-01-26 14:49:54,353 INFO mapr=
educe.Job (Job.java:printTaskEvents(1114)) - Task Id : attempt_201001261449=
30543_0001_m_000002_0, Status : SUCCEEDED [junit] attempt_20100126144930543=
_0001_m_000002_0: 2010-01-26 14:49:51,891 INFO jvm.JvmMetrics (JvmMetrics.j=
ava:init(71)) - Initializing JVM Metrics with processName=3DMAP, sessionId=
=3D [junit] attempt_20100126144930543_0001_m_000002_0: 2010-01-26 14:49:51,=
907 INFO mapred.Task (Task.java:done(739)) - Task:attempt_20100126144930543=
_0001_m_000002_0 is done. And is in the process of commiting [junit] attemp=
t_20100126144930543_0001_m_000002_0: 2010-01-26 14:49:51,913 INFO mapred.Ta=
sk (Task.java:sendDone(815)) - Task 'attempt_20100126144930543_0001_m_00000=
2_0' done. [junit] 2010-01-26 14:49:54,650 INFO security.Groups (Groups.jav=
a:getGroups(76)) - Returning cached groups for 'hudson' [junit] 2010-01-26 =
14:49:54,651 INFO security.SecurityUtil (SecurityUtil.java:getSubject(130))=
 - Groups for 'hudson': <hudson > [junit] 2010-01-26 14:49:54,658 INFO mapr=
ed.TaskTracker (TaskTracker.java:getTask(2927)) - JVM with ID: jvm_20100126=
144930543_0001_m_331720839 given task: attempt_20100126144930543_0001_m_000=
000_0 [junit] 2010-01-26 14:49:54,959 INFO mapred.TaskTracker (TaskTracker.=
java:reportProgress(2360)) - attempt_20100126144930543_0001_m_000000_0 0.0%=
 [junit] 2010-01-26 14:49:54,984 INFO mapred.TaskTracker (TaskTracker.java:=
reportProgress(2360)) - attempt_20100126144930543_0001_m_000000_0 0.667% ma=
p > sort [junit] 2010-01-26 14:49:54,985 INFO mapred.TaskTracker (TaskTrack=
er.java:reportDone(2441)) - Task attempt_20100126144930543_0001_m_000000_0 =
is done. [junit] 2010-01-26 14:49:54,986 INFO mapred.TaskTracker (TaskTrack=
er.java:reportDone(2442)) - reported output size for attempt_20100126144930=
543_0001_m_000000_0 was 0 [junit] 2010-01-26 14:49:54,986 INFO mapred.TaskT=
racker (TaskTracker.java:addFreeSlots(2000)) - addFreeSlot : current free s=
lots : 2 [junit] 2010-01-26 14:49:55,158 WARN util.ProcessTree (ProcessTree=
.java:sendSignal(130)) - Error executing shell command org.apache.hadoop.ut=
il.Shell$ExitCodeException: kill: No such process [junit] [junit] 2010-01-2=
6 14:49:55,158 INFO util.ProcessTree (ProcessTree.java:sendSignal(133)) - S=
ending signal to all members of process group -17017: SIGTERM. Exit code 1 =
[junit] 2010-01-26 14:49:56,943 INFO mapred.TaskTracker (TaskTracker.java:t=
ryToGetOutputSize(1952)) - org.apache.hadoop.util.DiskChecker$DiskErrorExce=
ption: Could not find output/file.out in any of the configured local direct=
ories [junit] 2010-01-26 14:49:56,948 INFO mapred.JobInProgress (JobInProgr=
ess.java:completedTask(2563)) - Task 'attempt_20100126144930543_0001_m_0000=
00_0' has completed task_20100126144930543_0001_m_000000 successfully. [jun=
it] 2010-01-26 14:49:56,952 INFO mapred.JobQueueTaskScheduler (TestTTResour=
ceReporting.java:assignTasks(159)) - expected memory values : (totalVirtual=
MemoryOnTT, totalPhysicalMemoryOnTT, availableVirtualMemoryOnTT, availableP=
hysicalMemoryOnTT, mapSlotMemSize, reduceSlotMemorySize, cumulativeCpuTime,=
 cpuFrequency, numProcessors) =3D (-1, -1,-1, -1,-1,-1,-1,-1,-1,-1.0) [juni=
t] reported memory values : (totalVirtualMemoryOnTT, totalPhysicalMemoryOnT=
T, availableVirtualMemoryOnTT, availablePhysicalMemoryOnTT, reportedMapSlot=
MemorySize, reportedReduceSlotMemorySize, reportedCumulativeCpuTime, report=
edCpuFrequency, reportedNumProcessors) =3D (-1, -1,-1, -1,-1,-1,-1,-1,-1,-1=
.0) [junit] 2010-01-26 14:49:56,957 INFO mapred.JobTracker (JobTracker.java=
:createTaskEntry(1770)) - Adding task (REDUCE) 'attempt_20100126144930543_0=
001_r_000000_0' to tip task_20100126144930543_0001_r_000000, for tracker 't=
racker_host0.foo.com:localhost/127.0.0.1:41432' [junit] 2010-01-26 14:49:56=
,958 INFO mapred.TaskTracker (TaskTracker.java:registerTask(2059)) - Launch=
TaskAction (registerTask): attempt_20100126144930543_0001_r_000000_0 task's=
 state:UNASSIGNED [junit] 2010-01-26 14:49:56,959 INFO mapred.TaskTracker (=
TaskTracker.java:run(2017)) - Trying to launch : attempt_20100126144930543_=
0001_r_000000_0 which needs 1 slots [junit] 2010-01-26 14:49:56,959 INFO ma=
pred.TaskTracker (TaskTracker.java:run(2028)) - In TaskLauncher, current fr=
ee slots : 2 and trying to launch attempt_20100126144930543_0001_r_000000_0=
 which needs 1 slots [junit] 2010-01-26 14:49:56,959 INFO tasktracker.Local=
izer (Localizer.java:initializeUserDirs(197)) - User-directories for the us=
er hudson are already initialized on this TT. Not doing anything. [junit] 2=
010-01-26 14:49:57,000 INFO mapred.JvmManager (JvmManager.java:<init>(430))=
 - In JvmRunner constructed JVM ID: jvm_20100126144930543_0001_r_35331837 [=
junit] 2010-01-26 14:49:57,001 INFO mapred.JvmManager (JvmManager.java:spaw=
nNewJvm(398)) - JVM Runner jvm_20100126144930543_0001_r_35331837 spawned. [=
junit] 2010-01-26 14:49:57,092 INFO mapred.JvmManager (JvmManager.java:runC=
hild(457)) - JVM : jvm_20100126144930543_0001_m_35331837 exited with exit c=
ode 0. Number of tasks it ran: 1 [junit] 2010-01-26 14:49:57,530 INFO mapre=
duce.Job (Job.java:printTaskEvents(1114)) - Task Id : attempt_2010012614493=
0543_0001_m_000000_0, Status : SUCCEEDED [junit] attempt_20100126144930543_=
0001_m_000000_0: 2010-01-26 14:49:54,890 INFO jvm.JvmMetrics (JvmMetrics.ja=
va:init(71)) - Initializing JVM Metrics with processName=3DMAP, sessionId=
=3D [junit] attempt_20100126144930543_0001_m_000000_0: 2010-01-26 14:49:54,=
930 INFO mapred.MapTask (MapTask.java:<init>(800)) - mapreduce.task.io.sort=
.mb =3D 10 [junit] attempt_20100126144930543_0001_m_000000_0: 2010-01-26 14=
:49:54,939 INFO mapred.MapTask (MapTask.java:<init>(814)) - data buffer =3D=
 7969177/9961472 [junit] attempt_20100126144930543_0001_m_000000_0: 2010-01=
-26 14:49:54,939 INFO mapred.MapTask (MapTask.java:<init>(815)) - record bu=
ffer =3D 26214/32768 [junit] attempt_20100126144930543_0001_m_000000_0: 201=
0-01-26 14:49:54,960 INFO mapred.MapTask (MapTask.java:flush(1173)) - Start=
ing flush of map output [junit] attempt_20100126144930543_0001_m_000000_0: =
2010-01-26 14:49:54,973 INFO mapred.MapTask (MapTask.java:sortAndSpill(1353=
)) - Finished spill 0 [junit] attempt_20100126144930543_0001_m_000000_0: 20=
10-01-26 14:49:54,976 INFO mapred.Task (Task.java:done(739)) - Task:attempt=
_20100126144930543_0001_m_000000_0 is done. And is in the process of commit=
ing [junit] attempt_20100126144930543_0001_m_000000_0: 2010-01-26 14:49:54,=
986 INFO mapred.Task (Task.java:sendDone(815)) - Task 'attempt_201001261449=
30543_0001_m_000000_0' done. [junit] 2010-01-26 14:49:57,570 INFO security.=
Groups (Groups.java:getGroups(76)) - Returning cached groups for 'hudson' [=
junit] 2010-01-26 14:49:57,570 INFO security.SecurityUtil (SecurityUtil.jav=
a:getSubject(130)) - Groups for 'hudson': <hudson > [junit] 2010-01-26 14:4=
9:57,590 INFO mapred.TaskTracker (TaskTracker.java:getTask(2927)) - JVM wit=
h ID: jvm_20100126144930543_0001_r_35331837 given task: attempt_20100126144=
930543_0001_r_000000_0 [junit] 2010-01-26 14:49:58,139 INFO mapred.TaskTrac=
ker (TaskTracker.java:sendMapFile(3466)) - Sent out 12 bytes to reduce 0 fr=
om map: attempt_20100126144930543_0001_m_000000_0 given 12/8 [junit] 2010-0=
1-26 14:49:58,140 INFO mapred.TaskTracker (TaskTracker.java:doGet(3341)) - =
Shuffled 1maps (mapIds=3Dattempt_20100126144930543_0001_m_000000_0) to redu=
ce 0 in 15s [junit] 2010-01-26 14:49:58,141 INFO TaskTracker.clienttrace (T=
askTracker.java:doGet(3346)) - src: 127.0.0.1:53541, dest: 127.0.0.1:50514,=
 maps: 1, op: MAPRED_SHUFFLE, reduceID: 0, duration: 15 [junit] 2010-01-26 =
14:49:58,148 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(2360)=
) - attempt_20100126144930543_0001_r_000000_0 0.0% 1 / 1 copied. [junit] 20=
10-01-26 14:49:58,191 INFO mapred.TaskTracker (TaskTracker.java:reportProgr=
ess(2360)) - attempt_20100126144930543_0001_r_000000_0 0.0% 1 / 1 copied. [=
junit] 2010-01-26 14:49:58,229 INFO mapred.TaskTracker (TaskTracker.java:re=
portProgress(2360)) - attempt_20100126144930543_0001_r_000000_0 1.0% reduce=
 > reduce [junit] 2010-01-26 14:49:58,231 INFO mapred.TaskTracker (TaskTrac=
ker.java:reportDone(2441)) - Task attempt_20100126144930543_0001_r_000000_0=
 is done. [junit] 2010-01-26 14:49:58,231 INFO mapred.TaskTracker (TaskTrac=
ker.java:reportDone(2442)) - reported output size for attempt_2010012614493=
0543_0001_r_000000_0 was 0 [junit] 2010-01-26 14:49:58,232 INFO mapred.Task=
Tracker (TaskTracker.java:addFreeSlots(2000)) - addFreeSlot : current free =
slots : 2 [junit] 2010-01-26 14:49:58,372 WARN util.ProcessTree (ProcessTre=
e.java:sendSignal(130)) - Error executing shell command org.apache.hadoop.u=
til.Shell$ExitCodeException: kill: No such process [junit] [junit] 2010-01-=
26 14:49:58,373 INFO util.ProcessTree (ProcessTree.java:sendSignal(133)) - =
Sending signal to all members of process group -17066: SIGTERM. Exit code 1=
 [junit] 2010-01-26 14:49:58,535 INFO mapreduce.Job (Job.java:monitorAndPri=
ntJob(1013)) - map 100% reduce 0% [junit] 2010-01-26 14:49:59,961 INFO mapr=
ed.JobInProgress (JobInProgress.java:completedTask(2563)) - Task 'attempt_2=
0100126144930543_0001_r_000000_0' has completed task_20100126144930543_0001=
_r_000000 successfully. [junit] 2010-01-26 14:49:59,968 INFO mapred.JobTrac=
ker (JobTracker.java:createTaskEntry(1770)) - Adding task (JOB_CLEANUP) 'at=
tempt_20100126144930543_0001_m_000001_0' to tip task_20100126144930543_0001=
_m_000001, for tracker 'tracker_host0.foo.com:localhost/127.0.0.1:41432' [j=
unit] 2010-01-26 14:49:59,970 INFO mapred.TaskTracker (TaskTracker.java:reg=
isterTask(2059)) - LaunchTaskAction (registerTask): attempt_201001261449305=
43_0001_m_000001_0 task's state:UNASSIGNED [junit] 2010-01-26 14:49:59,971 =
INFO mapred.TaskTracker (TaskTracker.java:run(383)) - Received KillTaskActi=
on for task: attempt_20100126144930543_0001_r_000000_0 [junit] 2010-01-26 1=
4:49:59,972 INFO mapred.TaskTracker (TaskTracker.java:purgeTask(1794)) - Ab=
out to purge task: attempt_20100126144930543_0001_r_000000_0 [junit] 2010-0=
1-26 14:49:59,972 INFO mapred.TaskRunner (ReduceTaskRunner.java:close(48)) =
- attempt_20100126144930543_0001_r_000000_0 done; removing files. [junit] 2=
010-01-26 14:49:59,980 INFO mapred.TaskTracker (TaskTracker.java:run(2017))=
 - Trying to launch : attempt_20100126144930543_0001_m_000001_0 which needs=
 1 slots [junit] 2010-01-26 14:49:59,981 INFO mapred.TaskTracker (TaskTrack=
er.java:run(2028)) - In TaskLauncher, current free slots : 2 and trying to =
launch attempt_20100126144930543_0001_m_000001_0 which needs 1 slots [junit=
] 2010-01-26 14:49:59,982 INFO tasktracker.Localizer (Localizer.java:initia=
lizeUserDirs(197)) - User-directories for the user hudson are already initi=
alized on this TT. Not doing anything. [junit] 2010-01-26 14:50:00,036 INFO=
 mapred.JvmManager (JvmManager.java:<init>(430)) - In JvmRunner constructed=
 JVM ID: jvm_20100126144930543_0001_m_-1906794465 [junit] 2010-01-26 14:50:=
00,038 INFO mapred.JvmManager (JvmManager.java:spawnNewJvm(398)) - JVM Runn=
er jvm_20100126144930543_0001_m_-1906794465 spawned. [junit] 2010-01-26 14:=
50:00,189 INFO mapred.JvmManager (JvmManager.java:runChild(457)) - JVM : jv=
m_20100126144930543_0001_m_331720839 exited with exit code 0. Number of tas=
ks it ran: 1 [junit] 2010-01-26 14:50:00,541 INFO mapreduce.Job (Job.java:p=
rintTaskEvents(1114)) - Task Id : attempt_20100126144930543_0001_r_000000_0=
, Status : SUCCEEDED [junit] attempt_20100126144930543_0001_r_000000_0: 201=
0-01-26 14:49:57,834 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initi=
alizing JVM Metrics with processName=3DSHUFFLE, sessionId=3D [junit] attemp=
t_20100126144930543_0001_r_000000_0: 2010-01-26 14:49:57,865 INFO reduce.Me=
rgeManager (MergeManager.java:<init>(175)) - MergerManager: memoryLimit=3D1=
41387360, maxSingleShuffleLimit=3D35346840, mergeThreshold=3D93315664, ioSo=
rtFactor=3D10, memToMemMergeOutputsThreshold=3D10 [junit] attempt_201001261=
44930543_0001_r_000000_0: 2010-01-26 14:49:57,868 INFO reduce.EventFetcher =
(EventFetcher.java:run(61)) - attempt_20100126144930543_0001_r_000000_0 Thr=
ead started: EventFetcher for fetching Map Completion Events [junit] attemp=
t_20100126144930543_0001_r_000000_0: 2010-01-26 14:49:57,878 INFO reduce.Sh=
uffleScheduler (ShuffleScheduler.java:getHost(303)) - Assiging localhost:53=
541 with 1 to fetcher#3 [junit] attempt_20100126144930543_0001_r_000000_0: =
2010-01-26 14:49:57,878 INFO reduce.ShuffleScheduler (ShuffleScheduler.java=
:getMapsForHost(333)) - assigned 1 of 1 to localhost:53541 to fetcher#3 [ju=
nit] attempt_20100126144930543_0001_r_000000_0: 2010-01-26 14:49:57,879 INF=
O reduce.EventFetcher (EventFetcher.java:run(69)) - attempt_201001261449305=
43_0001_r_000000_0: Got 1 new map-outputs [junit] attempt_20100126144930543=
_0001_r_000000_0: 2010-01-26 14:49:58,142 INFO reduce.Fetcher (Fetcher.java=
:copyFromHost(216)) - for url=3D53541/mapOutput?job=3Djob_20100126144930543=
_0001&reduce=3D0&map=3Dattempt_20100126144930543_0001_m_000000_0 sent hash =
and receievd reply [junit] attempt_20100126144930543_0001_r_000000_0: 2010-=
01-26 14:49:58,143 INFO reduce.Fetcher (Fetcher.java:copyMapOutput(320)) - =
fetcher#3 about to shuffle output of map attempt_20100126144930543_0001_m_0=
00000_0 decomp: 8 len: 12 to MEMORY [junit] attempt_20100126144930543_0001_=
r_000000_0: 2010-01-26 14:49:58,144 INFO reduce.Fetcher (Fetcher.java:shuff=
leToMemory(488)) - Read 8 bytes from map-output for attempt_201001261449305=
43_0001_m_000000_0 [junit] attempt_20100126144930543_0001_r_000000_0: 2010-=
01-26 14:49:58,144 INFO reduce.MergeManager (MergeManager.java:closeInMemor=
yFile(274)) - closeInMemoryFile -> map-output of size: 8, inMemoryMapOutput=
s.size() -> 1 [junit] attempt_20100126144930543_0001_r_000000_0: 2010-01-26=
 14:49:58,146 INFO reduce.ShuffleScheduler (ShuffleScheduler.java:freeHost(=
345)) - localhost:53541 freed by fetcher#3 in 267s [junit] attempt_20100126=
144930543_0001_r_000000_0: 2010-01-26 14:49:58,148 INFO reduce.MergeManager=
 (MergeManager.java:finalMerge(626)) - finalMerge called with 1 in-memory m=
ap-outputs and 0 on-disk map-outputs [junit] attempt_20100126144930543_0001=
_r_000000_0: 2010-01-26 14:49:58,168 INFO mapred.Merger (Merger.java:merge(=
543)) - Merging 1 sorted segments [junit] attempt_20100126144930543_0001_r_=
000000_0: 2010-01-26 14:49:58,168 INFO mapred.Merger (Merger.java:merge(642=
)) - Down to the last merge-pass, with 1 segments left of total size: 2 byt=
es [junit] attempt_20100126144930543_0001_r_000000_0: 2010-01-26 14:49:58,1=
84 INFO reduce.MergeManager (MergeManager.java:finalMerge(698)) - Merged 1 =
segments, 8 bytes to disk to satisfy reduce memory limit [junit] attempt_20=
100126144930543_0001_r_000000_0: 2010-01-26 14:49:58,185 INFO reduce.MergeM=
anager (MergeManager.java:finalMerge(724)) - Merging 1 files, 12 bytes from=
 disk [junit] attempt_20100126144930543_0001_r_000000_0: 2010-01-26 14:49:5=
8,186 INFO reduce.MergeManager (MergeManager.java:finalMerge(739)) - Mergin=
g 0 segments, 0 bytes from memory into reduce [junit] attempt_2010012614493=
0543_0001_r_000000_0: 2010-01-26 14:49:58,186 INFO mapred.Merger (Merger.ja=
va:merge(543)) - Merging 1 sorted segments [junit] attempt_2010012614493054=
3_0001_r_000000_0: 2010-01-26 14:49:58,189 INFO mapred.Merger (Merger.java:=
merge(642)) - Down to the last merge-pass, with 1 segments left of total si=
ze: 2 bytes [junit] attempt_20100126144930543_0001_r_000000_0: 2010-01-26 1=
4:49:58,194 WARN conf.Configuration (Configuration.java:set(601)) - mapred.=
skip.on is deprecated. Instead, use mapreduce.job.skiprecords [junit] attem=
pt_20100126144930543_0001_r_000000_0: 2010-01-26 14:49:58,222 INFO mapred.T=
ask (Task.java:done(739)) - Task:attempt_20100126144930543_0001_r_000000_0 =
is done. And is in the process of commiting [junit] attempt_201001261449305=
43_0001_r_000000_0: 2010-01-26 14:49:58,232 INFO mapred.Task (Task.java:sen=
dDone(815)) - Task 'attempt_20100126144930543_0001_r_000000_0' done. [junit=
] 2010-01-26 14:50:00,628 INFO security.Groups (Groups.java:getGroups(76)) =
- Returning cached groups for 'hudson' [junit] 2010-01-26 14:50:00,628 INFO=
 security.SecurityUtil (SecurityUtil.java:getSubject(130)) - Groups for 'hu=
dson': <hudson > [junit] 2010-01-26 14:50:00,634 INFO mapred.TaskTracker (T=
askTracker.java:getTask(2927)) - JVM with ID: jvm_20100126144930543_0001_m_=
-1906794465 given task: attempt_20100126144930543_0001_m_000001_0 [junit] 2=
010-01-26 14:50:00,909 INFO mapred.TaskTracker (TaskTracker.java:reportProg=
ress(2360)) - attempt_20100126144930543_0001_m_000001_0 0.0% [junit] 2010-0=
1-26 14:50:00,914 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(=
2360)) - attempt_20100126144930543_0001_m_000001_0 0.0% cleanup > map [juni=
t] 2010-01-26 14:50:00,917 INFO mapred.TaskTracker (TaskTracker.java:report=
Done(2441)) - Task attempt_20100126144930543_0001_m_000001_0 is done. [juni=
t] 2010-01-26 14:50:00,917 INFO mapred.TaskTracker (TaskTracker.java:report=
Done(2442)) - reported output size for attempt_20100126144930543_0001_m_000=
001_0 was 0 [junit] 2010-01-26 14:50:00,918 INFO mapred.TaskTracker (TaskTr=
acker.java:addFreeSlots(2000)) - addFreeSlot : current free slots : 2 [juni=
t] 2010-01-26 14:50:01,067 WARN util.ProcessTree (ProcessTree.java:sendSign=
al(130)) - Error executing shell command org.apache.hadoop.util.Shell$ExitC=
odeException: kill: No such process [junit] [junit] 2010-01-26 14:50:01,067=
 INFO util.ProcessTree (ProcessTree.java:sendSignal(133)) - Sending signal =
to all members of process group -17135: SIGTERM. Exit code 1 [junit] 2010-0=
1-26 14:50:01,549 INFO mapreduce.Job (Job.java:monitorAndPrintJob(1013)) - =
map 100% reduce 100% [junit] 2010-01-26 14:50:02,971 INFO mapred.TaskTracke=
r (TaskTracker.java:tryToGetOutputSize(1952)) - org.apache.hadoop.util.Disk=
Checker$DiskErrorException: Could not find output/file.out in any of the co=
nfigured local directories [junit] 2010-01-26 14:50:02,975 INFO mapred.JobI=
nProgress (JobInProgress.java:completedTask(2563)) - Task 'attempt_20100126=
144930543_0001_m_000001_0' has completed task_20100126144930543_0001_m_0000=
01 successfully. [junit] 2010-01-26 14:50:02,977 INFO mapred.JobInProgress =
(JobInProgress.java:jobComplete(2764)) - Job job_20100126144930543_0001 has=
 completed successfully. [junit] 2010-01-26 14:50:02,979 INFO mapred.JobInP=
rogress$JobSummary (JobInProgress.java:logJobSummary(3471)) - jobId=3Djob_2=
0100126144930543_0001,submitTime=3D1264517388178,launchTime=3D1264517388645=
,finishTime=3D1264517402977,numMaps=3D1,numSlotsPerMap=3D1,numReduces=3D1,n=
umSlotsPerReduce=3D1,user=3Dhudson,queue=3Ddefault,status=3DSUCCEEDED,mapSl=
otSeconds=3D2,reduceSlotsSeconds=3D1,clusterMapCapacity=3D2,clusterReduceCa=
pacity=3D2 [junit] 2010-01-26 14:50:02,989 INFO jobhistory.JobHistory (JobH=
istory.java:moveToDoneNow(315)) - Moving file:/grid/0/hudson/hudson-slave/w=
orkspace/Hadoop-Mapreduce-trunk/trunk/build/test/logs/history/job_201001261=
44930543_0001_hudson to file:/grid/0/hudson/hudson-slave/workspace/Hadoop-M=
apreduce-trunk/trunk/build/test/logs/history/done/job_20100126144930543_000=
1_hudson [junit] 2010-01-26 14:50:02,990 INFO mapred.JobQueueTaskScheduler =
(TestTTResourceReporting.java:assignTasks(159)) - expected memory values : =
(totalVirtualMemoryOnTT, totalPhysicalMemoryOnTT, availableVirtualMemoryOnT=
T, availablePhysicalMemoryOnTT, mapSlotMemSize, reduceSlotMemorySize, cumul=
ativeCpuTime, cpuFrequency, numProcessors) =3D (-1, -1,-1, -1,-1,-1,-1,-1,-=
1,-1.0) [junit] reported memory values : (totalVirtualMemoryOnTT, totalPhys=
icalMemoryOnTT, availableVirtualMemoryOnTT, availablePhysicalMemoryOnTT, re=
portedMapSlotMemorySize, reportedReduceSlotMemorySize, reportedCumulativeCp=
uTime, reportedCpuFrequency, reportedNumProcessors) =3D (-1, -1,-1, -1,-1,-=
1,-1,-1,-1,-1.0) [junit] 2010-01-26 14:50:02,991 INFO mapred.JobTracker (Jo=
bTracker.java:removeTaskEntry(1805)) - Removing task 'attempt_2010012614493=
0543_0001_m_000000_0' [junit] 2010-01-26 14:50:02,991 INFO mapred.JobTracke=
r (JobTracker.java:removeTaskEntry(1805)) - Removing task 'attempt_20100126=
144930543_0001_m_000001_0' [junit] 2010-01-26 14:50:02,991 INFO mapred.JobT=
racker (JobTracker.java:removeTaskEntry(1805)) - Removing task 'attempt_201=
00126144930543_0001_m_000002_0' [junit] 2010-01-26 14:50:02,991 INFO mapred=
.JobTracker (JobTracker.java:removeTaskEntry(1805)) - Removing task 'attemp=
t_20100126144930543_0001_r_000000_0' [junit] 2010-01-26 14:50:02,992 INFO m=
apred.TaskTracker (TaskTracker.java:purgeJob(1738)) - Received 'KillJobActi=
on' for job: job_20100126144930543_0001 [junit] 2010-01-26 14:50:02,993 INF=
O mapred.TaskRunner (MapTaskRunner.java:close(44)) - attempt_20100126144930=
543_0001_m_000000_0 done; removing files. [junit] 2010-01-26 14:50:03,000 I=
NFO mapred.TaskRunner (MapTaskRunner.java:close(44)) - attempt_201001261449=
30543_0001_m_000001_0 done; removing files. [junit] 2010-01-26 14:50:03,012=
 INFO mapred.IndexCache (IndexCache.java:removeMap(141)) - Map ID attempt_2=
0100126144930543_0001_m_000001_0 not found in cache [junit] 2010-01-26 14:5=
0:03,035 INFO jobhistory.JobHistory (JobHistory.java:moveToDoneNow(315)) - =
Moving file:/grid/0/hudson/hudson-slave/workspace/Hadoop-Mapreduce-trunk/tr=
unk/build/test/logs/history/job_20100126144930543_0001_conf.xml to file:/gr=
id/0/hudson/hudson-slave/workspace/Hadoop-Mapreduce-trunk/trunk/build/test/=
logs/history/done/job_20100126144930543_0001_conf.xml [junit] 2010-01-26 14=
:50:03,084 INFO mapred.JobInProgress (JobInProgress.java:cleanupLocalizedJo=
bConf(3535)) - Deleting localized job conf at /grid/0/hudson/hudson-slave/w=
orkspace/Hadoop-Mapreduce-trunk/trunk/build/test/logs/job_20100126144930543=
_0001_conf.xml [junit] 2010-01-26 14:50:03,390 INFO mapred.JvmManager (JvmM=
anager.java:runChild(457)) - JVM : jvm_20100126144930543_0001_r_35331837 ex=
ited with exit code 0. Number of tasks it ran: 1 [junit] 2010-01-26 14:50:0=
3,556 INFO mapreduce.Job (Job.java:printTaskEvents(1114)) - Task Id : attem=
pt_20100126144930543_0001_m_000001_0, Status : SUCCEEDED [junit] attempt_20=
100126144930543_0001_m_000001_0: 2010-01-26 14:50:00,890 INFO jvm.JvmMetric=
s (JvmMetrics.java:init(71)) - Initializing JVM Metrics with processName=3D=
MAP, sessionId=3D [junit] attempt_20100126144930543_0001_m_000001_0: 2010-0=
1-26 14:50:00,910 INFO mapred.Task (Task.java:runJobCleanupTask(904)) - Cle=
aning up job [junit] attempt_20100126144930543_0001_m_000001_0: 2010-01-26 =
14:50:00,910 INFO mapred.Task (Task.java:runJobCleanupTask(916)) - Committi=
ng job [junit] attempt_20100126144930543_0001_m_000001_0: 2010-01-26 14:50:=
00,912 INFO mapred.Task (Task.java:done(739)) - Task:attempt_20100126144930=
543_0001_m_000001_0 is done. And is in the process of commiting [junit] att=
empt_20100126144930543_0001_m_000001_0: 2010-01-26 14:50:00,918 INFO mapred=
.Task (Task.java:sendDone(815)) - Task 'attempt_20100126144930543_0001_m_00=
0001_0' done. [junit] 2010-01-26 14:50:03,561 INFO mapreduce.Job (Job.java:=
monitorAndPrintJob(1022)) - Job complete: job_20100126144930543_0001 [junit=
] 2010-01-26 14:50:03,565 INFO mapreduce.Job (Job.java:monitorAndPrintJob(1=
025)) - Counters: 28=20

--=20
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.