2014-08-22 20:11:20,937 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(187)) - found 1 test platforms from classpath
2014-08-22 20:11:21,002 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(237)) - installing platform: hadoop2-mr1
2014-08-22 20:11:21,002 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(238)) - running test: cascading.DistanceUseCasePlatformTest
2014-08-22 20:11:21,032 INFO hadoop2.Hadoop2MR1Platform (Hadoop2MR1Platform.java:setUp(106)) - not using cluster
2014-08-22 20:11:21,668 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 20:11:21,974 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:11:21,976 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 20:11:21,989 INFO property.AppProps (AppProps.java:getAppID(162)) - using app.id: A51A9121D3F5420DB060C7F72AC0F49E
2014-08-22 20:11:22,093 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:22,135 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:22,261 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:11:22,329 INFO util.Version (Version.java:printBanner(78)) - Concurrent, Inc - Cascading 2.5.6
2014-08-22 20:11:22,333 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] starting
2014-08-22 20:11:22,334 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/critics.txt"]
2014-08-22 20:11:22,335 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/composite"]
2014-08-22 20:11:22,336 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] parallel execution is enabled: false
2014-08-22 20:11:22,338 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] starting jobs: 3
2014-08-22 20:11:22,338 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] allocating threads: 1
2014-08-22 20:11:22,341 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] starting step: (1/3)
2014-08-22 20:11:22,365 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - session.id is deprecated. Instead, use dfs.metrics.session-id
2014-08-22 20:11:22,366 INFO jvm.JvmMetrics (JvmMetrics.java:init(76)) - Initializing JVM Metrics with processName=JobTracker, sessionId=
2014-08-22 20:11:22,390 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:22,779 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:22,823 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:22,981 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local862908581_0001
2014-08-22 20:11:23,035 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity862908581/.staging/job_local862908581_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:23,036 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity862908581/.staging/job_local862908581_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:23,220 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local862908581_0001/job_local862908581_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:23,221 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local862908581_0001/job_local862908581_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:23,234 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:23,236 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:23,239 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] submitted hadoop job: job_local862908581_0001
2014-08-22 20:11:23,240 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] tracking url: http://localhost:8080/
2014-08-22 20:11:23,240 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:23,302 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:23,307 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local862908581_0001_m_000000_0
2014-08-22 20:11:23,351 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:23,362 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/critics.txt
2014-08-22 20:11:23,362 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@141ed7ac
2014-08-22 20:11:23,372 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:23,379 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:23,530 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:23,531 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:23,531 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:23,531 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:23,531 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:23,556 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:23,557 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:23,615 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.task.partition is deprecated. Instead, use mapreduce.task.partition
2014-08-22 20:11:23,634 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/critics.txt"]
2014-08-22 20:11:23,634 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(euclidean)[by:[{1}:'l'][numSelfJoins:1]]
2014-08-22 20:11:23,655 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:23,655 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:23,655 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:23,655 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 1746; bufvoid = 104857600
2014-08-22 20:11:23,656 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214260(104857040); length = 137/6553600
2014-08-22 20:11:23,673 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:23,677 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local862908581_0001_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:23,688 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/critics.txt:0+828
2014-08-22 20:11:23,688 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local862908581_0001_m_000000_0' done.
2014-08-22 20:11:23,689 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local862908581_0001_m_000000_0
2014-08-22 20:11:23,689 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:23,692 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:23,692 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local862908581_0001_r_000000_0
2014-08-22 20:11:23,705 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:23,709 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@7c82a13a
2014-08-22 20:11:23,724 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:23,728 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local862908581_0001_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:23,763 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#1 about to shuffle output of map attempt_local862908581_0001_m_000000_0 decomp: 1818 len: 1822 to MEMORY
2014-08-22 20:11:23,769 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 1818 bytes from map-output for attempt_local862908581_0001_m_000000_0
2014-08-22 20:11:23,813 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 1818, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->1818
2014-08-22 20:11:23,815 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:23,816 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:23,816 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 20:11:23,829 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:23,830 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 20:11:23,833 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 1818 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:23,834 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 1822 bytes from disk
2014-08-22 20:11:23,835 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:23,835 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:23,836 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 20:11:23,836 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:23,838 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:23,839 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:23,861 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: CoGroup(euclidean)[by:[{1}:'l'][numSelfJoins:1]]
2014-08-22 20:11:23,862 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[['l', 'n1', 'v1', 'n2', 'v2']]"][8030991845/euclidean/]
2014-08-22 20:11:23,900 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(105)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 20:11:23,900 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(110)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 20:11:23,975 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local862908581_0001_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:23,977 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:23,978 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local862908581_0001_r_000000_0 is allowed to commit now
2014-08-22 20:11:23,979 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local862908581_0001_r_000000_0' to file:/tmp/hadoop-teamcity/8030991845_euclidean_1C371BD9EA81480D92C060E91A1F6EC9/_temporary/0/task_local862908581_0001_r_000000
2014-08-22 20:11:23,981 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:23,981 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local862908581_0001_r_000000_0' done.
2014-08-22 20:11:23,981 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local862908581_0001_r_000000_0
2014-08-22 20:11:23,982 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:24,077 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] starting step: (2/3)
2014-08-22 20:11:24,077 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:24,079 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:24,276 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:24,302 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:24,322 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:24,323 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:24,360 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1623154741_0002
2014-08-22 20:11:24,384 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1623154741/.staging/job_local1623154741_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:24,385 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1623154741/.staging/job_local1623154741_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:24,462 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1623154741_0002/job_local1623154741_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:24,463 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1623154741_0002/job_local1623154741_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:24,464 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:24,465 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] submitted hadoop job: job_local1623154741_0002
2014-08-22 20:11:24,465 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] tracking url: http://localhost:8080/
2014-08-22 20:11:24,466 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:24,466 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:24,471 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:24,471 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1623154741_0002_m_000000_0
2014-08-22 20:11:24,474 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:24,476 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/8030991845_euclidean_1C371BD9EA81480D92C060E91A1F6EC9/part-00000
2014-08-22 20:11:24,476 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@63cea096
2014-08-22 20:11:24,489 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:24,489 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:24,632 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:24,632 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:24,632 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:24,632 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:24,632 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:24,634 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:24,634 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:24,649 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[['l', 'n1', 'v1', 'n2', 'v2']]"][8030991845/euclidean/]
2014-08-22 20:11:24,649 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(euclidean)[by:[{?}:ALL]]
2014-08-22 20:11:24,686 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:24,687 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:24,687 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:24,687 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 13104; bufvoid = 104857600
2014-08-22 20:11:24,687 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26213704(104854816); length = 693/6553600
2014-08-22 20:11:24,759 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:24,763 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1623154741_0002_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:24,765 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/8030991845_euclidean_1C371BD9EA81480D92C060E91A1F6EC9/part-00000:0+13816
2014-08-22 20:11:24,766 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1623154741_0002_m_000000_0' done.
2014-08-22 20:11:24,766 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1623154741_0002_m_000000_0
2014-08-22 20:11:24,766 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:24,767 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:24,767 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1623154741_0002_r_000000_0
2014-08-22 20:11:24,770 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:24,770 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@3f9ab00e
2014-08-22 20:11:24,771 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:24,772 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1623154741_0002_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:24,774 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#2 about to shuffle output of map attempt_local1623154741_0002_m_000000_0 decomp: 13454 len: 13458 to MEMORY
2014-08-22 20:11:24,775 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 13454 bytes from map-output for attempt_local1623154741_0002_m_000000_0
2014-08-22 20:11:24,776 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 13454, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->13454
2014-08-22 20:11:24,776 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:24,777 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:24,778 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 20:11:24,781 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:24,781 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 20:11:24,787 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 13454 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:24,787 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 13458 bytes from disk
2014-08-22 20:11:24,788 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:24,788 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:24,788 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 20:11:24,789 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:24,790 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:24,790 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:24,805 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(euclidean)[by:[{?}:ALL]]
2014-08-22 20:11:24,805 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[['l', 'n1', 'v1', 'n2', 'v2']]"][9874089912/euclidean/]
2014-08-22 20:11:24,849 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1623154741_0002_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:24,851 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:24,851 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1623154741_0002_r_000000_0 is allowed to commit now
2014-08-22 20:11:24,852 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1623154741_0002_r_000000_0' to file:/tmp/hadoop-teamcity/9874089912_euclidean_47DB10B91051438DA8535F9EF1D878EC/_temporary/0/task_local1623154741_0002_r_000000
2014-08-22 20:11:24,854 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:24,854 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1623154741_0002_r_000000_0' done.
2014-08-22 20:11:24,854 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1623154741_0002_r_000000_0
2014-08-22 20:11:24,855 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:24,882 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] starting step: (3/3) ...tform/euclidean/composite
2014-08-22 20:11:24,882 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:24,884 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:24,930 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:24,954 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:24,971 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:24,972 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:25,000 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1227484731_0003
2014-08-22 20:11:25,027 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1227484731/.staging/job_local1227484731_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:25,028 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1227484731/.staging/job_local1227484731_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:25,125 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1227484731_0003/job_local1227484731_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:25,127 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1227484731_0003/job_local1227484731_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:25,129 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:25,129 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:25,130 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:25,130 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] submitted hadoop job: job_local1227484731_0003
2014-08-22 20:11:25,131 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] tracking url: http://localhost:8080/
2014-08-22 20:11:25,134 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:25,135 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1227484731_0003_m_000000_0
2014-08-22 20:11:25,138 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:25,142 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/9874089912_euclidean_47DB10B91051438DA8535F9EF1D878EC/part-00000
2014-08-22 20:11:25,142 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@172b29ed
2014-08-22 20:11:25,144 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:25,144 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:25,294 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:25,294 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:25,294 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:25,294 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:25,294 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:25,296 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:25,296 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:25,310 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[['l', 'n1', 'v1', 'n2', 'v2']]"][9874089912/euclidean/]
2014-08-22 20:11:25,310 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(euclidean)[by:[{2}:'n1', 'n2']]
2014-08-22 20:11:25,324 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:25,324 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:25,324 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:25,325 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 6291; bufvoid = 104857600
2014-08-22 20:11:25,325 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214052(104856208); length = 345/6553600
2014-08-22 20:11:25,334 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:25,337 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1227484731_0003_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:25,339 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/9874089912_euclidean_47DB10B91051438DA8535F9EF1D878EC/part-00000:0+6943
2014-08-22 20:11:25,340 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1227484731_0003_m_000000_0' done.
2014-08-22 20:11:25,340 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1227484731_0003_m_000000_0
2014-08-22 20:11:25,340 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:25,341 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:25,341 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1227484731_0003_r_000000_0
2014-08-22 20:11:25,344 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:25,344 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@233e9934
2014-08-22 20:11:25,345 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:25,346 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1227484731_0003_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:25,348 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#3 about to shuffle output of map attempt_local1227484731_0003_m_000000_0 decomp: 6467 len: 6471 to MEMORY
2014-08-22 20:11:25,349 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 6467 bytes from map-output for attempt_local1227484731_0003_m_000000_0
2014-08-22 20:11:25,349 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 6467, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->6467
2014-08-22 20:11:25,350 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:25,351 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:25,352 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 20:11:25,355 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:25,355 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 20:11:25,359 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 6467 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:25,359 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 6471 bytes from disk
2014-08-22 20:11:25,359 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:25,359 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:25,360 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 20:11:25,361 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:25,361 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:25,362 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:25,375 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(euclidean)[by:[{2}:'n1', 'n2']]
2014-08-22 20:11:25,376 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/composite"]
2014-08-22 20:11:25,404 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1227484731_0003_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:25,406 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:25,407 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1227484731_0003_r_000000_0 is allowed to commit now
2014-08-22 20:11:25,408 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1227484731_0003_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/composite/_temporary/0/task_local1227484731_0003_r_000000
2014-08-22 20:11:25,410 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:25,410 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1227484731_0003_r_000000_0' done.
2014-08-22 20:11:25,410 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1227484731_0003_r_000000_0
2014-08-22 20:11:25,411 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:25,445 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/composite/_temporary
2014-08-22 20:11:25,488 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:25,535 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:25,538 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output//hadoop2-mr1/distanceusecaseplatform/euclidean/composite
2014-08-22 20:11:25,573 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:11:25,574 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 20:11:25,607 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:25,613 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:25,643 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:11:25,656 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [pearson] starting
2014-08-22 20:11:25,656 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [pearson] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/critics.txt"]
2014-08-22 20:11:25,656 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [pearson] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/pearson/composite"]
2014-08-22 20:11:25,657 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [pearson] parallel execution is enabled: false
2014-08-22 20:11:25,657 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [pearson] starting jobs: 3
2014-08-22 20:11:25,657 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [pearson] allocating threads: 1
2014-08-22 20:11:25,658 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pearson] starting step: (1/3)
2014-08-22 20:11:25,659 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:25,661 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:25,694 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:25,717 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:25,737 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1862133144_0004
2014-08-22 20:11:25,759 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1862133144/.staging/job_local1862133144_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:25,759 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1862133144/.staging/job_local1862133144_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:25,849 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1862133144_0004/job_local1862133144_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:25,849 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1862133144_0004/job_local1862133144_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:25,851 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:25,851 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pearson] submitted hadoop job: job_local1862133144_0004
2014-08-22 20:11:25,851 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:25,851 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pearson] tracking url: http://localhost:8080/
2014-08-22 20:11:25,852 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:25,855 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:25,855 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1862133144_0004_m_000000_0
2014-08-22 20:11:25,858 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:25,860 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/critics.txt
2014-08-22 20:11:25,860 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@42101da9
2014-08-22 20:11:25,862 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:25,862 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:26,006 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:26,006 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:26,006 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:26,007 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:26,007 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:26,009 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:26,009 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:26,025 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/critics.txt"]
2014-08-22 20:11:26,026 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(pearson)[by:[{1}:'l'][numSelfJoins:1]]
2014-08-22 20:11:26,032 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:26,032 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:26,032 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:26,032 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 1746; bufvoid = 104857600
2014-08-22 20:11:26,032 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214260(104857040); length = 137/6553600
2014-08-22 20:11:26,037 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:26,039 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1862133144_0004_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:26,042 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/critics.txt:0+828
2014-08-22 20:11:26,042 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1862133144_0004_m_000000_0' done.
2014-08-22 20:11:26,042 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1862133144_0004_m_000000_0
2014-08-22 20:11:26,043 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:26,043 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:26,044 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1862133144_0004_r_000000_0
2014-08-22 20:11:26,046 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:26,046 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@8f5cbda
2014-08-22 20:11:26,047 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:26,048 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1862133144_0004_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:26,050 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#4 about to shuffle output of map attempt_local1862133144_0004_m_000000_0 decomp: 1818 len: 1822 to MEMORY
2014-08-22 20:11:26,052 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 1818 bytes from map-output for attempt_local1862133144_0004_m_000000_0
2014-08-22 20:11:26,052 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 1818, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->1818
2014-08-22 20:11:26,054 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:26,055 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:26,055 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 20:11:26,058 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:26,058 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 20:11:26,060 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 1818 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:26,061 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 1822 bytes from disk
2014-08-22 20:11:26,061 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:26,061 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:26,062 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 20:11:26,062 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:26,063 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:26,063 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:26,077 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: CoGroup(pearson)[by:[{1}:'l'][numSelfJoins:1]]
2014-08-22 20:11:26,077 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[['l', 'n1', 'v1', 'n2', 'v2']]"][9457619964/pearson/]
2014-08-22 20:11:26,087 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(105)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 20:11:26,088 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(110)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 20:11:26,124 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1862133144_0004_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:26,126 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:26,126 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1862133144_0004_r_000000_0 is allowed to commit now
2014-08-22 20:11:26,127 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1862133144_0004_r_000000_0' to file:/tmp/hadoop-teamcity/9457619964_pearson_992B1271688C4BC2AA5AF29873486A06/_temporary/0/task_local1862133144_0004_r_000000
2014-08-22 20:11:26,129 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:26,129 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1862133144_0004_r_000000_0' done.
2014-08-22 20:11:26,129 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1862133144_0004_r_000000_0
2014-08-22 20:11:26,131 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:26,155 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pearson] starting step: (2/3)
2014-08-22 20:11:26,155 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:26,156 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:26,197 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:26,218 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:26,230 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:26,230 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:26,252 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local565144749_0005
2014-08-22 20:11:26,271 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity565144749/.staging/job_local565144749_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:26,272 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity565144749/.staging/job_local565144749_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:26,328 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local565144749_0005/job_local565144749_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:26,328 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local565144749_0005/job_local565144749_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:26,330 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:26,332 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pearson] submitted hadoop job: job_local565144749_0005
2014-08-22 20:11:26,332 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pearson] tracking url: http://localhost:8080/
2014-08-22 20:11:26,332 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:26,333 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:26,336 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:26,337 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local565144749_0005_m_000000_0
2014-08-22 20:11:26,339 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:26,340 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/9457619964_pearson_992B1271688C4BC2AA5AF29873486A06/part-00000
2014-08-22 20:11:26,341 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@52c20893
2014-08-22 20:11:26,343 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:26,343 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:26,481 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:26,482 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:26,482 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:26,482 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:26,482 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:26,484 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:26,484 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:26,497 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[['l', 'n1', 'v1', 'n2', 'v2']]"][9457619964/pearson/]
2014-08-22 20:11:26,497 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(pearson)[by:[{?}:ALL]]
2014-08-22 20:11:26,516 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:26,516 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:26,517 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:26,517 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 13104; bufvoid = 104857600
2014-08-22 20:11:26,517 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26213704(104854816); length = 693/6553600
2014-08-22 20:11:26,531 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:26,533 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local565144749_0005_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:26,536 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/9457619964_pearson_992B1271688C4BC2AA5AF29873486A06/part-00000:0+13816
2014-08-22 20:11:26,536 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local565144749_0005_m_000000_0' done.
2014-08-22 20:11:26,536 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local565144749_0005_m_000000_0
2014-08-22 20:11:26,537 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:26,537 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:26,538 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local565144749_0005_r_000000_0
2014-08-22 20:11:26,540 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:26,540 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@6568f248
2014-08-22 20:11:26,541 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:26,542 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local565144749_0005_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:26,544 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#5 about to shuffle output of map attempt_local565144749_0005_m_000000_0 decomp: 13454 len: 13458 to MEMORY
2014-08-22 20:11:26,545 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 13454 bytes from map-output for attempt_local565144749_0005_m_000000_0
2014-08-22 20:11:26,545 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 13454, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->13454
2014-08-22 20:11:26,546 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:26,547 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:26,547 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 20:11:26,550 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:26,550 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 20:11:26,554 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 13454 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:26,555 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 13458 bytes from disk
2014-08-22 20:11:26,555 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:26,555 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:26,556 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 20:11:26,556 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:26,557 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:26,557 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:26,568 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(pearson)[by:[{?}:ALL]]
2014-08-22 20:11:26,568 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[['l', 'n1', 'v1', 'n2', 'v2']]"][9086173784/pearson/]
2014-08-22 20:11:26,603 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local565144749_0005_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:26,604 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:26,605 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local565144749_0005_r_000000_0 is allowed to commit now
2014-08-22 20:11:26,606 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local565144749_0005_r_000000_0' to file:/tmp/hadoop-teamcity/9086173784_pearson_7273897DC93045EE9B3CB5BF418598E8/_temporary/0/task_local565144749_0005_r_000000
2014-08-22 20:11:26,607 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:26,607 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local565144749_0005_r_000000_0' done.
2014-08-22 20:11:26,607 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local565144749_0005_r_000000_0
2014-08-22 20:11:26,608 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:26,627 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pearson] starting step: (3/3) ...latform/pearson/composite
2014-08-22 20:11:26,628 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:26,629 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:26,668 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:26,690 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:26,702 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:26,703 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:26,995 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1282610998_0006
2014-08-22 20:11:27,017 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1282610998/.staging/job_local1282610998_0006/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:27,017 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1282610998/.staging/job_local1282610998_0006/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:27,072 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1282610998_0006/job_local1282610998_0006.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:27,072 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1282610998_0006/job_local1282610998_0006.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:27,074 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:27,074 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pearson] submitted hadoop job: job_local1282610998_0006
2014-08-22 20:11:27,075 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pearson] tracking url: http://localhost:8080/
2014-08-22 20:11:27,075 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:27,076 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:27,080 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:27,080 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1282610998_0006_m_000000_0
2014-08-22 20:11:27,083 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:27,084 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/9086173784_pearson_7273897DC93045EE9B3CB5BF418598E8/part-00000
2014-08-22 20:11:27,085 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@6f7e982f
2014-08-22 20:11:27,086 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:27,087 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:27,159 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:27,159 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:27,160 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:27,160 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:27,160 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:27,166 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:27,167 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:27,180 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[['l', 'n1', 'v1', 'n2', 'v2']]"][9086173784/pearson/]
2014-08-22 20:11:27,181 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(pearson)[by:[{2}:'n1', 'n2']]
2014-08-22 20:11:27,193 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:27,193 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:27,193 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:27,193 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 6291; bufvoid = 104857600
2014-08-22 20:11:27,193 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214052(104856208); length = 345/6553600
2014-08-22 20:11:27,200 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:27,203 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1282610998_0006_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:27,205 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/9086173784_pearson_7273897DC93045EE9B3CB5BF418598E8/part-00000:0+6943
2014-08-22 20:11:27,205 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1282610998_0006_m_000000_0' done.
2014-08-22 20:11:27,206 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1282610998_0006_m_000000_0
2014-08-22 20:11:27,206 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:27,207 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:27,207 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1282610998_0006_r_000000_0
2014-08-22 20:11:27,211 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:27,211 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@6b6d079a
2014-08-22 20:11:27,212 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:27,213 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1282610998_0006_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:27,215 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#6 about to shuffle output of map attempt_local1282610998_0006_m_000000_0 decomp: 6467 len: 6471 to MEMORY
2014-08-22 20:11:27,215 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 6467 bytes from map-output for attempt_local1282610998_0006_m_000000_0
2014-08-22 20:11:27,216 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 6467, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->6467
2014-08-22 20:11:27,216 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:27,218 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:27,218 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 20:11:27,220 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:27,221 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 20:11:27,224 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 6467 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:27,224 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 6471 bytes from disk
2014-08-22 20:11:27,224 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:27,224 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:27,225 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 20:11:27,225 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:27,226 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:27,226 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:27,238 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(pearson)[by:[{2}:'n1', 'n2']]
2014-08-22 20:11:27,238 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/pearson/composite"]
2014-08-22 20:11:27,265 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1282610998_0006_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:27,266 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:27,267 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1282610998_0006_r_000000_0 is allowed to commit now
2014-08-22 20:11:27,268 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1282610998_0006_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/pearson/composite/_temporary/0/task_local1282610998_0006_r_000000
2014-08-22 20:11:27,269 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:27,270 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1282610998_0006_r_000000_0' done.
2014-08-22 20:11:27,270 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1282610998_0006_r_000000_0
2014-08-22 20:11:27,270 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:27,298 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/pearson/composite/_temporary
2014-08-22 20:11:27,334 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:27,372 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:27,375 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output//hadoop2-mr1/distanceusecaseplatform/pearson/composite
2014-08-22 20:11:27,402 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:11:27,403 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 20:11:27,431 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:27,435 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:27,461 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:11:27,476 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] starting
2014-08-22 20:11:27,476 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/critics.txt"]
2014-08-22 20:11:27,477 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/long"]
2014-08-22 20:11:27,477 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] parallel execution is enabled: false
2014-08-22 20:11:27,477 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] starting jobs: 3
2014-08-22 20:11:27,477 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] allocating threads: 1
2014-08-22 20:11:27,478 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] starting step: (1/3)
2014-08-22 20:11:27,479 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:27,481 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:27,508 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:27,529 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:27,551 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local990074852_0007
2014-08-22 20:11:27,572 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity990074852/.staging/job_local990074852_0007/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:27,572 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity990074852/.staging/job_local990074852_0007/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:27,625 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local990074852_0007/job_local990074852_0007.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:27,626 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local990074852_0007/job_local990074852_0007.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:27,627 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:27,627 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] submitted hadoop job: job_local990074852_0007
2014-08-22 20:11:27,627 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] tracking url: http://localhost:8080/
2014-08-22 20:11:27,629 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:27,629 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:27,632 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:27,633 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local990074852_0007_m_000000_0
2014-08-22 20:11:27,635 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:27,636 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/critics.txt
2014-08-22 20:11:27,637 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@49c68e73
2014-08-22 20:11:27,638 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:27,638 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:27,783 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:27,783 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:27,783 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:27,783 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:27,783 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:27,785 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:27,785 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:27,795 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/critics.txt"]
2014-08-22 20:11:27,796 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(euclidean)[by:[{1}:'movie'][numSelfJoins:1]]
2014-08-22 20:11:27,801 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:27,802 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:27,802 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:27,803 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 1746; bufvoid = 104857600
2014-08-22 20:11:27,803 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214260(104857040); length = 137/6553600
2014-08-22 20:11:27,807 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:27,810 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local990074852_0007_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:27,812 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/critics.txt:0+828
2014-08-22 20:11:27,813 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local990074852_0007_m_000000_0' done.
2014-08-22 20:11:27,813 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local990074852_0007_m_000000_0
2014-08-22 20:11:27,814 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:27,815 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:27,815 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local990074852_0007_r_000000_0
2014-08-22 20:11:27,817 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:27,817 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@6e6e056e
2014-08-22 20:11:27,818 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:27,819 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local990074852_0007_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:27,821 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#7 about to shuffle output of map attempt_local990074852_0007_m_000000_0 decomp: 1818 len: 1822 to MEMORY
2014-08-22 20:11:27,822 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 1818 bytes from map-output for attempt_local990074852_0007_m_000000_0
2014-08-22 20:11:27,822 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 1818, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->1818
2014-08-22 20:11:27,823 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:27,824 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:27,824 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 20:11:27,828 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:27,829 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 20:11:27,831 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 1818 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:27,831 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 1822 bytes from disk
2014-08-22 20:11:27,831 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:27,831 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:27,832 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 20:11:27,832 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:27,833 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:27,833 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:27,842 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: CoGroup(euclidean)[by:[{1}:'movie'][numSelfJoins:1]]
2014-08-22 20:11:27,842 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[['movie', 'name1', 'rate1', 'name2', 'rate2']]"][2526446685/euclidean/]
2014-08-22 20:11:27,851 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(105)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 20:11:27,851 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(110)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 20:11:27,880 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local990074852_0007_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:27,882 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:27,882 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local990074852_0007_r_000000_0 is allowed to commit now
2014-08-22 20:11:27,883 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local990074852_0007_r_000000_0' to file:/tmp/hadoop-teamcity/2526446685_euclidean_A205AC62EE8E4252924D7EA9B193EFD4/_temporary/0/task_local990074852_0007_r_000000
2014-08-22 20:11:27,884 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:27,884 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local990074852_0007_r_000000_0' done.
2014-08-22 20:11:27,884 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local990074852_0007_r_000000_0
2014-08-22 20:11:27,885 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:27,909 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] starting step: (2/3)
2014-08-22 20:11:27,910 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:27,911 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:27,951 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:27,971 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:27,983 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:27,984 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:27,992 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local210669218_0008
2014-08-22 20:11:28,017 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity210669218/.staging/job_local210669218_0008/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:28,018 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity210669218/.staging/job_local210669218_0008/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:28,074 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local210669218_0008/job_local210669218_0008.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:28,075 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local210669218_0008/job_local210669218_0008.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:28,076 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:28,076 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] submitted hadoop job: job_local210669218_0008
2014-08-22 20:11:28,076 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:28,077 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:28,076 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] tracking url: http://localhost:8080/
2014-08-22 20:11:28,079 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:28,079 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local210669218_0008_m_000000_0
2014-08-22 20:11:28,082 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:28,083 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/2526446685_euclidean_A205AC62EE8E4252924D7EA9B193EFD4/part-00000
2014-08-22 20:11:28,083 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@450ae3fb
2014-08-22 20:11:28,085 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:28,086 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:28,229 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:28,229 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:28,229 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:28,229 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:28,230 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:28,231 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:28,231 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:28,241 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[['movie', 'name1', 'rate1', 'name2', 'rate2']]"][2526446685/euclidean/]
2014-08-22 20:11:28,241 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(euclidean)[by:[{?}:ALL]]
2014-08-22 20:11:28,255 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:28,256 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:28,256 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:28,256 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 13104; bufvoid = 104857600
2014-08-22 20:11:28,256 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26213704(104854816); length = 693/6553600
2014-08-22 20:11:28,270 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:28,274 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local210669218_0008_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:28,276 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/2526446685_euclidean_A205AC62EE8E4252924D7EA9B193EFD4/part-00000:0+13816
2014-08-22 20:11:28,276 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local210669218_0008_m_000000_0' done.
2014-08-22 20:11:28,276 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local210669218_0008_m_000000_0
2014-08-22 20:11:28,277 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:28,277 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:28,278 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local210669218_0008_r_000000_0
2014-08-22 20:11:28,280 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:28,281 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@6d232cf2
2014-08-22 20:11:28,281 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:28,284 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local210669218_0008_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:28,292 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#8 about to shuffle output of map attempt_local210669218_0008_m_000000_0 decomp: 13454 len: 13458 to MEMORY
2014-08-22 20:11:28,292 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 13454 bytes from map-output for attempt_local210669218_0008_m_000000_0
2014-08-22 20:11:28,293 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 13454, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->13454
2014-08-22 20:11:28,293 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:28,295 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:28,295 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 20:11:28,297 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:28,298 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 20:11:28,302 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 13454 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:28,302 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 13458 bytes from disk
2014-08-22 20:11:28,302 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:28,302 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:28,303 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 20:11:28,303 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:28,304 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:28,304 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:28,313 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(euclidean)[by:[{?}:ALL]]
2014-08-22 20:11:28,314 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[['movie', 'name1', 'rate1', 'name2', 'rate2', 'score']]"][6702601728/euclidean/]
2014-08-22 20:11:28,347 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local210669218_0008_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:28,349 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:28,349 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local210669218_0008_r_000000_0 is allowed to commit now
2014-08-22 20:11:28,350 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local210669218_0008_r_000000_0' to file:/tmp/hadoop-teamcity/6702601728_euclidean_1DC69937426B4948BB6690B0F5ABCF02/_temporary/0/task_local210669218_0008_r_000000
2014-08-22 20:11:28,352 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:28,352 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local210669218_0008_r_000000_0' done.
2014-08-22 20:11:28,352 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local210669218_0008_r_000000_0
2014-08-22 20:11:28,352 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:28,370 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] starting step: (3/3) ...seplatform/euclidean/long
2014-08-22 20:11:28,371 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:28,372 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:28,410 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:28,432 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:28,443 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:28,443 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:28,449 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local520442614_0009
2014-08-22 20:11:28,468 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity520442614/.staging/job_local520442614_0009/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:28,468 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity520442614/.staging/job_local520442614_0009/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:28,519 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local520442614_0009/job_local520442614_0009.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:28,519 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local520442614_0009/job_local520442614_0009.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:28,521 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:28,521 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] submitted hadoop job: job_local520442614_0009
2014-08-22 20:11:28,521 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:28,521 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] tracking url: http://localhost:8080/
2014-08-22 20:11:28,521 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:28,525 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:28,525 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local520442614_0009_m_000000_0
2014-08-22 20:11:28,527 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:28,529 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/6702601728_euclidean_1DC69937426B4948BB6690B0F5ABCF02/part-00000
2014-08-22 20:11:28,529 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@2073b879
2014-08-22 20:11:28,531 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:28,531 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:28,673 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:28,674 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:28,674 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:28,674 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:28,674 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:28,675 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:28,676 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:28,687 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[['movie', 'name1', 'rate1', 'name2', 'rate2', 'score']]"][6702601728/euclidean/]
2014-08-22 20:11:28,687 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(euclidean)[by:[{2}:'name1', 'name2']]
2014-08-22 20:11:28,696 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:28,697 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:28,697 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:28,697 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 7074; bufvoid = 104857600
2014-08-22 20:11:28,697 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214052(104856208); length = 345/6553600
2014-08-22 20:11:28,703 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:28,706 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local520442614_0009_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:28,708 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/6702601728_euclidean_1DC69937426B4948BB6690B0F5ABCF02/part-00000:0+7726
2014-08-22 20:11:28,708 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local520442614_0009_m_000000_0' done.
2014-08-22 20:11:28,708 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local520442614_0009_m_000000_0
2014-08-22 20:11:28,708 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:28,709 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:28,709 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local520442614_0009_r_000000_0
2014-08-22 20:11:28,711 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:28,711 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@c0dd841
2014-08-22 20:11:28,712 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:28,713 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local520442614_0009_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:28,715 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#9 about to shuffle output of map attempt_local520442614_0009_m_000000_0 decomp: 7250 len: 7254 to MEMORY
2014-08-22 20:11:28,716 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 7250 bytes from map-output for attempt_local520442614_0009_m_000000_0
2014-08-22 20:11:28,716 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 7250, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->7250
2014-08-22 20:11:28,717 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:28,718 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:28,718 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 20:11:28,720 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:28,721 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 20:11:28,723 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 7250 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:28,724 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 7254 bytes from disk
2014-08-22 20:11:28,724 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:28,724 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:28,725 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 20:11:28,725 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:28,725 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:28,726 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:28,736 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(euclidean)[by:[{2}:'name1', 'name2']]
2014-08-22 20:11:28,736 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/long"]
2014-08-22 20:11:28,755 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local520442614_0009_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:28,757 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:28,757 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local520442614_0009_r_000000_0 is allowed to commit now
2014-08-22 20:11:28,758 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local520442614_0009_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/long/_temporary/0/task_local520442614_0009_r_000000
2014-08-22 20:11:28,759 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:28,760 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local520442614_0009_r_000000_0' done.
2014-08-22 20:11:28,760 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local520442614_0009_r_000000_0
2014-08-22 20:11:28,761 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:28,783 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/long/_temporary
2014-08-22 20:11:28,818 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:28,855 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:28,857 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output//hadoop2-mr1/distanceusecaseplatform/euclidean/long
2014-08-22 20:11:28,884 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:11:28,884 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 20:11:28,911 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:28,914 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:28,933 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:11:28,943 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] starting
2014-08-22 20:11:28,944 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/critics.txt"]
2014-08-22 20:11:28,944 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/short"]
2014-08-22 20:11:28,944 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] parallel execution is enabled: false
2014-08-22 20:11:28,944 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] starting jobs: 3
2014-08-22 20:11:28,944 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [euclidean] allocating threads: 1
2014-08-22 20:11:28,946 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] starting step: (1/3)
2014-08-22 20:11:28,947 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:28,948 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:28,975 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:28,996 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:29,018 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1466551523_0010
2014-08-22 20:11:29,042 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1466551523/.staging/job_local1466551523_0010/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:29,042 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1466551523/.staging/job_local1466551523_0010/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:29,111 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1466551523_0010/job_local1466551523_0010.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:29,111 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1466551523_0010/job_local1466551523_0010.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:29,113 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:29,113 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:29,114 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:29,114 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] submitted hadoop job: job_local1466551523_0010
2014-08-22 20:11:29,114 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] tracking url: http://localhost:8080/
2014-08-22 20:11:29,116 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:29,117 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1466551523_0010_m_000000_0
2014-08-22 20:11:29,119 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:29,120 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/critics.txt
2014-08-22 20:11:29,121 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@79f1e0e0
2014-08-22 20:11:29,122 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:29,122 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:29,427 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:29,427 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:29,427 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:29,427 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:29,427 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:29,429 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:29,429 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:29,438 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/critics.txt"]
2014-08-22 20:11:29,438 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(euclidean)[by:[{1}:'movie'][numSelfJoins:1]]
2014-08-22 20:11:29,444 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:29,444 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:29,444 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:29,444 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 1746; bufvoid = 104857600
2014-08-22 20:11:29,444 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214260(104857040); length = 137/6553600
2014-08-22 20:11:29,448 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:29,450 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1466551523_0010_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:29,452 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/critics.txt:0+828
2014-08-22 20:11:29,452 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1466551523_0010_m_000000_0' done.
2014-08-22 20:11:29,453 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1466551523_0010_m_000000_0
2014-08-22 20:11:29,453 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:29,453 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:29,454 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1466551523_0010_r_000000_0
2014-08-22 20:11:29,456 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:29,456 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@47abfd68
2014-08-22 20:11:29,457 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:29,458 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1466551523_0010_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:29,460 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#10 about to shuffle output of map attempt_local1466551523_0010_m_000000_0 decomp: 1818 len: 1822 to MEMORY
2014-08-22 20:11:29,460 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 1818 bytes from map-output for attempt_local1466551523_0010_m_000000_0
2014-08-22 20:11:29,461 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 1818, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->1818
2014-08-22 20:11:29,461 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:29,462 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:29,462 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 20:11:29,465 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:29,465 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 20:11:29,467 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 1818 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:29,468 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 1822 bytes from disk
2014-08-22 20:11:29,468 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:29,468 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:29,468 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 20:11:29,469 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:29,469 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:29,470 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:29,478 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: CoGroup(euclidean)[by:[{1}:'movie'][numSelfJoins:1]]
2014-08-22 20:11:29,478 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[['movie', 'name1', 'rate1', 'name2', 'rate2']]"][9531794893/euclidean/]
2014-08-22 20:11:29,487 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(105)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 20:11:29,487 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(110)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 20:11:29,514 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1466551523_0010_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:29,516 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:29,516 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1466551523_0010_r_000000_0 is allowed to commit now
2014-08-22 20:11:29,517 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1466551523_0010_r_000000_0' to file:/tmp/hadoop-teamcity/9531794893_euclidean_9DCF79EC961E45C5A522A93825B8CDC4/_temporary/0/task_local1466551523_0010_r_000000
2014-08-22 20:11:29,518 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:29,519 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1466551523_0010_r_000000_0' done.
2014-08-22 20:11:29,519 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1466551523_0010_r_000000_0
2014-08-22 20:11:29,519 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:29,542 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] starting step: (2/3)
2014-08-22 20:11:29,544 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:29,545 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:29,584 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:29,605 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:29,616 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:29,616 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:29,621 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local833390231_0011
2014-08-22 20:11:29,641 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity833390231/.staging/job_local833390231_0011/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:29,641 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity833390231/.staging/job_local833390231_0011/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:29,692 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local833390231_0011/job_local833390231_0011.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:29,692 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local833390231_0011/job_local833390231_0011.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:29,694 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:29,694 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:29,694 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:29,694 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] submitted hadoop job: job_local833390231_0011
2014-08-22 20:11:29,695 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] tracking url: http://localhost:8080/
2014-08-22 20:11:29,697 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:29,697 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local833390231_0011_m_000000_0
2014-08-22 20:11:29,699 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:29,700 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/9531794893_euclidean_9DCF79EC961E45C5A522A93825B8CDC4/part-00000
2014-08-22 20:11:29,700 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@1e9f9761
2014-08-22 20:11:29,702 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:29,702 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:29,844 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:29,844 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:29,844 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:29,845 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:29,845 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:29,846 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:29,846 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:29,855 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[['movie', 'name1', 'rate1', 'name2', 'rate2']]"][9531794893/euclidean/]
2014-08-22 20:11:29,855 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(euclidean)[by:[{?}:ALL]]
2014-08-22 20:11:29,868 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:29,869 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:29,869 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:29,869 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 13104; bufvoid = 104857600
2014-08-22 20:11:29,869 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26213704(104854816); length = 693/6553600
2014-08-22 20:11:29,877 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:29,879 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local833390231_0011_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:29,881 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/9531794893_euclidean_9DCF79EC961E45C5A522A93825B8CDC4/part-00000:0+13816
2014-08-22 20:11:29,881 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local833390231_0011_m_000000_0' done.
2014-08-22 20:11:29,881 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local833390231_0011_m_000000_0
2014-08-22 20:11:29,881 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:29,882 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:29,882 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local833390231_0011_r_000000_0
2014-08-22 20:11:29,884 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:29,884 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@3c7a279c
2014-08-22 20:11:29,885 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:29,886 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local833390231_0011_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:29,888 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#11 about to shuffle output of map attempt_local833390231_0011_m_000000_0 decomp: 13454 len: 13458 to MEMORY
2014-08-22 20:11:29,888 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 13454 bytes from map-output for attempt_local833390231_0011_m_000000_0
2014-08-22 20:11:29,888 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 13454, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->13454
2014-08-22 20:11:29,889 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:29,890 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:29,890 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 20:11:29,892 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:29,893 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 20:11:29,898 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 13454 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:29,898 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 13458 bytes from disk
2014-08-22 20:11:29,898 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:29,898 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:29,899 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 20:11:29,899 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:29,900 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:29,900 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:29,909 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(euclidean)[by:[{?}:ALL]]
2014-08-22 20:11:29,909 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[['movie', 'name1', 'rate1', 'name2', 'rate2', 'score']]"][3663815457/euclidean/]
2014-08-22 20:11:29,940 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local833390231_0011_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:29,942 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:29,942 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local833390231_0011_r_000000_0 is allowed to commit now
2014-08-22 20:11:29,943 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local833390231_0011_r_000000_0' to file:/tmp/hadoop-teamcity/3663815457_euclidean_08137B5DCE544EFB9C62B0E55F673D54/_temporary/0/task_local833390231_0011_r_000000
2014-08-22 20:11:29,944 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:29,944 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local833390231_0011_r_000000_0' done.
2014-08-22 20:11:29,944 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local833390231_0011_r_000000_0
2014-08-22 20:11:29,944 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:29,966 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] starting step: (3/3) ...eplatform/euclidean/short
2014-08-22 20:11:29,966 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:29,967 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:30,003 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:30,023 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:30,033 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:30,033 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:30,039 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local107954054_0012
2014-08-22 20:11:30,060 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity107954054/.staging/job_local107954054_0012/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:30,061 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity107954054/.staging/job_local107954054_0012/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:30,120 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local107954054_0012/job_local107954054_0012.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:30,121 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local107954054_0012/job_local107954054_0012.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:30,123 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:30,123 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] submitted hadoop job: job_local107954054_0012
2014-08-22 20:11:30,123 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:30,123 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [euclidean] tracking url: http://localhost:8080/
2014-08-22 20:11:30,124 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:30,127 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:30,127 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local107954054_0012_m_000000_0
2014-08-22 20:11:30,129 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:30,131 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/3663815457_euclidean_08137B5DCE544EFB9C62B0E55F673D54/part-00000
2014-08-22 20:11:30,131 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@570c16b7
2014-08-22 20:11:30,133 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:30,134 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:30,275 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:30,275 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:30,275 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:30,276 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:30,276 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:30,277 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:30,277 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:30,289 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[['movie', 'name1', 'rate1', 'name2', 'rate2', 'score']]"][3663815457/euclidean/]
2014-08-22 20:11:30,289 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(euclidean)[by:[{2}:'name1', 'name2']]
2014-08-22 20:11:30,297 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:30,297 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:30,297 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:30,298 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 7074; bufvoid = 104857600
2014-08-22 20:11:30,298 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214052(104856208); length = 345/6553600
2014-08-22 20:11:30,303 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:30,305 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local107954054_0012_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:30,308 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/3663815457_euclidean_08137B5DCE544EFB9C62B0E55F673D54/part-00000:0+7726
2014-08-22 20:11:30,308 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local107954054_0012_m_000000_0' done.
2014-08-22 20:11:30,308 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local107954054_0012_m_000000_0
2014-08-22 20:11:30,308 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:30,309 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:30,309 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local107954054_0012_r_000000_0
2014-08-22 20:11:30,311 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:30,312 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@5dcdd76a
2014-08-22 20:11:30,312 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:30,313 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local107954054_0012_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:30,315 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#12 about to shuffle output of map attempt_local107954054_0012_m_000000_0 decomp: 7250 len: 7254 to MEMORY
2014-08-22 20:11:30,316 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 7250 bytes from map-output for attempt_local107954054_0012_m_000000_0
2014-08-22 20:11:30,316 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 7250, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->7250
2014-08-22 20:11:30,317 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:30,319 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:30,319 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 20:11:30,322 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:30,322 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 20:11:30,325 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 7250 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:30,325 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 7254 bytes from disk
2014-08-22 20:11:30,326 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:30,326 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:30,326 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 20:11:30,327 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:30,327 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:30,327 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:30,337 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(euclidean)[by:[{2}:'name1', 'name2']]
2014-08-22 20:11:30,337 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/short"]
2014-08-22 20:11:30,356 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local107954054_0012_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:30,358 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:30,358 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local107954054_0012_r_000000_0 is allowed to commit now
2014-08-22 20:11:30,359 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local107954054_0012_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/short/_temporary/0/task_local107954054_0012_r_000000
2014-08-22 20:11:30,360 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:30,360 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local107954054_0012_r_000000_0' done.
2014-08-22 20:11:30,360 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local107954054_0012_r_000000_0
2014-08-22 20:11:30,361 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:30,387 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/distanceusecaseplatform/euclidean/short/_temporary
2014-08-22 20:11:30,425 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:30,471 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:30,473 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output//hadoop2-mr1/distanceusecaseplatform/euclidean/short