07:09:01,610 INFO Test worker support.ClassPathXmlApplicationContext - Refreshing org.springframework.context.support.ClassPathXmlApplicationContext@34d0cdd0: startup date [Thu Sep 05 07:09:01 PDT 2013]; root of context hierarchy
07:09:01,611 INFO Test worker xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [org/springframework/data/hadoop/fs/HdfsItemWriterTest-context.xml]
07:09:01,653 INFO Test worker xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [org/springframework/data/hadoop/batch-common.xml]
07:09:01,670 INFO Test worker xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [org/springframework/data/hadoop/hadoop-ctx.xml]
07:09:01,732 INFO Test worker support.DefaultListableBeanFactory - Overriding bean definition for bean 'mainJob': replacing [Generic bean: class [org.springframework.batch.core.configuration.xml.SimpleFlowFactoryBean]; scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null] with [Generic bean: class [org.springframework.batch.core.configuration.xml.JobParserJobFactoryBean]; scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
07:09:01,746 INFO Test worker config.PropertyPlaceholderConfigurer - Loading properties file from class path resource [test.properties]
07:09:01,762 INFO Test worker support.DefaultListableBeanFactory - Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@5b83d60d: defining beans [jobRepository,transactionManager,jobLauncher,taskExecutor,ppc,hadoopFs,hadoopResourceLoader,hadoopConfiguration,cfg-init,fs-init,rl-init,org.springframework.data.hadoop.scripting.HdfsScriptRunner#0,org.springframework.batch.core.scope.internalStepScope,org.springframework.beans.factory.config.CustomEditorConfigurer,org.springframework.batch.core.configuration.xml.CoreNamespacePostProcessor,import,do,org.springframework.data.hadoop.scripting.HdfsScriptRunner#1,script-tasklet,clean,mainJob,itemReader,hdfsItemWriter,hadoop-tasklet,mr-job]; root of factory hierarchy
07:09:02,029 INFO Test worker support.SimpleJobLauncher - Job: [FlowJob: [name=mainJob]] launched with the following parameters: [{}]
07:09:02,046 INFO Test worker job.SimpleStepHandler - Executing step: [import]
07:09:02,105 INFO Test worker job.SimpleStepHandler - Executing step: [do]
07:09:02,112 INFO Test worker mapreduce.JobTasklet - Starting job [mr-job]
07:09:02,130 INFO Test worker input.FileInputFormat - Total input paths to process : 1
07:09:02,188 INFO Test worker mapred.JobClient - Running job: job_201308191125_0562
07:09:03,189 INFO Test worker mapred.JobClient - map 0% reduce 0%
07:09:07,196 INFO Test worker mapred.JobClient - map 100% reduce 0%
07:09:14,214 INFO Test worker mapred.JobClient - map 100% reduce 33%
07:09:15,217 INFO Test worker mapred.JobClient - map 100% reduce 100%
07:09:16,220 INFO Test worker mapred.JobClient - Job complete: job_201308191125_0562
07:09:16,231 INFO Test worker mapred.JobClient - Counters: 29
07:09:16,231 INFO Test worker mapred.JobClient - Job Counters
07:09:16,231 INFO Test worker mapred.JobClient - Launched reduce tasks=1
07:09:16,232 INFO Test worker mapred.JobClient - SLOTS_MILLIS_MAPS=4184
07:09:16,232 INFO Test worker mapred.JobClient - Total time spent by all reduces waiting after reserving slots (ms)=0
07:09:16,232 INFO Test worker mapred.JobClient - Total time spent by all maps waiting after reserving slots (ms)=0
07:09:16,232 INFO Test worker mapred.JobClient - Launched map tasks=1
07:09:16,232 INFO Test worker mapred.JobClient - Data-local map tasks=1
07:09:16,232 INFO Test worker mapred.JobClient - SLOTS_MILLIS_REDUCES=8602
07:09:16,232 INFO Test worker mapred.JobClient - File Output Format Counters
07:09:16,232 INFO Test worker mapred.JobClient - Bytes Written=345
07:09:16,233 INFO Test worker mapred.JobClient - FileSystemCounters
07:09:16,233 INFO Test worker mapred.JobClient - FILE_BYTES_READ=477
07:09:16,233 INFO Test worker mapred.JobClient - HDFS_BYTES_READ=396
07:09:16,233 INFO Test worker mapred.JobClient - FILE_BYTES_WRITTEN=106369
07:09:16,233 INFO Test worker mapred.JobClient - HDFS_BYTES_WRITTEN=345
07:09:16,233 INFO Test worker mapred.JobClient - File Input Format Counters
07:09:16,233 INFO Test worker mapred.JobClient - Bytes Read=280
07:09:16,233 INFO Test worker mapred.JobClient - Map-Reduce Framework
07:09:16,234 INFO Test worker mapred.JobClient - Map output materialized bytes=477
07:09:16,234 INFO Test worker mapred.JobClient - Map input records=6
07:09:16,234 INFO Test worker mapred.JobClient - Reduce shuffle bytes=477
07:09:16,234 INFO Test worker mapred.JobClient - Spilled Records=50
07:09:16,234 INFO Test worker mapred.JobClient - Map output bytes=421
07:09:16,234 INFO Test worker mapred.JobClient - CPU time spent (ms)=1580
07:09:16,234 INFO Test worker mapred.JobClient - Total committed heap usage (bytes)=239075328
07:09:16,234 INFO Test worker mapred.JobClient - Combine input records=0
07:09:16,235 INFO Test worker mapred.JobClient - SPLIT_RAW_BYTES=116
07:09:16,235 INFO Test worker mapred.JobClient - Reduce input records=25
07:09:16,235 INFO Test worker mapred.JobClient - Reduce input groups=21
07:09:16,235 INFO Test worker mapred.JobClient - Combine output records=0
07:09:16,235 INFO Test worker mapred.JobClient - Physical memory (bytes) snapshot=330432512
07:09:16,235 INFO Test worker mapred.JobClient - Reduce output records=21
07:09:16,235 INFO Test worker mapred.JobClient - Virtual memory (bytes) snapshot=1705381888
07:09:16,235 INFO Test worker mapred.JobClient - Map output records=25
07:09:16,237 INFO Test worker mapreduce.JobTasklet - Completed job [mr-job]
07:09:16,361 INFO Test worker job.SimpleStepHandler - Executing step: [clean]
07:09:16,424 INFO Test worker support.SimpleJobLauncher - Job: [FlowJob: [name=mainJob]] completed with the following parameters: [{}] and the following status: [COMPLETED]