Class cascading.DistanceUseCasePlatformTest

4

tests

0

failures

9.442s

duration

100%

successful

Tests

Test Duration Result
testEuclideanDistance 1.483s passed
testEuclideanDistanceComposite 4.509s passed
testEuclideanDistanceShort 1.616s passed
testPearsonDistanceComposite 1.834s passed

Standard output

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