07:09:50,105 INFO Test worker context.TestContextManager - @TestExecutionListeners is not present for class [class org.springframework.data.hadoop.mapreduce.JobTests]: using defaults.
07:09:50,109 INFO Test worker xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [org/springframework/data/hadoop/mapreduce/JobTests-context.xml]
07:09:50,155 INFO Test worker xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [org/springframework/data/hadoop/hadoop-ctx.xml]
07:09:50,220 INFO Test worker support.GenericApplicationContext - Refreshing org.springframework.context.support.GenericApplicationContext@24c535d: startup date [Thu Sep 05 07:09:50 PDT 2013]; root of context hierarchy
07:09:50,245 INFO Test worker config.PropertyPlaceholderConfigurer - Loading properties file from class path resource [test.properties]
07:09:50,255 INFO Test worker support.DefaultListableBeanFactory - Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@3c63dc28: defining beans [ppc,hadoopFs,hadoopResourceLoader,hadoopConfiguration,cfg-init,fs-init,rl-init,org.springframework.data.hadoop.scripting.HdfsScriptRunner#0,script,nop-script,jar-job-runner,another-runner,ns-runner,no-wait,jar-job,custom-jar-job,ns-job,executor,props,myScheduler,org.springframework.scheduling.support.MethodInvokingRunnable#0,org.springframework.scheduling.config.ScheduledTaskRegistrar#0,killer-runner,victim-job,async,org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor]; root of factory hierarchy
Called script
07:09:50,424 INFO Test worker mapreduce.JobRunner - Starting job [custom-jar-job]
07:09:50,470 INFO Test worker input.FileInputFormat - Total input paths to process : 1
07:09:50,569 INFO Test worker mapred.JobClient - Running job: job_201308191125_0565
07:09:51,571 INFO Test worker mapred.JobClient - map 0% reduce 0%
07:09:56,579 INFO Test worker mapred.JobClient - map 100% reduce 0%
07:10:03,592 INFO Test worker mapred.JobClient - map 100% reduce 33%
07:10:05,596 INFO Test worker mapred.JobClient - map 100% reduce 100%
07:10:05,598 INFO Test worker mapred.JobClient - Job complete: job_201308191125_0565
07:10:05,601 INFO Test worker mapred.JobClient - Counters: 29
07:10:05,601 INFO Test worker mapred.JobClient - Job Counters
07:10:05,601 INFO Test worker mapred.JobClient - Launched reduce tasks=1
07:10:05,601 INFO Test worker mapred.JobClient - SLOTS_MILLIS_MAPS=4717
07:10:05,601 INFO Test worker mapred.JobClient - Total time spent by all reduces waiting after reserving slots (ms)=0
07:10:05,601 INFO Test worker mapred.JobClient - Total time spent by all maps waiting after reserving slots (ms)=0
07:10:05,601 INFO Test worker mapred.JobClient - Launched map tasks=1
07:10:05,601 INFO Test worker mapred.JobClient - Data-local map tasks=1
07:10:05,602 INFO Test worker mapred.JobClient - SLOTS_MILLIS_REDUCES=9238
07:10:05,602 INFO Test worker mapred.JobClient - File Output Format Counters
07:10:05,602 INFO Test worker mapred.JobClient - Bytes Written=38
07:10:05,602 INFO Test worker mapred.JobClient - FileSystemCounters
07:10:05,602 INFO Test worker mapred.JobClient - FILE_BYTES_READ=64
07:10:05,602 INFO Test worker mapred.JobClient - HDFS_BYTES_READ=150
07:10:05,602 INFO Test worker mapred.JobClient - FILE_BYTES_WRITTEN=109013
07:10:05,602 INFO Test worker mapred.JobClient - HDFS_BYTES_WRITTEN=38
07:10:05,602 INFO Test worker mapred.JobClient - File Input Format Counters
07:10:05,603 INFO Test worker mapred.JobClient - Bytes Read=28
07:10:05,603 INFO Test worker mapred.JobClient - Map-Reduce Framework
07:10:05,603 INFO Test worker mapred.JobClient - Map output materialized bytes=64
07:10:05,603 INFO Test worker mapred.JobClient - Map input records=3
07:10:05,603 INFO Test worker mapred.JobClient - Reduce shuffle bytes=64
07:10:05,603 INFO Test worker mapred.JobClient - Spilled Records=10
07:10:05,603 INFO Test worker mapred.JobClient - Map output bytes=48
07:10:05,603 INFO Test worker mapred.JobClient - CPU time spent (ms)=1680
07:10:05,603 INFO Test worker mapred.JobClient - Total committed heap usage (bytes)=239075328
07:10:05,604 INFO Test worker mapred.JobClient - Combine input records=0
07:10:05,604 INFO Test worker mapred.JobClient - SPLIT_RAW_BYTES=122
07:10:05,604 INFO Test worker mapred.JobClient - Reduce input records=5
07:10:05,604 INFO Test worker mapred.JobClient - Reduce input groups=5
07:10:05,604 INFO Test worker mapred.JobClient - Combine output records=0
07:10:05,604 INFO Test worker mapred.JobClient - Physical memory (bytes) snapshot=332107776
07:10:05,604 INFO Test worker mapred.JobClient - Reduce output records=5
07:10:05,604 INFO Test worker mapred.JobClient - Virtual memory (bytes) snapshot=1731809280
07:10:05,604 INFO Test worker mapred.JobClient - Map output records=5
07:10:05,607 INFO Test worker mapreduce.JobRunner - Completed job [custom-jar-job]
07:10:05,611 INFO Test worker config.PropertiesFactoryBean - Loading properties file from class path resource [props.properties]
07:10:05,613 INFO Test worker config.PropertiesFactoryBean - Loading properties file from class path resource [cfg-1.properties]
07:10:05,613 INFO Test worker config.PropertiesFactoryBean - Loading properties file from class path resource [cfg-2.properties]
07:10:05,643 INFO Test worker concurrent.ThreadPoolTaskScheduler - Initializing ExecutorService 'myScheduler'
4
Called script
07:10:05,711 INFO myScheduler-1 mapreduce.JobRunner - Starting job [custom-jar-job]