2014-08-22 21:58:01,078 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(187)) - found 1 test platforms from classpath
2014-08-22 21:58:01,143 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(237)) - installing platform: hadoop2-mr1
2014-08-22 21:58:01,143 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(238)) - running test: cascading.DistanceUseCasePlatformTest
2014-08-22 21:58:01,173 INFO hadoop2.Hadoop2MR1Platform (Hadoop2MR1Platform.java:setUp(106)) - not using cluster
2014-08-22 21:58:01,815 WARN util.NativeCodeLoader (NativeCodeLoader.java:<clinit>(62)) - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
2014-08-22 21:58:02,125 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 21:58:02,127 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 21:58:02,140 INFO property.AppProps (AppProps.java:getAppID(162)) - using app.id: FAA9238E2AF94D7CAEAABDDC2AFC2885
2014-08-22 21:58:02,245 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:58:02,289 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:58:02,417 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 21:58:02,489 INFO util.Version (Version.java:printBanner(78)) - Concurrent, Inc - Cascading 2.5.6
2014-08-22 21:58:02,492 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] starting
2014-08-22 21:58:02,493 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/critics.txt"]
2014-08-22 21:58:02,493 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/composite"]
2014-08-22 21:58:02,494 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] parallel execution is enabled: false
2014-08-22 21:58:02,495 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] starting jobs: 3
2014-08-22 21:58:02,495 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] allocating threads: 1
2014-08-22 21:58:02,497 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] starting step: (1/3)
2014-08-22 21:58:02,523 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - session.id is deprecated. Instead, use dfs.metrics.session-id
2014-08-22 21:58:02,525 INFO jvm.JvmMetrics (JvmMetrics.java:init(76)) - Initializing JVM Metrics with processName=JobTracker, sessionId=
2014-08-22 21:58:02,549 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:02,955 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:58:02,998 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:58:03,169 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local803872535_0001
2014-08-22 21:58:03,210 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity803872535/.staging/job_local803872535_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:03,221 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity803872535/.staging/job_local803872535_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:03,405 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local803872535_0001/job_local803872535_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:03,413 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local803872535_0001/job_local803872535_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:03,420 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:58:03,421 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:58:03,424 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] submitted hadoop job: job_local803872535_0001
2014-08-22 21:58:03,424 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] tracking url: http://localhost:8080/
2014-08-22 21:58:03,424 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:58:03,484 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:58:03,489 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local803872535_0001_m_000000_0
2014-08-22 21:58:03,533 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:03,544 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/critics.txt
2014-08-22 21:58:03,545 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@52fc9d2b
2014-08-22 21:58:03,555 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:58:03,563 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:58:03,711 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:58:03,711 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:58:03,712 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:58:03,713 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:58:03,713 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:58:03,741 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:58:03,742 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:58:03,801 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.task.partition is deprecated. Instead, use mapreduce.task.partition
2014-08-22 21:58:03,821 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/critics.txt"]
2014-08-22 21:58:03,821 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(euclidean)[by:[{1}:'l'][numSelfJoins:1]]
2014-08-22 21:58:03,842 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:58:03,843 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:58:03,843 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:58:03,844 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 1746; bufvoid = 104857600
2014-08-22 21:58:03,845 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214260(104857040); length = 137/6553600
2014-08-22 21:58:03,862 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:58:03,867 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local803872535_0001_m_000000_0 is done. And is in the process of committing
2014-08-22 21:58:03,886 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/critics.txt:0+828
2014-08-22 21:58:03,887 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local803872535_0001_m_000000_0' done.
2014-08-22 21:58:03,888 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local803872535_0001_m_000000_0
2014-08-22 21:58:03,888 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:58:03,891 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:58:03,892 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local803872535_0001_r_000000_0
2014-08-22 21:58:03,900 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:03,904 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@2f6a23cf
2014-08-22 21:58:03,919 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:58:03,923 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local803872535_0001_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:58:03,957 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#1 about to shuffle output of map attempt_local803872535_0001_m_000000_0 decomp: 1818 len: 1822 to MEMORY
2014-08-22 21:58:03,963 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 1818 bytes from map-output for attempt_local803872535_0001_m_000000_0
2014-08-22 21:58:04,006 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 1818, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->1818
2014-08-22 21:58:04,007 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:58:04,009 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:04,010 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:58:04,020 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:04,020 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 1797 bytes
2014-08-22 21:58:04,024 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 1818 bytes to disk to satisfy reduce memory limit
2014-08-22 21:58:04,025 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 1822 bytes from disk
2014-08-22 21:58:04,026 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:58:04,027 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:04,028 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 1797 bytes
2014-08-22 21:58:04,029 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:04,031 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:58:04,032 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:58:04,054 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: CoGroup(euclidean)[by:[{1}:'l'][numSelfJoins:1]]
2014-08-22 21:58:04,055 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[['l', 'n1', 'v1', 'n2', 'v2']]"][3135040711/euclidean/]
2014-08-22 21:58:04,091 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(105)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 21:58:04,092 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(110)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 21:58:04,158 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local803872535_0001_r_000000_0 is done. And is in the process of committing
2014-08-22 21:58:04,160 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:04,160 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local803872535_0001_r_000000_0 is allowed to commit now
2014-08-22 21:58:04,162 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local803872535_0001_r_000000_0' to file:/tmp/hadoop-teamcity/3135040711_euclidean_B2965E9558E145EDA5881BCAC1F17F94/_temporary/0/task_local803872535_0001_r_000000
2014-08-22 21:58:04,163 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:58:04,164 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local803872535_0001_r_000000_0' done.
2014-08-22 21:58:04,164 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local803872535_0001_r_000000_0
2014-08-22 21:58:04,164 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:58:04,206 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] starting step: (2/3)
2014-08-22 21:58:04,207 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:04,209 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:04,257 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:58:04,283 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:58:04,298 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:58:04,299 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:58:04,350 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local516562399_0002
2014-08-22 21:58:04,372 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity516562399/.staging/job_local516562399_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:04,374 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity516562399/.staging/job_local516562399_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:04,506 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local516562399_0002/job_local516562399_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:04,509 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local516562399_0002/job_local516562399_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:04,510 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:58:04,510 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] submitted hadoop job: job_local516562399_0002
2014-08-22 21:58:04,510 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] tracking url: http://localhost:8080/
2014-08-22 21:58:04,511 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:58:04,511 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:58:04,515 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:58:04,515 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local516562399_0002_m_000000_0
2014-08-22 21:58:04,518 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:04,520 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/3135040711_euclidean_B2965E9558E145EDA5881BCAC1F17F94/part-00000
2014-08-22 21:58:04,520 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@76c7cadf
2014-08-22 21:58:04,534 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:58:04,534 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:58:04,684 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:58:04,685 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:58:04,685 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:58:04,685 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:58:04,685 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:58:04,687 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:58:04,687 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:58:04,703 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[['l', 'n1', 'v1', 'n2', 'v2']]"][3135040711/euclidean/]
2014-08-22 21:58:04,703 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(euclidean)[by:[{?}:ALL]]
2014-08-22 21:58:04,743 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:58:04,744 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:58:04,744 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:58:04,744 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 13104; bufvoid = 104857600
2014-08-22 21:58:04,744 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26213704(104854816); length = 693/6553600
2014-08-22 21:58:04,821 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:58:04,825 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local516562399_0002_m_000000_0 is done. And is in the process of committing
2014-08-22 21:58:04,828 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/3135040711_euclidean_B2965E9558E145EDA5881BCAC1F17F94/part-00000:0+13816
2014-08-22 21:58:04,828 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local516562399_0002_m_000000_0' done.
2014-08-22 21:58:04,828 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local516562399_0002_m_000000_0
2014-08-22 21:58:04,828 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:58:04,829 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:58:04,829 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local516562399_0002_r_000000_0
2014-08-22 21:58:04,832 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:04,833 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@5ad3c69c
2014-08-22 21:58:04,834 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:58:04,835 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local516562399_0002_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:58:04,837 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#2 about to shuffle output of map attempt_local516562399_0002_m_000000_0 decomp: 13454 len: 13458 to MEMORY
2014-08-22 21:58:04,838 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 13454 bytes from map-output for attempt_local516562399_0002_m_000000_0
2014-08-22 21:58:04,838 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 13454, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->13454
2014-08-22 21:58:04,839 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:58:04,840 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:04,841 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:58:04,844 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:04,845 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 13386 bytes
2014-08-22 21:58:04,851 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 13454 bytes to disk to satisfy reduce memory limit
2014-08-22 21:58:04,851 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 13458 bytes from disk
2014-08-22 21:58:04,852 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:58:04,852 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:04,852 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 13386 bytes
2014-08-22 21:58:04,853 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:04,854 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:58:04,854 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:58:04,873 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(euclidean)[by:[{?}:ALL]]
2014-08-22 21:58:04,874 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[['l', 'n1', 'v1', 'n2', 'v2']]"][2070903248/euclidean/]
2014-08-22 21:58:04,920 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local516562399_0002_r_000000_0 is done. And is in the process of committing
2014-08-22 21:58:04,922 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:04,922 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local516562399_0002_r_000000_0 is allowed to commit now
2014-08-22 21:58:04,923 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local516562399_0002_r_000000_0' to file:/tmp/hadoop-teamcity/2070903248_euclidean_0B9D43969EFE418EA52E658E8E5C70C2/_temporary/0/task_local516562399_0002_r_000000
2014-08-22 21:58:04,925 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:58:04,925 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local516562399_0002_r_000000_0' done.
2014-08-22 21:58:04,925 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local516562399_0002_r_000000_0
2014-08-22 21:58:04,926 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:58:04,948 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] starting step: (3/3) ...tform/euclidean/composite
2014-08-22 21:58:04,948 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:04,950 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:04,998 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:58:05,021 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:58:05,035 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:58:05,036 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:58:05,073 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1426203716_0003
2014-08-22 21:58:05,102 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1426203716/.staging/job_local1426203716_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:05,105 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1426203716/.staging/job_local1426203716_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:05,176 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1426203716_0003/job_local1426203716_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:05,179 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1426203716_0003/job_local1426203716_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:05,180 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:58:05,180 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] submitted hadoop job: job_local1426203716_0003
2014-08-22 21:58:05,180 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] tracking url: http://localhost:8080/
2014-08-22 21:58:05,181 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:58:05,182 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:58:05,186 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:58:05,186 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1426203716_0003_m_000000_0
2014-08-22 21:58:05,190 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:05,193 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/2070903248_euclidean_0B9D43969EFE418EA52E658E8E5C70C2/part-00000
2014-08-22 21:58:05,194 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@1e35ecd
2014-08-22 21:58:05,197 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:58:05,197 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:58:05,346 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:58:05,346 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:58:05,346 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:58:05,346 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:58:05,346 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:58:05,349 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:58:05,349 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:58:05,364 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[['l', 'n1', 'v1', 'n2', 'v2']]"][2070903248/euclidean/]
2014-08-22 21:58:05,364 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(euclidean)[by:[{2}:'n1', 'n2']]
2014-08-22 21:58:05,377 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:58:05,377 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:58:05,377 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:58:05,378 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 6291; bufvoid = 104857600
2014-08-22 21:58:05,378 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214052(104856208); length = 345/6553600
2014-08-22 21:58:05,387 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:58:05,390 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1426203716_0003_m_000000_0 is done. And is in the process of committing
2014-08-22 21:58:05,393 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/2070903248_euclidean_0B9D43969EFE418EA52E658E8E5C70C2/part-00000:0+6943
2014-08-22 21:58:05,393 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1426203716_0003_m_000000_0' done.
2014-08-22 21:58:05,393 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1426203716_0003_m_000000_0
2014-08-22 21:58:05,394 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:58:05,394 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:58:05,395 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1426203716_0003_r_000000_0
2014-08-22 21:58:05,397 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:05,397 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@58edf4c8
2014-08-22 21:58:05,398 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:58:05,399 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1426203716_0003_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:58:05,401 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#3 about to shuffle output of map attempt_local1426203716_0003_m_000000_0 decomp: 6467 len: 6471 to MEMORY
2014-08-22 21:58:05,402 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 6467 bytes from map-output for attempt_local1426203716_0003_m_000000_0
2014-08-22 21:58:05,402 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 6467, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->6467
2014-08-22 21:58:05,403 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:58:05,404 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:05,404 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:58:05,407 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:05,407 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 6432 bytes
2014-08-22 21:58:05,411 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 6467 bytes to disk to satisfy reduce memory limit
2014-08-22 21:58:05,411 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 6471 bytes from disk
2014-08-22 21:58:05,412 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:58:05,412 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:05,412 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 6432 bytes
2014-08-22 21:58:05,413 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:05,413 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:58:05,413 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:58:05,427 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(euclidean)[by:[{2}:'n1', 'n2']]
2014-08-22 21:58:05,427 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/composite"]
2014-08-22 21:58:05,455 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1426203716_0003_r_000000_0 is done. And is in the process of committing
2014-08-22 21:58:05,457 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:05,457 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1426203716_0003_r_000000_0 is allowed to commit now
2014-08-22 21:58:05,458 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1426203716_0003_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/composite/_temporary/0/task_local1426203716_0003_r_000000
2014-08-22 21:58:05,460 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:58:05,460 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1426203716_0003_r_000000_0' done.
2014-08-22 21:58:05,460 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1426203716_0003_r_000000_0
2014-08-22 21:58:05,460 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:58:05,493 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/composite/_temporary
2014-08-22 21:58:05,537 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:58:05,592 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:58:05,596 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/distanceusecaseplatform/euclidean/composite
2014-08-22 21:58:05,631 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 21:58:05,631 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 21:58:05,665 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:58:05,670 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:58:05,702 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 21:58:05,714 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [pearson] starting
2014-08-22 21:58:05,715 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [pearson] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/critics.txt"]
2014-08-22 21:58:05,715 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [pearson] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/pearson/composite"]
2014-08-22 21:58:05,716 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [pearson] parallel execution is enabled: false
2014-08-22 21:58:05,716 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [pearson] starting jobs: 3
2014-08-22 21:58:05,716 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [pearson] allocating threads: 1
2014-08-22 21:58:05,718 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pearson] starting step: (1/3)
2014-08-22 21:58:05,719 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:05,722 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:05,752 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:58:05,773 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:58:05,792 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local2141916785_0004
2014-08-22 21:58:05,813 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity2141916785/.staging/job_local2141916785_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:05,814 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity2141916785/.staging/job_local2141916785_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:05,882 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local2141916785_0004/job_local2141916785_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:05,884 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local2141916785_0004/job_local2141916785_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:05,884 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:58:05,885 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pearson] submitted hadoop job: job_local2141916785_0004
2014-08-22 21:58:05,885 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pearson] tracking url: http://localhost:8080/
2014-08-22 21:58:05,886 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:58:05,886 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:58:05,889 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:58:05,890 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local2141916785_0004_m_000000_0
2014-08-22 21:58:05,893 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:05,895 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/critics.txt
2014-08-22 21:58:05,895 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@678a270a
2014-08-22 21:58:05,898 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:58:05,898 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:58:06,043 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:58:06,043 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:58:06,044 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:58:06,044 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:58:06,044 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:58:06,046 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:58:06,046 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:58:06,062 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/critics.txt"]
2014-08-22 21:58:06,062 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(pearson)[by:[{1}:'l'][numSelfJoins:1]]
2014-08-22 21:58:06,069 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:58:06,069 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:58:06,069 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:58:06,069 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 1746; bufvoid = 104857600
2014-08-22 21:58:06,069 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214260(104857040); length = 137/6553600
2014-08-22 21:58:06,073 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:58:06,076 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2141916785_0004_m_000000_0 is done. And is in the process of committing
2014-08-22 21:58:06,078 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/critics.txt:0+828
2014-08-22 21:58:06,079 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2141916785_0004_m_000000_0' done.
2014-08-22 21:58:06,079 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local2141916785_0004_m_000000_0
2014-08-22 21:58:06,079 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:58:06,080 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:58:06,080 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local2141916785_0004_r_000000_0
2014-08-22 21:58:06,083 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:06,084 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@6a74f160
2014-08-22 21:58:06,085 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:58:06,086 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local2141916785_0004_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:58:06,091 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#4 about to shuffle output of map attempt_local2141916785_0004_m_000000_0 decomp: 1818 len: 1822 to MEMORY
2014-08-22 21:58:06,091 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 1818 bytes from map-output for attempt_local2141916785_0004_m_000000_0
2014-08-22 21:58:06,091 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 1818, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->1818
2014-08-22 21:58:06,092 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:58:06,093 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:06,093 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:58:06,096 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:06,096 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 1797 bytes
2014-08-22 21:58:06,099 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 1818 bytes to disk to satisfy reduce memory limit
2014-08-22 21:58:06,099 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 1822 bytes from disk
2014-08-22 21:58:06,099 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:58:06,099 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:06,100 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 1797 bytes
2014-08-22 21:58:06,100 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:06,101 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:58:06,101 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:58:06,115 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: CoGroup(pearson)[by:[{1}:'l'][numSelfJoins:1]]
2014-08-22 21:58:06,116 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[['l', 'n1', 'v1', 'n2', 'v2']]"][3946685601/pearson/]
2014-08-22 21:58:06,126 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(105)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 21:58:06,127 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(110)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 21:58:06,165 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2141916785_0004_r_000000_0 is done. And is in the process of committing
2014-08-22 21:58:06,167 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:06,167 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local2141916785_0004_r_000000_0 is allowed to commit now
2014-08-22 21:58:06,168 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local2141916785_0004_r_000000_0' to file:/tmp/hadoop-teamcity/3946685601_pearson_70A7B74B5C014729AA6B65FCCF43BB64/_temporary/0/task_local2141916785_0004_r_000000
2014-08-22 21:58:06,170 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:58:06,170 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2141916785_0004_r_000000_0' done.
2014-08-22 21:58:06,170 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local2141916785_0004_r_000000_0
2014-08-22 21:58:06,171 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:58:06,188 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pearson] starting step: (2/3)
2014-08-22 21:58:06,189 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:06,191 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:06,231 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:58:06,253 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:58:06,266 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:58:06,266 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:58:06,274 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1023145507_0005
2014-08-22 21:58:06,295 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1023145507/.staging/job_local1023145507_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:06,296 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1023145507/.staging/job_local1023145507_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:06,362 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1023145507_0005/job_local1023145507_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:06,364 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1023145507_0005/job_local1023145507_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:06,365 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:58:06,366 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:58:06,367 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:58:06,367 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pearson] submitted hadoop job: job_local1023145507_0005
2014-08-22 21:58:06,369 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pearson] tracking url: http://localhost:8080/
2014-08-22 21:58:06,371 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:58:06,371 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1023145507_0005_m_000000_0
2014-08-22 21:58:06,374 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:06,376 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/3946685601_pearson_70A7B74B5C014729AA6B65FCCF43BB64/part-00000
2014-08-22 21:58:06,376 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@69fa10da
2014-08-22 21:58:06,378 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:58:06,379 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:58:06,519 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:58:06,519 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:58:06,519 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:58:06,519 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:58:06,520 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:58:06,521 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:58:06,522 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:58:06,534 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[['l', 'n1', 'v1', 'n2', 'v2']]"][3946685601/pearson/]
2014-08-22 21:58:06,534 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(pearson)[by:[{?}:ALL]]
2014-08-22 21:58:06,552 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:58:06,553 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:58:06,553 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:58:06,553 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 13104; bufvoid = 104857600
2014-08-22 21:58:06,553 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26213704(104854816); length = 693/6553600
2014-08-22 21:58:06,569 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:58:06,572 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1023145507_0005_m_000000_0 is done. And is in the process of committing
2014-08-22 21:58:06,575 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/3946685601_pearson_70A7B74B5C014729AA6B65FCCF43BB64/part-00000:0+13816
2014-08-22 21:58:06,575 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1023145507_0005_m_000000_0' done.
2014-08-22 21:58:06,575 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1023145507_0005_m_000000_0
2014-08-22 21:58:06,575 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:58:06,576 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:58:06,576 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1023145507_0005_r_000000_0
2014-08-22 21:58:06,579 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:06,579 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@6fd3633c
2014-08-22 21:58:06,580 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:58:06,581 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1023145507_0005_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:58:06,583 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#5 about to shuffle output of map attempt_local1023145507_0005_m_000000_0 decomp: 13454 len: 13458 to MEMORY
2014-08-22 21:58:06,584 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 13454 bytes from map-output for attempt_local1023145507_0005_m_000000_0
2014-08-22 21:58:06,584 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 13454, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->13454
2014-08-22 21:58:06,585 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:58:06,586 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:06,586 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:58:06,589 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:06,589 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 13386 bytes
2014-08-22 21:58:06,593 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 13454 bytes to disk to satisfy reduce memory limit
2014-08-22 21:58:06,594 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 13458 bytes from disk
2014-08-22 21:58:06,594 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:58:06,594 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:06,594 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 13386 bytes
2014-08-22 21:58:06,596 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:06,597 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:58:06,598 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:58:06,610 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(pearson)[by:[{?}:ALL]]
2014-08-22 21:58:06,610 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[['l', 'n1', 'v1', 'n2', 'v2']]"][194854425/pearson/]
2014-08-22 21:58:06,648 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1023145507_0005_r_000000_0 is done. And is in the process of committing
2014-08-22 21:58:06,650 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:06,651 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1023145507_0005_r_000000_0 is allowed to commit now
2014-08-22 21:58:06,652 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1023145507_0005_r_000000_0' to file:/tmp/hadoop-teamcity/194854425_pearson_77404911CC3E4DABB261C8D0AE0B6B38/_temporary/0/task_local1023145507_0005_r_000000
2014-08-22 21:58:06,654 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:58:06,654 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1023145507_0005_r_000000_0' done.
2014-08-22 21:58:06,654 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1023145507_0005_r_000000_0
2014-08-22 21:58:06,655 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:58:06,959 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pearson] starting step: (3/3) ...latform/pearson/composite
2014-08-22 21:58:06,960 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:06,962 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:07,027 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:58:07,048 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:58:07,059 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:58:07,060 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:58:07,066 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1090036218_0006
2014-08-22 21:58:07,085 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1090036218/.staging/job_local1090036218_0006/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:07,087 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1090036218/.staging/job_local1090036218_0006/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:07,146 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1090036218_0006/job_local1090036218_0006.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:07,147 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1090036218_0006/job_local1090036218_0006.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:07,148 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:58:07,148 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pearson] submitted hadoop job: job_local1090036218_0006
2014-08-22 21:58:07,148 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pearson] tracking url: http://localhost:8080/
2014-08-22 21:58:07,149 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:58:07,150 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:58:07,154 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:58:07,154 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1090036218_0006_m_000000_0
2014-08-22 21:58:07,157 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:07,159 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/194854425_pearson_77404911CC3E4DABB261C8D0AE0B6B38/part-00000
2014-08-22 21:58:07,159 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@31313e0e
2014-08-22 21:58:07,162 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:58:07,163 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:58:07,235 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:58:07,236 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:58:07,236 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:58:07,236 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:58:07,236 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:58:07,240 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:58:07,240 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:58:07,254 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[['l', 'n1', 'v1', 'n2', 'v2']]"][194854425/pearson/]
2014-08-22 21:58:07,254 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(pearson)[by:[{2}:'n1', 'n2']]
2014-08-22 21:58:07,265 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:58:07,265 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:58:07,265 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:58:07,265 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 6291; bufvoid = 104857600
2014-08-22 21:58:07,265 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214052(104856208); length = 345/6553600
2014-08-22 21:58:07,272 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:58:07,275 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1090036218_0006_m_000000_0 is done. And is in the process of committing
2014-08-22 21:58:07,277 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/194854425_pearson_77404911CC3E4DABB261C8D0AE0B6B38/part-00000:0+6943
2014-08-22 21:58:07,278 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1090036218_0006_m_000000_0' done.
2014-08-22 21:58:07,278 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1090036218_0006_m_000000_0
2014-08-22 21:58:07,278 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:58:07,279 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:58:07,279 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1090036218_0006_r_000000_0
2014-08-22 21:58:07,281 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:07,282 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@1ae73783
2014-08-22 21:58:07,282 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:58:07,283 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1090036218_0006_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:58:07,287 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#6 about to shuffle output of map attempt_local1090036218_0006_m_000000_0 decomp: 6467 len: 6471 to MEMORY
2014-08-22 21:58:07,288 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 6467 bytes from map-output for attempt_local1090036218_0006_m_000000_0
2014-08-22 21:58:07,288 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 6467, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->6467
2014-08-22 21:58:07,289 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:58:07,289 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:07,290 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:58:07,292 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:07,293 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 6432 bytes
2014-08-22 21:58:07,295 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 6467 bytes to disk to satisfy reduce memory limit
2014-08-22 21:58:07,296 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 6471 bytes from disk
2014-08-22 21:58:07,296 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:58:07,296 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:07,297 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 6432 bytes
2014-08-22 21:58:07,297 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:07,298 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:58:07,298 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:58:07,309 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(pearson)[by:[{2}:'n1', 'n2']]
2014-08-22 21:58:07,309 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/pearson/composite"]
2014-08-22 21:58:07,335 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1090036218_0006_r_000000_0 is done. And is in the process of committing
2014-08-22 21:58:07,336 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:07,337 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1090036218_0006_r_000000_0 is allowed to commit now
2014-08-22 21:58:07,338 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1090036218_0006_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/pearson/composite/_temporary/0/task_local1090036218_0006_r_000000
2014-08-22 21:58:07,339 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:58:07,339 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1090036218_0006_r_000000_0' done.
2014-08-22 21:58:07,339 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1090036218_0006_r_000000_0
2014-08-22 21:58:07,341 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:58:07,371 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/pearson/composite/_temporary
2014-08-22 21:58:07,408 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:58:07,449 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:58:07,452 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/distanceusecaseplatform/pearson/composite
2014-08-22 21:58:07,483 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 21:58:07,484 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 21:58:07,517 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:58:07,521 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:58:07,550 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 21:58:07,570 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] starting
2014-08-22 21:58:07,571 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/critics.txt"]
2014-08-22 21:58:07,572 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/long"]
2014-08-22 21:58:07,572 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] parallel execution is enabled: false
2014-08-22 21:58:07,572 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] starting jobs: 3
2014-08-22 21:58:07,572 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] allocating threads: 1
2014-08-22 21:58:07,573 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] starting step: (1/3)
2014-08-22 21:58:07,574 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:07,576 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:07,604 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:58:07,624 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:58:07,641 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local74633046_0007
2014-08-22 21:58:07,662 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity74633046/.staging/job_local74633046_0007/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:07,663 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity74633046/.staging/job_local74633046_0007/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:07,717 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local74633046_0007/job_local74633046_0007.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:07,718 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local74633046_0007/job_local74633046_0007.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:07,719 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:58:07,719 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] submitted hadoop job: job_local74633046_0007
2014-08-22 21:58:07,719 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:58:07,721 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:58:07,719 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] tracking url: http://localhost:8080/
2014-08-22 21:58:07,723 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:58:07,724 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local74633046_0007_m_000000_0
2014-08-22 21:58:07,726 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:07,729 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/critics.txt
2014-08-22 21:58:07,729 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@6719fc9e
2014-08-22 21:58:07,731 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:58:07,731 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:58:07,888 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:58:07,889 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:58:07,889 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:58:07,889 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:58:07,889 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:58:07,892 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:58:07,892 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:58:07,903 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/critics.txt"]
2014-08-22 21:58:07,903 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(euclidean)[by:[{1}:'movie'][numSelfJoins:1]]
2014-08-22 21:58:07,910 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:58:07,910 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:58:07,910 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:58:07,911 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 1746; bufvoid = 104857600
2014-08-22 21:58:07,911 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214260(104857040); length = 137/6553600
2014-08-22 21:58:07,915 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:58:07,917 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local74633046_0007_m_000000_0 is done. And is in the process of committing
2014-08-22 21:58:07,920 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/critics.txt:0+828
2014-08-22 21:58:07,920 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local74633046_0007_m_000000_0' done.
2014-08-22 21:58:07,920 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local74633046_0007_m_000000_0
2014-08-22 21:58:07,921 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:58:07,921 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:58:07,921 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local74633046_0007_r_000000_0
2014-08-22 21:58:07,924 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:07,924 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@1997f158
2014-08-22 21:58:07,925 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:58:07,925 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local74633046_0007_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:58:07,927 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#7 about to shuffle output of map attempt_local74633046_0007_m_000000_0 decomp: 1818 len: 1822 to MEMORY
2014-08-22 21:58:07,928 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 1818 bytes from map-output for attempt_local74633046_0007_m_000000_0
2014-08-22 21:58:07,928 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 1818, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->1818
2014-08-22 21:58:07,929 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:58:07,930 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:07,930 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:58:07,932 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:07,932 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 1797 bytes
2014-08-22 21:58:07,935 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 1818 bytes to disk to satisfy reduce memory limit
2014-08-22 21:58:07,936 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 1822 bytes from disk
2014-08-22 21:58:07,936 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:58:07,936 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:07,936 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 1797 bytes
2014-08-22 21:58:07,937 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:07,937 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:58:07,938 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:58:07,947 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: CoGroup(euclidean)[by:[{1}:'movie'][numSelfJoins:1]]
2014-08-22 21:58:07,947 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[['movie', 'name1', 'rate1', 'name2', 'rate2']]"][962756127/euclidean/]
2014-08-22 21:58:07,955 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(105)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 21:58:07,955 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(110)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 21:58:07,987 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local74633046_0007_r_000000_0 is done. And is in the process of committing
2014-08-22 21:58:07,989 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:07,989 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local74633046_0007_r_000000_0 is allowed to commit now
2014-08-22 21:58:07,990 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local74633046_0007_r_000000_0' to file:/tmp/hadoop-teamcity/962756127_euclidean_52DEE6EF6DA941F58ADF6D3813996DAF/_temporary/0/task_local74633046_0007_r_000000
2014-08-22 21:58:07,991 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:58:07,991 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local74633046_0007_r_000000_0' done.
2014-08-22 21:58:07,991 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local74633046_0007_r_000000_0
2014-08-22 21:58:07,992 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:58:08,015 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] starting step: (2/3)
2014-08-22 21:58:08,015 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:08,016 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:08,056 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:58:08,077 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:58:08,088 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:58:08,088 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:58:08,094 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local125172544_0008
2014-08-22 21:58:08,113 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity125172544/.staging/job_local125172544_0008/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:08,114 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity125172544/.staging/job_local125172544_0008/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:08,177 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local125172544_0008/job_local125172544_0008.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:08,178 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local125172544_0008/job_local125172544_0008.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:08,180 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:58:08,180 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] submitted hadoop job: job_local125172544_0008
2014-08-22 21:58:08,180 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:58:08,180 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:58:08,180 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] tracking url: http://localhost:8080/
2014-08-22 21:58:08,183 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:58:08,183 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local125172544_0008_m_000000_0
2014-08-22 21:58:08,186 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:08,188 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/962756127_euclidean_52DEE6EF6DA941F58ADF6D3813996DAF/part-00000
2014-08-22 21:58:08,188 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@4335236e
2014-08-22 21:58:08,191 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:58:08,191 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:58:08,336 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:58:08,336 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:58:08,337 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:58:08,337 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:58:08,338 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:58:08,340 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:58:08,340 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:58:08,350 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[['movie', 'name1', 'rate1', 'name2', 'rate2']]"][962756127/euclidean/]
2014-08-22 21:58:08,350 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(euclidean)[by:[{?}:ALL]]
2014-08-22 21:58:08,363 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:58:08,363 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:58:08,364 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:58:08,364 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 13104; bufvoid = 104857600
2014-08-22 21:58:08,364 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26213704(104854816); length = 693/6553600
2014-08-22 21:58:08,376 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:58:08,379 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local125172544_0008_m_000000_0 is done. And is in the process of committing
2014-08-22 21:58:08,381 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/962756127_euclidean_52DEE6EF6DA941F58ADF6D3813996DAF/part-00000:0+13816
2014-08-22 21:58:08,381 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local125172544_0008_m_000000_0' done.
2014-08-22 21:58:08,381 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local125172544_0008_m_000000_0
2014-08-22 21:58:08,382 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:58:08,382 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:58:08,382 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local125172544_0008_r_000000_0
2014-08-22 21:58:08,385 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:08,385 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@322ba3e4
2014-08-22 21:58:08,386 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:58:08,387 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local125172544_0008_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:58:08,389 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#8 about to shuffle output of map attempt_local125172544_0008_m_000000_0 decomp: 13454 len: 13458 to MEMORY
2014-08-22 21:58:08,389 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 13454 bytes from map-output for attempt_local125172544_0008_m_000000_0
2014-08-22 21:58:08,390 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 13454, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->13454
2014-08-22 21:58:08,390 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:58:08,391 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:08,391 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:58:08,394 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:08,394 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 13386 bytes
2014-08-22 21:58:08,398 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 13454 bytes to disk to satisfy reduce memory limit
2014-08-22 21:58:08,398 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 13458 bytes from disk
2014-08-22 21:58:08,398 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:58:08,398 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:08,399 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 13386 bytes
2014-08-22 21:58:08,399 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:08,400 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:58:08,400 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:58:08,410 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(euclidean)[by:[{?}:ALL]]
2014-08-22 21:58:08,410 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[['movie', 'name1', 'rate1', 'name2', 'rate2', 'score']]"][2617370511/euclidean/]
2014-08-22 21:58:08,444 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local125172544_0008_r_000000_0 is done. And is in the process of committing
2014-08-22 21:58:08,446 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:08,447 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local125172544_0008_r_000000_0 is allowed to commit now
2014-08-22 21:58:08,448 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local125172544_0008_r_000000_0' to file:/tmp/hadoop-teamcity/2617370511_euclidean_9B1A94EA88F14521B8ACAFC9359D9C58/_temporary/0/task_local125172544_0008_r_000000
2014-08-22 21:58:08,450 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:58:08,450 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local125172544_0008_r_000000_0' done.
2014-08-22 21:58:08,451 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local125172544_0008_r_000000_0
2014-08-22 21:58:08,451 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:58:08,473 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] starting step: (3/3) ...seplatform/euclidean/long
2014-08-22 21:58:08,474 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:08,475 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:08,514 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:58:08,534 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:58:08,545 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:58:08,546 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:58:08,551 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local2053093323_0009
2014-08-22 21:58:08,571 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity2053093323/.staging/job_local2053093323_0009/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:08,572 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity2053093323/.staging/job_local2053093323_0009/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:08,623 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local2053093323_0009/job_local2053093323_0009.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:08,625 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local2053093323_0009/job_local2053093323_0009.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:08,626 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:58:08,626 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:58:08,627 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:58:08,627 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] submitted hadoop job: job_local2053093323_0009
2014-08-22 21:58:08,628 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] tracking url: http://localhost:8080/
2014-08-22 21:58:08,630 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:58:08,630 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local2053093323_0009_m_000000_0
2014-08-22 21:58:08,632 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:08,634 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/2617370511_euclidean_9B1A94EA88F14521B8ACAFC9359D9C58/part-00000
2014-08-22 21:58:08,634 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@4da9ec16
2014-08-22 21:58:08,637 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:58:08,638 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:58:08,780 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:58:08,781 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:58:08,781 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:58:08,781 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:58:08,781 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:58:08,784 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:58:08,784 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:58:08,794 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[['movie', 'name1', 'rate1', 'name2', 'rate2', 'score']]"][2617370511/euclidean/]
2014-08-22 21:58:08,794 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(euclidean)[by:[{2}:'name1', 'name2']]
2014-08-22 21:58:08,803 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:58:08,803 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:58:08,803 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:58:08,803 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 7074; bufvoid = 104857600
2014-08-22 21:58:08,803 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214052(104856208); length = 345/6553600
2014-08-22 21:58:08,809 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:58:08,811 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2053093323_0009_m_000000_0 is done. And is in the process of committing
2014-08-22 21:58:08,813 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/2617370511_euclidean_9B1A94EA88F14521B8ACAFC9359D9C58/part-00000:0+7726
2014-08-22 21:58:08,813 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2053093323_0009_m_000000_0' done.
2014-08-22 21:58:08,813 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local2053093323_0009_m_000000_0
2014-08-22 21:58:08,814 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:58:08,814 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:58:08,814 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local2053093323_0009_r_000000_0
2014-08-22 21:58:08,816 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:08,817 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@11cf3710
2014-08-22 21:58:08,817 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:58:08,818 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local2053093323_0009_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:58:08,820 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#9 about to shuffle output of map attempt_local2053093323_0009_m_000000_0 decomp: 7250 len: 7254 to MEMORY
2014-08-22 21:58:08,821 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 7250 bytes from map-output for attempt_local2053093323_0009_m_000000_0
2014-08-22 21:58:08,821 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 7250, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->7250
2014-08-22 21:58:08,822 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:58:08,823 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:08,823 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:58:08,828 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:08,828 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 7215 bytes
2014-08-22 21:58:08,831 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 7250 bytes to disk to satisfy reduce memory limit
2014-08-22 21:58:08,831 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 7254 bytes from disk
2014-08-22 21:58:08,832 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:58:08,832 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:08,832 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 7215 bytes
2014-08-22 21:58:08,833 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:08,833 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:58:08,834 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:58:08,843 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(euclidean)[by:[{2}:'name1', 'name2']]
2014-08-22 21:58:08,843 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/long"]
2014-08-22 21:58:08,862 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2053093323_0009_r_000000_0 is done. And is in the process of committing
2014-08-22 21:58:08,864 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:08,864 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local2053093323_0009_r_000000_0 is allowed to commit now
2014-08-22 21:58:08,865 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local2053093323_0009_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/long/_temporary/0/task_local2053093323_0009_r_000000
2014-08-22 21:58:08,866 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:58:08,866 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2053093323_0009_r_000000_0' done.
2014-08-22 21:58:08,866 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local2053093323_0009_r_000000_0
2014-08-22 21:58:08,866 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:58:08,891 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/long/_temporary
2014-08-22 21:58:08,929 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:58:08,973 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:58:08,976 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/distanceusecaseplatform/euclidean/long
2014-08-22 21:58:09,002 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 21:58:09,002 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 21:58:09,026 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:58:09,029 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:58:09,048 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 21:58:09,058 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] starting
2014-08-22 21:58:09,059 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/critics.txt"]
2014-08-22 21:58:09,059 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/short"]
2014-08-22 21:58:09,060 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] parallel execution is enabled: false
2014-08-22 21:58:09,061 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] starting jobs: 3
2014-08-22 21:58:09,061 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] allocating threads: 1
2014-08-22 21:58:09,062 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] starting step: (1/3)
2014-08-22 21:58:09,063 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:09,064 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:09,090 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:58:09,110 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:58:09,127 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local2032911944_0010
2014-08-22 21:58:09,148 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity2032911944/.staging/job_local2032911944_0010/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:09,149 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity2032911944/.staging/job_local2032911944_0010/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:09,202 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local2032911944_0010/job_local2032911944_0010.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:09,203 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local2032911944_0010/job_local2032911944_0010.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:09,204 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:58:09,205 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] submitted hadoop job: job_local2032911944_0010
2014-08-22 21:58:09,205 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:58:09,205 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] tracking url: http://localhost:8080/
2014-08-22 21:58:09,205 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:58:09,208 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:58:09,208 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local2032911944_0010_m_000000_0
2014-08-22 21:58:09,210 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:09,212 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/critics.txt
2014-08-22 21:58:09,212 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@3781efb9
2014-08-22 21:58:09,214 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:58:09,214 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:58:09,516 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:58:09,516 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:58:09,516 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:58:09,516 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:58:09,517 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:58:09,518 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:58:09,518 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:58:09,527 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/critics.txt"]
2014-08-22 21:58:09,527 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(euclidean)[by:[{1}:'movie'][numSelfJoins:1]]
2014-08-22 21:58:09,533 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:58:09,534 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:58:09,534 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:58:09,534 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 1746; bufvoid = 104857600
2014-08-22 21:58:09,534 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214260(104857040); length = 137/6553600
2014-08-22 21:58:09,538 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:58:09,541 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2032911944_0010_m_000000_0 is done. And is in the process of committing
2014-08-22 21:58:09,543 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/critics.txt:0+828
2014-08-22 21:58:09,543 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2032911944_0010_m_000000_0' done.
2014-08-22 21:58:09,543 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local2032911944_0010_m_000000_0
2014-08-22 21:58:09,543 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:58:09,544 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:58:09,544 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local2032911944_0010_r_000000_0
2014-08-22 21:58:09,547 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:09,547 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@e026161
2014-08-22 21:58:09,548 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:58:09,549 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local2032911944_0010_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:58:09,551 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#10 about to shuffle output of map attempt_local2032911944_0010_m_000000_0 decomp: 1818 len: 1822 to MEMORY
2014-08-22 21:58:09,551 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 1818 bytes from map-output for attempt_local2032911944_0010_m_000000_0
2014-08-22 21:58:09,551 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 1818, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->1818
2014-08-22 21:58:09,552 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:58:09,554 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:09,554 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:58:09,558 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:09,559 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 1797 bytes
2014-08-22 21:58:09,561 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 1818 bytes to disk to satisfy reduce memory limit
2014-08-22 21:58:09,561 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 1822 bytes from disk
2014-08-22 21:58:09,561 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:58:09,561 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:09,562 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 1797 bytes
2014-08-22 21:58:09,563 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:09,563 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:58:09,563 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:58:09,571 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: CoGroup(euclidean)[by:[{1}:'movie'][numSelfJoins:1]]
2014-08-22 21:58:09,571 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[['movie', 'name1', 'rate1', 'name2', 'rate2']]"][2599396630/euclidean/]
2014-08-22 21:58:09,580 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(105)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 21:58:09,580 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(110)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 21:58:09,607 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2032911944_0010_r_000000_0 is done. And is in the process of committing
2014-08-22 21:58:09,609 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:09,609 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local2032911944_0010_r_000000_0 is allowed to commit now
2014-08-22 21:58:09,610 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local2032911944_0010_r_000000_0' to file:/tmp/hadoop-teamcity/2599396630_euclidean_222F818C6713476199DD56C7A26E8027/_temporary/0/task_local2032911944_0010_r_000000
2014-08-22 21:58:09,611 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:58:09,611 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2032911944_0010_r_000000_0' done.
2014-08-22 21:58:09,611 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local2032911944_0010_r_000000_0
2014-08-22 21:58:09,611 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:58:09,632 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] starting step: (2/3)
2014-08-22 21:58:09,633 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:09,634 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:09,673 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:58:09,692 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:58:09,703 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:58:09,703 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:58:09,708 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local100191702_0011
2014-08-22 21:58:09,728 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity100191702/.staging/job_local100191702_0011/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:09,729 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity100191702/.staging/job_local100191702_0011/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:09,783 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local100191702_0011/job_local100191702_0011.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:09,784 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local100191702_0011/job_local100191702_0011.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:09,785 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:58:09,785 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] submitted hadoop job: job_local100191702_0011
2014-08-22 21:58:09,785 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:58:09,786 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:58:09,786 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] tracking url: http://localhost:8080/
2014-08-22 21:58:09,788 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:58:09,789 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local100191702_0011_m_000000_0
2014-08-22 21:58:09,791 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:09,794 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/2599396630_euclidean_222F818C6713476199DD56C7A26E8027/part-00000
2014-08-22 21:58:09,794 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@12dfbabd
2014-08-22 21:58:09,796 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:58:09,797 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:58:09,940 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:58:09,941 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:58:09,941 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:58:09,941 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:58:09,941 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:58:09,942 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:58:09,942 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:58:09,950 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[['movie', 'name1', 'rate1', 'name2', 'rate2']]"][2599396630/euclidean/]
2014-08-22 21:58:09,950 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(euclidean)[by:[{?}:ALL]]
2014-08-22 21:58:09,961 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:58:09,961 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:58:09,962 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:58:09,962 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 13104; bufvoid = 104857600
2014-08-22 21:58:09,962 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26213704(104854816); length = 693/6553600
2014-08-22 21:58:09,970 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:58:09,972 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local100191702_0011_m_000000_0 is done. And is in the process of committing
2014-08-22 21:58:09,974 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/2599396630_euclidean_222F818C6713476199DD56C7A26E8027/part-00000:0+13816
2014-08-22 21:58:09,974 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local100191702_0011_m_000000_0' done.
2014-08-22 21:58:09,974 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local100191702_0011_m_000000_0
2014-08-22 21:58:09,974 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:58:09,975 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:58:09,975 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local100191702_0011_r_000000_0
2014-08-22 21:58:09,977 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:09,977 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@7286a58a
2014-08-22 21:58:09,978 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:58:09,980 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local100191702_0011_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:58:09,982 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#11 about to shuffle output of map attempt_local100191702_0011_m_000000_0 decomp: 13454 len: 13458 to MEMORY
2014-08-22 21:58:09,982 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 13454 bytes from map-output for attempt_local100191702_0011_m_000000_0
2014-08-22 21:58:09,982 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 13454, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->13454
2014-08-22 21:58:09,983 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:58:09,984 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:09,984 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:58:09,986 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:09,986 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 13386 bytes
2014-08-22 21:58:09,990 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 13454 bytes to disk to satisfy reduce memory limit
2014-08-22 21:58:09,990 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 13458 bytes from disk
2014-08-22 21:58:09,990 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:58:09,991 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:09,991 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 13386 bytes
2014-08-22 21:58:09,992 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:09,992 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:58:09,992 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:58:09,999 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(euclidean)[by:[{?}:ALL]]
2014-08-22 21:58:09,999 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[['movie', 'name1', 'rate1', 'name2', 'rate2', 'score']]"][6122172497/euclidean/]
2014-08-22 21:58:10,028 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local100191702_0011_r_000000_0 is done. And is in the process of committing
2014-08-22 21:58:10,030 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:10,030 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local100191702_0011_r_000000_0 is allowed to commit now
2014-08-22 21:58:10,031 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local100191702_0011_r_000000_0' to file:/tmp/hadoop-teamcity/6122172497_euclidean_FFDB4DCCE006446C98FBCA06F1702124/_temporary/0/task_local100191702_0011_r_000000
2014-08-22 21:58:10,032 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:58:10,032 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local100191702_0011_r_000000_0' done.
2014-08-22 21:58:10,032 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local100191702_0011_r_000000_0
2014-08-22 21:58:10,032 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:58:10,047 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] starting step: (3/3) ...eplatform/euclidean/short
2014-08-22 21:58:10,048 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:10,049 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:58:10,084 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:58:10,103 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:58:10,114 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:58:10,114 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:58:10,120 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1151188186_0012
2014-08-22 21:58:10,139 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1151188186/.staging/job_local1151188186_0012/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:10,140 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1151188186/.staging/job_local1151188186_0012/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:10,199 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1151188186_0012/job_local1151188186_0012.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:58:10,201 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1151188186_0012/job_local1151188186_0012.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:58:10,201 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:58:10,202 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] submitted hadoop job: job_local1151188186_0012
2014-08-22 21:58:10,202 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:58:10,202 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] tracking url: http://localhost:8080/
2014-08-22 21:58:10,202 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:58:10,206 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:58:10,207 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1151188186_0012_m_000000_0
2014-08-22 21:58:10,209 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:10,210 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/6122172497_euclidean_FFDB4DCCE006446C98FBCA06F1702124/part-00000
2014-08-22 21:58:10,211 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@53e36ec6
2014-08-22 21:58:10,213 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:58:10,213 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:58:10,358 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:58:10,359 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:58:10,359 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:58:10,360 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:58:10,360 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:58:10,362 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:58:10,362 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:58:10,370 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[['movie', 'name1', 'rate1', 'name2', 'rate2', 'score']]"][6122172497/euclidean/]
2014-08-22 21:58:10,371 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(euclidean)[by:[{2}:'name1', 'name2']]
2014-08-22 21:58:10,378 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:58:10,379 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:58:10,379 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:58:10,380 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 7074; bufvoid = 104857600
2014-08-22 21:58:10,380 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214052(104856208); length = 345/6553600
2014-08-22 21:58:10,385 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:58:10,387 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1151188186_0012_m_000000_0 is done. And is in the process of committing
2014-08-22 21:58:10,389 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/6122172497_euclidean_FFDB4DCCE006446C98FBCA06F1702124/part-00000:0+7726
2014-08-22 21:58:10,390 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1151188186_0012_m_000000_0' done.
2014-08-22 21:58:10,390 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1151188186_0012_m_000000_0
2014-08-22 21:58:10,390 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:58:10,391 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:58:10,391 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1151188186_0012_r_000000_0
2014-08-22 21:58:10,394 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:58:10,394 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@25e12e2c
2014-08-22 21:58:10,395 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:58:10,396 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1151188186_0012_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:58:10,398 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#12 about to shuffle output of map attempt_local1151188186_0012_m_000000_0 decomp: 7250 len: 7254 to MEMORY
2014-08-22 21:58:10,399 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 7250 bytes from map-output for attempt_local1151188186_0012_m_000000_0
2014-08-22 21:58:10,399 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 7250, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->7250
2014-08-22 21:58:10,400 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:58:10,401 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:10,401 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:58:10,404 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:10,404 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 7215 bytes
2014-08-22 21:58:10,407 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 7250 bytes to disk to satisfy reduce memory limit
2014-08-22 21:58:10,408 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 7254 bytes from disk
2014-08-22 21:58:10,408 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:58:10,408 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:58:10,409 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 7215 bytes
2014-08-22 21:58:10,410 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:10,411 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:58:10,411 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:58:10,420 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(euclidean)[by:[{2}:'name1', 'name2']]
2014-08-22 21:58:10,420 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/short"]
2014-08-22 21:58:10,440 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1151188186_0012_r_000000_0 is done. And is in the process of committing
2014-08-22 21:58:10,442 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:58:10,442 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1151188186_0012_r_000000_0 is allowed to commit now
2014-08-22 21:58:10,443 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1151188186_0012_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/short/_temporary/0/task_local1151188186_0012_r_000000
2014-08-22 21:58:10,444 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:58:10,444 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1151188186_0012_r_000000_0' done.
2014-08-22 21:58:10,444 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1151188186_0012_r_000000_0
2014-08-22 21:58:10,444 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:58:10,472 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/short/_temporary
2014-08-22 21:58:10,507 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:58:10,542 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:58:10,545 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/distanceusecaseplatform/euclidean/short