hadoop-mapreduce-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "dhruba borthakur (JIRA)" <j...@apache.org>
Subject [jira] Commented: (MAPREDUCE-1420) TestTTResourceReporting failing in trunk
Date Thu, 28 Jan 2010 01:16:34 GMT

    [ https://issues.apache.org/jira/browse/MAPREDUCE-1420?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12805737#action_12805737
] 

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. 
> The most specific issue from the logs seems to be : Error executing shell command org.apache.hadoop.util.Shell$ExitCodeException:
kill: No such process 
> Link :
> http://hudson.zones.apache.org/hudson/view/Hadoop/job/Hadoop-Mapreduce-trunk/217/
> Giving the complete raw output:
> [junit] 2010-01-26 14:49:47,885 INFO mapred.JobQueueTaskScheduler (TestTTResourceReporting.java:assignTasks(159))
- expected memory values : (totalVirtualMemoryOnTT, totalPhysicalMemoryOnTT, availableVirtualMemoryOnTT,
availablePhysicalMemoryOnTT, mapSlotMemSize, reduceSlotMemorySize, cumulativeCpuTime, cpuFrequency,
numProcessors) = (-1, -1,-1, -1,-1,-1,-1,-1,-1,-1.0) [junit] reported memory values : (totalVirtualMemoryOnTT,
totalPhysicalMemoryOnTT, availableVirtualMemoryOnTT, availablePhysicalMemoryOnTT, reportedMapSlotMemorySize,
reportedReduceSlotMemorySize, reportedCumulativeCpuTime, reportedCpuFrequency, reportedNumProcessors)
= (-1, -1,-1, -1,-1,-1,-1,-1,-1,-1.0) [junit] 2010-01-26 14:49:47,930 WARN conf.Configuration
(Configuration.java:set(601)) - jobclient.output.filter is deprecated. Instead, use mapreduce.client.output.filter
[junit] 2010-01-26 14:49:47,943 WARN conf.Configuration (Configuration.java:set(601)) - mapred.used.genericoptionsparser
is deprecated. Instead, use mapreduce.client.genericoptionsparser.used [junit] 2010-01-26
14:49:48,013 WARN mapreduce.JobSubmitter (JobSubmitter.java:copyAndConfigureFiles(226)) -
No job jar file set. User classes may not be found. See Job or Job#setJar(String). [junit]
2010-01-26 14:49:48,088 WARN conf.Configuration (Configuration.java:set(601)) - mapred.map.tasks
is deprecated. Instead, use mapreduce.job.maps [junit] 2010-01-26 14:49:48,088 INFO mapreduce.JobSubmitter
(JobSubmitter.java:submitJobInternal(351)) - number of splits:1 [junit] 2010-01-26 14:49:48,293
WARN conf.Configuration (Configuration.java:handleDeprecation(332)) - mapred.committer.job.setup.cleanup.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
mapred.JobTracker (JobTracker.java:initJob(3192)) - Initializing job_20100126144930543_0001
[junit] 2010-01-26 14:49:48,330 INFO mapreduce.Job (Job.java:monitorAndPrintJob(999)) - Running
job: job_20100126144930543_0001 [junit] 2010-01-26 14:49:48,333 INFO mapred.JobInProgress
(JobInProgress.java:initTasks(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/Hadoop-Mapreduce-trunk/trunk/build/test/logs/history/job_20100126144930543_0001_hudson
[junit] 2010-01-26 14:49:48,549 INFO jobhistory.JobHistory (JobHistory.java:setupEventWriter(256))
- LogDirConfPath is file:/grid/0/hudson/hudson-slave/workspace/Hadoop-Mapreduce-trunk/trunk/build/test/logs/history/job_20100126144930543_0001_conf.xml
[junit] about to write out: token = 1; sec = 0 [junit] 2010-01-26 14:49:48,638 INFO mapred.JobInProgress
(JobInProgress.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 (JobInProgress.java:createMapTasks(722)) - Input size
for job job_20100126144930543_0001 = 0. Number of splits = 1 [junit] 2010-01-26 14:49:48,647
INFO mapred.JobInProgress (JobInProgress.java:initTasks(653)) - Job job_20100126144930543_0001
initialized successfully with 1 map tasks and 1 reduce tasks. [junit] 2010-01-26 14:49:49,335
INFO mapreduce.Job (Job.java:monitorAndPrintJob(1013)) - map 0% reduce 0% [junit] 2010-01-26
14:49:50,906 INFO mapred.JobTracker (JobTracker.java:createTaskEntry(1770)) - Adding task
(JOB_SETUP) 'attempt_20100126144930543_0001_m_000002_0' to tip task_20100126144930543_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 (TaskTracker.java:registerTask(2059)) - LaunchTaskAction (registerTask):
attempt_20100126144930543_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 [junit] 2010-01-26 14:49:50,917 INFO mapred.TaskTracker (TaskTracker.java:run(2028))
- In TaskLauncher, current free slots : 2 and trying to launch attempt_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,995 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 = 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:spawnNewJvm(398)) - JVM Runner jvm_20100126144930543_0001_m_35331837
spawned. [junit] 2010-01-26 14:49:51,635 INFO security.Groups (Groups.java:getGroups(76))
- Returning cached groups for 'hudson' [junit] 2010-01-26 14:49:51,636 INFO security.SecurityUtil
(SecurityUtil.java:getSubject(130)) - Groups for 'hudson': <hudson > [junit] 2010-01-26
14:49:51,657 INFO mapred.TaskTracker (TaskTracker.java:getTask(2927)) - JVM with ID: jvm_20100126144930543_0001_m_35331837
given task: attempt_20100126144930543_0001_m_000002_0 [junit] 2010-01-26 14:49:51,910 INFO
mapred.TaskTracker (TaskTracker.java:reportProgress(2360)) - attempt_20100126144930543_0001_m_000002_0
0.0% setup > map [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_0001_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:sendSignal(130)) - Error executing shell command org.apache.hadoop.util.Shell$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:tryToGetOutputSize(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.java:completedTask(2563)) - Task 'attempt_20100126144930543_0001_m_000002_0'
has completed task_20100126144930543_0001_m_000002 successfully. [junit] 2010-01-26 14:49:53,939
INFO mapred.JobQueueTaskScheduler (TestTTResourceReporting.java:assignTasks(159)) - expected
memory values : (totalVirtualMemoryOnTT, totalPhysicalMemoryOnTT, availableVirtualMemoryOnTT,
availablePhysicalMemoryOnTT, mapSlotMemSize, reduceSlotMemorySize, cumulativeCpuTime, cpuFrequency,
numProcessors) = (-1, -1,-1, -1,-1,-1,-1,-1,-1,-1.0) [junit] reported memory values : (totalVirtualMemoryOnTT,
totalPhysicalMemoryOnTT, availableVirtualMemoryOnTT, availablePhysicalMemoryOnTT, reportedMapSlotMemorySize,
reportedReduceSlotMemorySize, reportedCumulativeCpuTime, reportedCpuFrequency, reportedNumProcessors)
= (-1, -1,-1, -1,-1,-1,-1,-1,-1,-1.0) [junit] 2010-01-26 14:49:53,939 INFO mapred.JobInProgress
(JobInProgress.java:findNewMapTask(2224)) - Choosing a non-local task task_20100126144930543_0001_m_000000
[junit] 2010-01-26 14:49:53,940 INFO mapred.JobTracker (JobTracker.java:createTaskEntry(1770))
- Adding task (MAP) 'attempt_20100126144930543_0001_m_000000_0' to tip task_20100126144930543_0001_m_000000,
for tracker '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)) - LaunchTaskAction (registerTask):
attempt_20100126144930543_0001_m_000000_0 task's state:UNASSIGNED [junit] 2010-01-26 14:49:53,942
INFO mapred.TaskTracker (TaskTracker.java:run(2017)) - Trying to launch : attempt_20100126144930543_0001_m_000000_0
which needs 1 slots [junit] 2010-01-26 14:49:53,943 INFO 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 TaskLauncher, current
free slots : 2 and trying to launch attempt_20100126144930543_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 doing anything. [junit] 2010-01-26
14:49:53,944 INFO mapred.TaskRunner (MapTaskRunner.java:close(44)) - attempt_20100126144930543_0001_m_000002_0
done; removing files. [junit] 2010-01-26 14:49:53,950 INFO mapred.IndexCache (IndexCache.java:removeMap(141))
- Map ID attempt_20100126144930543_0001_m_000002_0 not found in cache [junit] 2010-01-26 14:49:54,024
INFO mapred.JvmManager (JvmManager.java:<init>(430)) - In JvmRunner constructed JVM
ID: jvm_20100126144930543_0001_m_331720839 [junit] 2010-01-26 14:49:54,028 INFO mapred.JvmManager
(JvmManager.java:spawnNewJvm(398)) - JVM Runner jvm_20100126144930543_0001_m_331720839 spawned.
[junit] 2010-01-26 14:49:54,353 INFO mapreduce.Job (Job.java:printTaskEvents(1114)) - Task
Id : attempt_20100126144930543_0001_m_000002_0, Status : SUCCEEDED [junit] attempt_20100126144930543_0001_m_000002_0:
2010-01-26 14:49:51,891 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM
Metrics with processName=MAP, sessionId= [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] attempt_20100126144930543_0001_m_000002_0:
2010-01-26 14:49:51,913 INFO mapred.Task (Task.java:sendDone(815)) - Task 'attempt_20100126144930543_0001_m_000002_0'
done. [junit] 2010-01-26 14:49:54,650 INFO security.Groups (Groups.java: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 mapred.TaskTracker
(TaskTracker.java:getTask(2927)) - JVM with ID: jvm_20100126144930543_0001_m_331720839 given
task: attempt_20100126144930543_0001_m_000000_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% map > sort [junit] 2010-01-26 14:49:54,985
INFO mapred.TaskTracker (TaskTracker.java:reportDone(2441)) - Task attempt_20100126144930543_0001_m_000000_0
is done. [junit] 2010-01-26 14:49:54,986 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2442))
- reported output size for attempt_20100126144930543_0001_m_000000_0 was 0 [junit] 2010-01-26
14:49:54,986 INFO mapred.TaskTracker (TaskTracker.java:addFreeSlots(2000)) - addFreeSlot :
current free slots : 2 [junit] 2010-01-26 14:49:55,158 WARN util.ProcessTree (ProcessTree.java:sendSignal(130))
- Error executing shell command org.apache.hadoop.util.Shell$ExitCodeException: kill: No such
process [junit] [junit] 2010-01-26 14:49:55,158 INFO util.ProcessTree (ProcessTree.java:sendSignal(133))
- Sending 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:tryToGetOutputSize(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:56,948 INFO mapred.JobInProgress (JobInProgress.java:completedTask(2563)) - Task 'attempt_20100126144930543_0001_m_000000_0'
has completed task_20100126144930543_0001_m_000000 successfully. [junit] 2010-01-26 14:49:56,952
INFO mapred.JobQueueTaskScheduler (TestTTResourceReporting.java:assignTasks(159)) - expected
memory values : (totalVirtualMemoryOnTT, totalPhysicalMemoryOnTT, availableVirtualMemoryOnTT,
availablePhysicalMemoryOnTT, mapSlotMemSize, reduceSlotMemorySize, cumulativeCpuTime, cpuFrequency,
numProcessors) = (-1, -1,-1, -1,-1,-1,-1,-1,-1,-1.0) [junit] reported memory values : (totalVirtualMemoryOnTT,
totalPhysicalMemoryOnTT, availableVirtualMemoryOnTT, availablePhysicalMemoryOnTT, reportedMapSlotMemorySize,
reportedReduceSlotMemorySize, reportedCumulativeCpuTime, reportedCpuFrequency, reportedNumProcessors)
= (-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_0001_r_000000_0'
to tip task_20100126144930543_0001_r_000000, for tracker 'tracker_host0.foo.com:localhost/127.0.0.1:41432'
[junit] 2010-01-26 14:49:56,958 INFO mapred.TaskTracker (TaskTracker.java:registerTask(2059))
- LaunchTaskAction (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 mapred.TaskTracker (TaskTracker.java:run(2028)) - In TaskLauncher, current
free 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.Localizer (Localizer.java:initializeUserDirs(197))
- User-directories for the user hudson are already initialized on this TT. Not doing anything.
[junit] 2010-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:spawnNewJvm(398)) - JVM Runner jvm_20100126144930543_0001_r_35331837
spawned. [junit] 2010-01-26 14:49:57,092 INFO mapred.JvmManager (JvmManager.java:runChild(457))
- JVM : jvm_20100126144930543_0001_m_35331837 exited with exit code 0. Number of tasks it
ran: 1 [junit] 2010-01-26 14:49:57,530 INFO mapreduce.Job (Job.java:printTaskEvents(1114))
- Task Id : attempt_20100126144930543_0001_m_000000_0, Status : SUCCEEDED [junit] attempt_20100126144930543_0001_m_000000_0:
2010-01-26 14:49:54,890 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM
Metrics with processName=MAP, sessionId= [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
= 10 [junit] attempt_20100126144930543_0001_m_000000_0: 2010-01-26 14:49:54,939 INFO mapred.MapTask
(MapTask.java:<init>(814)) - data buffer = 7969177/9961472 [junit] attempt_20100126144930543_0001_m_000000_0:
2010-01-26 14:49:54,939 INFO mapred.MapTask (MapTask.java:<init>(815)) - record buffer
= 26214/32768 [junit] attempt_20100126144930543_0001_m_000000_0: 2010-01-26 14:49:54,960 INFO
mapred.MapTask (MapTask.java:flush(1173)) - Starting 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: 2010-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 commiting [junit] attempt_20100126144930543_0001_m_000000_0: 2010-01-26 14:49:54,986
INFO mapred.Task (Task.java:sendDone(815)) - Task 'attempt_20100126144930543_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.java:getSubject(130))
- Groups for 'hudson': <hudson > [junit] 2010-01-26 14:49:57,590 INFO mapred.TaskTracker
(TaskTracker.java:getTask(2927)) - JVM with ID: jvm_20100126144930543_0001_r_35331837 given
task: attempt_20100126144930543_0001_r_000000_0 [junit] 2010-01-26 14:49:58,139 INFO mapred.TaskTracker
(TaskTracker.java:sendMapFile(3466)) - Sent out 12 bytes to reduce 0 from map: attempt_20100126144930543_0001_m_000000_0
given 12/8 [junit] 2010-01-26 14:49:58,140 INFO mapred.TaskTracker (TaskTracker.java:doGet(3341))
- Shuffled 1maps (mapIds=attempt_20100126144930543_0001_m_000000_0) to reduce 0 in 15s [junit]
2010-01-26 14:49:58,141 INFO TaskTracker.clienttrace (TaskTracker.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] 2010-01-26 14:49:58,191
INFO mapred.TaskTracker (TaskTracker.java:reportProgress(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:reportProgress(2360))
- attempt_20100126144930543_0001_r_000000_0 1.0% reduce > reduce [junit] 2010-01-26 14:49:58,231
INFO mapred.TaskTracker (TaskTracker.java:reportDone(2441)) - Task attempt_20100126144930543_0001_r_000000_0
is done. [junit] 2010-01-26 14:49:58,231 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2442))
- reported output size for attempt_20100126144930543_0001_r_000000_0 was 0 [junit] 2010-01-26
14:49:58,232 INFO mapred.TaskTracker (TaskTracker.java:addFreeSlots(2000)) - addFreeSlot :
current free slots : 2 [junit] 2010-01-26 14:49:58,372 WARN util.ProcessTree (ProcessTree.java:sendSignal(130))
- Error executing shell command org.apache.hadoop.util.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:monitorAndPrintJob(1013)) - map 100% reduce 0% [junit]
2010-01-26 14:49:59,961 INFO mapred.JobInProgress (JobInProgress.java:completedTask(2563))
- Task 'attempt_20100126144930543_0001_r_000000_0' has completed task_20100126144930543_0001_r_000000
successfully. [junit] 2010-01-26 14:49:59,968 INFO mapred.JobTracker (JobTracker.java:createTaskEntry(1770))
- Adding task (JOB_CLEANUP) 'attempt_20100126144930543_0001_m_000001_0' to tip task_20100126144930543_0001_m_000001,
for tracker 'tracker_host0.foo.com:localhost/127.0.0.1:41432' [junit] 2010-01-26 14:49:59,970
INFO mapred.TaskTracker (TaskTracker.java:registerTask(2059)) - LaunchTaskAction (registerTask):
attempt_20100126144930543_0001_m_000001_0 task's state:UNASSIGNED [junit] 2010-01-26 14:49:59,971
INFO mapred.TaskTracker (TaskTracker.java:run(383)) - Received KillTaskAction for task: attempt_20100126144930543_0001_r_000000_0
[junit] 2010-01-26 14:49:59,972 INFO mapred.TaskTracker (TaskTracker.java:purgeTask(1794))
- About to purge task: attempt_20100126144930543_0001_r_000000_0 [junit] 2010-01-26 14:49:59,972
INFO mapred.TaskRunner (ReduceTaskRunner.java:close(48)) - attempt_20100126144930543_0001_r_000000_0
done; removing files. [junit] 2010-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 (TaskTracker.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:initializeUserDirs(197))
- User-directories for the user hudson are already initialized 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 Runner jvm_20100126144930543_0001_m_-1906794465
spawned. [junit] 2010-01-26 14:50:00,189 INFO mapred.JvmManager (JvmManager.java:runChild(457))
- JVM : jvm_20100126144930543_0001_m_331720839 exited with exit code 0. Number of tasks it
ran: 1 [junit] 2010-01-26 14:50:00,541 INFO mapreduce.Job (Job.java:printTaskEvents(1114))
- Task Id : attempt_20100126144930543_0001_r_000000_0, Status : SUCCEEDED [junit] attempt_20100126144930543_0001_r_000000_0:
2010-01-26 14:49:57,834 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM
Metrics with processName=SHUFFLE, sessionId= [junit] attempt_20100126144930543_0001_r_000000_0:
2010-01-26 14:49:57,865 INFO reduce.MergeManager (MergeManager.java:<init>(175)) - MergerManager:
memoryLimit=141387360, maxSingleShuffleLimit=35346840, mergeThreshold=93315664, ioSortFactor=10,
memToMemMergeOutputsThreshold=10 [junit] attempt_20100126144930543_0001_r_000000_0: 2010-01-26
14:49:57,868 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_20100126144930543_0001_r_000000_0
Thread started: EventFetcher for fetching Map Completion Events [junit] attempt_20100126144930543_0001_r_000000_0:
2010-01-26 14:49:57,878 INFO reduce.ShuffleScheduler (ShuffleScheduler.java:getHost(303))
- Assiging localhost:53541 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 [junit] attempt_20100126144930543_0001_r_000000_0:
2010-01-26 14:49:57,879 INFO reduce.EventFetcher (EventFetcher.java:run(69)) - attempt_20100126144930543_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=53541/mapOutput?job=job_20100126144930543_0001&reduce=0&map=attempt_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_000000_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:shuffleToMemory(488))
- Read 8 bytes from map-output for attempt_20100126144930543_0001_m_000000_0 [junit] attempt_20100126144930543_0001_r_000000_0:
2010-01-26 14:49:58,144 INFO reduce.MergeManager (MergeManager.java:closeInMemoryFile(274))
- closeInMemoryFile -> map-output of size: 8, inMemoryMapOutputs.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_20100126144930543_0001_r_000000_0: 2010-01-26 14:49:58,148 INFO reduce.MergeManager
(MergeManager.java:finalMerge(626)) - finalMerge called with 1 in-memory map-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 bytes [junit] attempt_20100126144930543_0001_r_000000_0:
2010-01-26 14:49:58,184 INFO reduce.MergeManager (MergeManager.java:finalMerge(698)) - Merged
1 segments, 8 bytes to disk to satisfy reduce memory limit [junit] attempt_20100126144930543_0001_r_000000_0:
2010-01-26 14:49:58,185 INFO reduce.MergeManager (MergeManager.java:finalMerge(724)) - Merging
1 files, 12 bytes from disk [junit] attempt_20100126144930543_0001_r_000000_0: 2010-01-26
14:49:58,186 INFO reduce.MergeManager (MergeManager.java:finalMerge(739)) - Merging 0 segments,
0 bytes from memory into reduce [junit] attempt_20100126144930543_0001_r_000000_0: 2010-01-26
14:49:58,186 INFO mapred.Merger (Merger.java:merge(543)) - Merging 1 sorted segments [junit]
attempt_20100126144930543_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 size: 2 bytes [junit] attempt_20100126144930543_0001_r_000000_0:
2010-01-26 14:49:58,194 WARN conf.Configuration (Configuration.java:set(601)) - mapred.skip.on
is deprecated. Instead, use mapreduce.job.skiprecords [junit] attempt_20100126144930543_0001_r_000000_0:
2010-01-26 14:49:58,222 INFO mapred.Task (Task.java:done(739)) - Task:attempt_20100126144930543_0001_r_000000_0
is done. And is in the process of commiting [junit] attempt_20100126144930543_0001_r_000000_0:
2010-01-26 14:49:58,232 INFO mapred.Task (Task.java:sendDone(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 'hudson': <hudson > [junit] 2010-01-26 14:50:00,634 INFO mapred.TaskTracker
(TaskTracker.java:getTask(2927)) - JVM with ID: jvm_20100126144930543_0001_m_-1906794465 given
task: attempt_20100126144930543_0001_m_000001_0 [junit] 2010-01-26 14:50:00,909 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(2360)) - attempt_20100126144930543_0001_m_000001_0 0.0% [junit]
2010-01-26 14:50:00,914 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(2360)) -
attempt_20100126144930543_0001_m_000001_0 0.0% cleanup > map [junit] 2010-01-26 14:50:00,917
INFO mapred.TaskTracker (TaskTracker.java:reportDone(2441)) - Task attempt_20100126144930543_0001_m_000001_0
is done. [junit] 2010-01-26 14:50:00,917 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2442))
- reported output size for attempt_20100126144930543_0001_m_000001_0 was 0 [junit] 2010-01-26
14:50:00,918 INFO mapred.TaskTracker (TaskTracker.java:addFreeSlots(2000)) - addFreeSlot :
current free slots : 2 [junit] 2010-01-26 14:50:01,067 WARN util.ProcessTree (ProcessTree.java:sendSignal(130))
- Error executing shell command org.apache.hadoop.util.Shell$ExitCodeException: 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-01-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.TaskTracker (TaskTracker.java:tryToGetOutputSize(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:50:02,975 INFO mapred.JobInProgress
(JobInProgress.java:completedTask(2563)) - Task 'attempt_20100126144930543_0001_m_000001_0'
has completed task_20100126144930543_0001_m_000001 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.JobInProgress$JobSummary
(JobInProgress.java:logJobSummary(3471)) - jobId=job_20100126144930543_0001,submitTime=1264517388178,launchTime=1264517388645,finishTime=1264517402977,numMaps=1,numSlotsPerMap=1,numReduces=1,numSlotsPerReduce=1,user=hudson,queue=default,status=SUCCEEDED,mapSlotSeconds=2,reduceSlotsSeconds=1,clusterMapCapacity=2,clusterReduceCapacity=2
[junit] 2010-01-26 14:50:02,989 INFO jobhistory.JobHistory (JobHistory.java:moveToDoneNow(315))
- Moving file:/grid/0/hudson/hudson-slave/workspace/Hadoop-Mapreduce-trunk/trunk/build/test/logs/history/job_20100126144930543_0001_hudson
to file:/grid/0/hudson/hudson-slave/workspace/Hadoop-Mapreduce-trunk/trunk/build/test/logs/history/done/job_20100126144930543_0001_hudson
[junit] 2010-01-26 14:50:02,990 INFO mapred.JobQueueTaskScheduler (TestTTResourceReporting.java:assignTasks(159))
- expected memory values : (totalVirtualMemoryOnTT, totalPhysicalMemoryOnTT, availableVirtualMemoryOnTT,
availablePhysicalMemoryOnTT, mapSlotMemSize, reduceSlotMemorySize, cumulativeCpuTime, cpuFrequency,
numProcessors) = (-1, -1,-1, -1,-1,-1,-1,-1,-1,-1.0) [junit] reported memory values : (totalVirtualMemoryOnTT,
totalPhysicalMemoryOnTT, availableVirtualMemoryOnTT, availablePhysicalMemoryOnTT, reportedMapSlotMemorySize,
reportedReduceSlotMemorySize, reportedCumulativeCpuTime, reportedCpuFrequency, reportedNumProcessors)
= (-1, -1,-1, -1,-1,-1,-1,-1,-1,-1.0) [junit] 2010-01-26 14:50:02,991 INFO mapred.JobTracker
(JobTracker.java:removeTaskEntry(1805)) - Removing task 'attempt_20100126144930543_0001_m_000000_0'
[junit] 2010-01-26 14:50:02,991 INFO mapred.JobTracker (JobTracker.java:removeTaskEntry(1805))
- Removing task 'attempt_20100126144930543_0001_m_000001_0' [junit] 2010-01-26 14:50:02,991
INFO mapred.JobTracker (JobTracker.java:removeTaskEntry(1805)) - Removing task 'attempt_20100126144930543_0001_m_000002_0'
[junit] 2010-01-26 14:50:02,991 INFO mapred.JobTracker (JobTracker.java:removeTaskEntry(1805))
- Removing task 'attempt_20100126144930543_0001_r_000000_0' [junit] 2010-01-26 14:50:02,992
INFO mapred.TaskTracker (TaskTracker.java:purgeJob(1738)) - Received 'KillJobAction' for job:
job_20100126144930543_0001 [junit] 2010-01-26 14:50:02,993 INFO mapred.TaskRunner (MapTaskRunner.java:close(44))
- attempt_20100126144930543_0001_m_000000_0 done; removing files. [junit] 2010-01-26 14:50:03,000
INFO mapred.TaskRunner (MapTaskRunner.java:close(44)) - attempt_20100126144930543_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_20100126144930543_0001_m_000001_0 not found in cache [junit] 2010-01-26 14:50:03,035
INFO jobhistory.JobHistory (JobHistory.java:moveToDoneNow(315)) - Moving file:/grid/0/hudson/hudson-slave/workspace/Hadoop-Mapreduce-trunk/trunk/build/test/logs/history/job_20100126144930543_0001_conf.xml
to file:/grid/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:cleanupLocalizedJobConf(3535))
- Deleting localized job conf at /grid/0/hudson/hudson-slave/workspace/Hadoop-Mapreduce-trunk/trunk/build/test/logs/job_20100126144930543_0001_conf.xml
[junit] 2010-01-26 14:50:03,390 INFO mapred.JvmManager (JvmManager.java:runChild(457)) - JVM
: jvm_20100126144930543_0001_r_35331837 exited with exit code 0. Number of tasks it ran: 1
[junit] 2010-01-26 14:50:03,556 INFO mapreduce.Job (Job.java:printTaskEvents(1114)) - Task
Id : attempt_20100126144930543_0001_m_000001_0, Status : SUCCEEDED [junit] attempt_20100126144930543_0001_m_000001_0:
2010-01-26 14:50:00,890 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM
Metrics with processName=MAP, sessionId= [junit] attempt_20100126144930543_0001_m_000001_0:
2010-01-26 14:50:00,910 INFO mapred.Task (Task.java:runJobCleanupTask(904)) - Cleaning up
job [junit] attempt_20100126144930543_0001_m_000001_0: 2010-01-26 14:50:00,910 INFO mapred.Task
(Task.java:runJobCleanupTask(916)) - Committing job [junit] attempt_20100126144930543_0001_m_000001_0:
2010-01-26 14:50:00,912 INFO mapred.Task (Task.java:done(739)) - Task:attempt_20100126144930543_0001_m_000001_0
is done. And is in the process of commiting [junit] attempt_20100126144930543_0001_m_000001_0:
2010-01-26 14:50:00,918 INFO mapred.Task (Task.java:sendDone(815)) - Task 'attempt_20100126144930543_0001_m_000001_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(1025)) - Counters: 28 

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


Mime
View raw message