hadoop-mapreduce-issues mailing list archives

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

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

Scott Chen commented on MAPREDUCE-1420:
---------------------------------------

It seems that the problem is the reported CPU frequency doesn't match the expected one.
This is because the CPU frequency in /proc/cpuinfo can actually change on some environment
See http://lwn.net/Articles/162548/
The test works on my dev box but not hudson this time.

The patch remove CPU frequency from the static value checking.
It will still be verified in the dynamic value checking.

> 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