[
https://issues.apache.org/jira/browse/MAPREDUCE-1420?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Iyappan Srinivasan updated MAPREDUCE-1420:
------------------------------------------
Attachment: output.rtf
The output in a readable format
> 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, output.rtf
>
>
> 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.
