[
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.
