07:09:19,304 INFO Test worker context.TestContextManager - @TestExecutionListeners is not present for class [class org.springframework.data.hadoop.mapreduce.StreamingTest]: using defaults.
07:09:19,306 INFO Test worker xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [org/springframework/data/hadoop/streaming/basic.xml]
07:09:19,338 INFO Test worker xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [org/springframework/data/hadoop/hadoop-ctx.xml]
07:09:19,378 INFO Test worker support.GenericApplicationContext - Refreshing org.springframework.context.support.GenericApplicationContext@1da13fb3: startup date [Thu Sep 05 07:09:19 PDT 2013]; root of context hierarchy
07:09:19,386 INFO Test worker config.PropertyPlaceholderConfigurer - Loading properties file from class path resource [test.properties]
07:09:19,391 INFO Test worker support.DefaultListableBeanFactory - Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@7be2c00f: defining beans [ppc,hadoopFs,hadoopResourceLoader,hadoopConfiguration,cfg-init,fs-init,rl-init,org.springframework.data.hadoop.scripting.HdfsScriptRunner#0,vanilla-stream-job,ns-stream-job,props,org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor]; root of factory hierarchy
07:09:19,454 INFO Test worker config.PropertiesFactoryBean - Loading properties file from class path resource [props.properties]
07:09:19,455 INFO Test worker config.PropertiesFactoryBean - Loading properties file from class path resource [cfg-1.properties]
07:09:19,455 INFO Test worker config.PropertiesFactoryBean - Loading properties file from class path resource [cfg-2.properties]
packageJobJar: [] [/home/bamboo/.gradle/caches/artifacts-15/filestore/org.apache.hadoop/hadoop-streaming/1.2.0/jar/37d96e82162684e35f9c7ead641cc8226bab121c/hadoop-streaming-1.2.0.jar] /tmp/streamjob4264085025997605219.jar tmpDir=null
packageJobJar: [] [/home/bamboo/.gradle/caches/artifacts-15/filestore/org.apache.hadoop/hadoop-streaming/1.2.0/jar/37d96e82162684e35f9c7ead641cc8226bab121c/hadoop-streaming-1.2.0.jar] /tmp/streamjob1349481066168259031.jar tmpDir=null
07:09:19,714 INFO Test worker mapred.FileInputFormat - Total input paths to process : 1
07:09:19,822 INFO Test worker mapred.JobClient - Running job: job_201308191125_0563
07:09:20,823 INFO Test worker mapred.JobClient - map 0% reduce 0%
07:09:24,830 INFO Test worker mapred.JobClient - map 100% reduce 0%
07:09:31,843 INFO Test worker mapred.JobClient - map 100% reduce 33%
07:09:33,847 INFO Test worker mapred.JobClient - map 100% reduce 100%
07:09:34,851 INFO Test worker mapred.JobClient - Job complete: job_201308191125_0563
07:09:34,854 INFO Test worker mapred.JobClient - Counters: 30
07:09:34,854 INFO Test worker mapred.JobClient - Job Counters
07:09:34,855 INFO Test worker mapred.JobClient - Launched reduce tasks=1
07:09:34,855 INFO Test worker mapred.JobClient - SLOTS_MILLIS_MAPS=6157
07:09:34,855 INFO Test worker mapred.JobClient - Total time spent by all reduces waiting after reserving slots (ms)=0
07:09:34,855 INFO Test worker mapred.JobClient - Total time spent by all maps waiting after reserving slots (ms)=0
07:09:34,855 INFO Test worker mapred.JobClient - Launched map tasks=2
07:09:34,855 INFO Test worker mapred.JobClient - Data-local map tasks=2
07:09:34,855 INFO Test worker mapred.JobClient - SLOTS_MILLIS_REDUCES=8619
07:09:34,855 INFO Test worker mapred.JobClient - File Input Format Counters
07:09:34,855 INFO Test worker mapred.JobClient - Bytes Read=22364
07:09:34,855 INFO Test worker mapred.JobClient - File Output Format Counters
07:09:34,856 INFO Test worker mapred.JobClient - Bytes Written=25
07:09:34,856 INFO Test worker mapred.JobClient - FileSystemCounters
07:09:34,856 INFO Test worker mapred.JobClient - FILE_BYTES_READ=22117
07:09:34,856 INFO Test worker mapred.JobClient - HDFS_BYTES_READ=22558
07:09:34,856 INFO Test worker mapred.JobClient - FILE_BYTES_WRITTEN=210324
07:09:34,856 INFO Test worker mapred.JobClient - HDFS_BYTES_WRITTEN=25
07:09:34,856 INFO Test worker mapred.JobClient - Map-Reduce Framework
07:09:34,856 INFO Test worker mapred.JobClient - Map output materialized bytes=22123
07:09:34,856 INFO Test worker mapred.JobClient - Map input records=653
07:09:34,856 INFO Test worker mapred.JobClient - Reduce shuffle bytes=22123
07:09:34,856 INFO Test worker mapred.JobClient - Spilled Records=1306
07:09:34,857 INFO Test worker mapred.JobClient - Map output bytes=20804
07:09:34,857 INFO Test worker mapred.JobClient - Total committed heap usage (bytes)=402063360
07:09:34,857 INFO Test worker mapred.JobClient - CPU time spent (ms)=2610
07:09:34,857 INFO Test worker mapred.JobClient - Map input bytes=20151
07:09:34,857 INFO Test worker mapred.JobClient - SPLIT_RAW_BYTES=194
07:09:34,857 INFO Test worker mapred.JobClient - Combine input records=0
07:09:34,857 INFO Test worker mapred.JobClient - Reduce input records=653
07:09:34,857 INFO Test worker mapred.JobClient - Reduce input groups=409
07:09:34,858 INFO Test worker mapred.JobClient - Combine output records=0
07:09:34,859 INFO Test worker mapred.JobClient - Physical memory (bytes) snapshot=543047680
07:09:34,859 INFO Test worker mapred.JobClient - Reduce output records=1
07:09:34,859 INFO Test worker mapred.JobClient - Virtual memory (bytes) snapshot=2559578112
07:09:34,859 INFO Test worker mapred.JobClient - Map output records=653
07:09:34,945 INFO Test worker mapred.FileInputFormat - Total input paths to process : 1
07:09:35,048 INFO Test worker mapred.JobClient - Running job: job_201308191125_0564
07:09:36,050 INFO Test worker mapred.JobClient - map 0% reduce 0%
07:09:41,067 INFO Test worker mapred.JobClient - map 100% reduce 0%
07:09:48,081 INFO Test worker mapred.JobClient - map 100% reduce 33%
07:09:49,083 INFO Test worker mapred.JobClient - map 100% reduce 100%
07:09:50,087 INFO Test worker mapred.JobClient - Job complete: job_201308191125_0564
07:09:50,090 INFO Test worker mapred.JobClient - Counters: 30
07:09:50,090 INFO Test worker mapred.JobClient - Job Counters
07:09:50,090 INFO Test worker mapred.JobClient - Launched reduce tasks=1
07:09:50,090 INFO Test worker mapred.JobClient - SLOTS_MILLIS_MAPS=6811
07:09:50,090 INFO Test worker mapred.JobClient - Total time spent by all reduces waiting after reserving slots (ms)=0
07:09:50,090 INFO Test worker mapred.JobClient - Total time spent by all maps waiting after reserving slots (ms)=0
07:09:50,090 INFO Test worker mapred.JobClient - Launched map tasks=2
07:09:50,090 INFO Test worker mapred.JobClient - Data-local map tasks=2
07:09:50,091 INFO Test worker mapred.JobClient - SLOTS_MILLIS_REDUCES=8482
07:09:50,091 INFO Test worker mapred.JobClient - File Input Format Counters
07:09:50,091 INFO Test worker mapred.JobClient - Bytes Read=22364
07:09:50,091 INFO Test worker mapred.JobClient - File Output Format Counters
07:09:50,091 INFO Test worker mapred.JobClient - Bytes Written=25
07:09:50,091 INFO Test worker mapred.JobClient - FileSystemCounters
07:09:50,091 INFO Test worker mapred.JobClient - FILE_BYTES_READ=22117
07:09:50,091 INFO Test worker mapred.JobClient - HDFS_BYTES_READ=22558
07:09:50,091 INFO Test worker mapred.JobClient - FILE_BYTES_WRITTEN=223874
07:09:50,091 INFO Test worker mapred.JobClient - HDFS_BYTES_WRITTEN=25
07:09:50,092 INFO Test worker mapred.JobClient - Map-Reduce Framework
07:09:50,092 INFO Test worker mapred.JobClient - Map output materialized bytes=22123
07:09:50,092 INFO Test worker mapred.JobClient - Map input records=653
07:09:50,092 INFO Test worker mapred.JobClient - Reduce shuffle bytes=22123
07:09:50,092 INFO Test worker mapred.JobClient - Spilled Records=1306
07:09:50,092 INFO Test worker mapred.JobClient - Map output bytes=20804
07:09:50,092 INFO Test worker mapred.JobClient - Total committed heap usage (bytes)=402063360
07:09:50,092 INFO Test worker mapred.JobClient - CPU time spent (ms)=2450
07:09:50,092 INFO Test worker mapred.JobClient - Map input bytes=20151
07:09:50,092 INFO Test worker mapred.JobClient - SPLIT_RAW_BYTES=194
07:09:50,093 INFO Test worker mapred.JobClient - Combine input records=0
07:09:50,093 INFO Test worker mapred.JobClient - Reduce input records=653
07:09:50,093 INFO Test worker mapred.JobClient - Reduce input groups=409
07:09:50,093 INFO Test worker mapred.JobClient - Combine output records=0
07:09:50,093 INFO Test worker mapred.JobClient - Physical memory (bytes) snapshot=545431552
07:09:50,093 INFO Test worker mapred.JobClient - Reduce output records=1
07:09:50,093 INFO Test worker mapred.JobClient - Virtual memory (bytes) snapshot=2509049856
07:09:50,093 INFO Test worker mapred.JobClient - Map output records=653