Hi,
I was wondering if anyone could assist with a question relating to very slow performance of "terasort" on a brand new CDH 5.6.0 cluster ?
1) Running "teragen" take about 15 minutes for a 100GB file:
2) Running "terasort" takes 85+ minutes:
Lots of similar looping log file entries as per below. I hit "<ctrl> + c" to kill the terasort.
Has anyone experienced a similar slow issue on CDH 5.6.0 ?
Perhaps there are some MapReduce or YARN parameters I can look at that might speed things up ?
$ time hadoop jar /opt/cloudera/parcels/CDH/lib/hadoop-0.20-mapreduce/hadoop-examples.jar terasort /benchmarks/teragen-100gb-test-3 /benchmarks/terasort
....
....
16/04/04 09:32:48 INFO mapred.MapTask: Starting flush of map output
16/04/04 09:32:48 INFO mapred.MapTask: Spilling map output
16/04/04 09:32:48 INFO mapred.MapTask: bufstart = 75355282; bufend = 34888038; bufvoid = 104857600
16/04/04 09:32:48 INFO mapred.MapTask: kvstart = 18838816(75355264); kvend = 16313708(65254832); length = 2525109/6553600
16/04/04 09:32:49 INFO mapred.MapTask: Finished spill 1
16/04/04 09:32:49 INFO mapred.Merger: Merging 2 sorted segments
16/04/04 09:32:49 INFO mapred.Merger: Down to the last merge-pass, with 2 segments left of total size: 139586394 bytes
16/04/04 09:32:51 INFO mapred.LocalJobRunner: map > sort >
16/04/04 09:32:52 INFO mapred.Task: Task:attempt_local1770220147_0001_m_000742_0 is done. And is in the process of committing
16/04/04 09:32:52 INFO mapred.LocalJobRunner: map > sort
16/04/04 09:32:52 INFO mapred.Task: Task 'attempt_local1770220147_0001_m_000742_0' done.
16/04/04 09:32:52 INFO mapred.LocalJobRunner: Finishing task: attempt_local1770220147_0001_m_000742_0
16/04/04 09:32:52 INFO mapred.LocalJobRunner: Starting task: attempt_local1770220147_0001_m_000743_0
16/04/04 09:32:52 INFO output.FileOutputCommitter: File Output Committer Algorithm version is 1
16/04/04 09:32:52 INFO mapred.Task: Using ResourceCalculatorProcessTree : [ ]
16/04/04 09:32:52 INFO mapred.MapTask: Processing split: hdfs://{obfuscated}/benchmarks/teragen-100gb-test-3/part-m-00000:939524096+134217728
16/04/04 09:32:52 INFO mapred.MapTask: (EQUATOR) 0 kvi 26214396(104857584)
16/04/04 09:32:52 INFO mapred.MapTask: mapreduce.task.io.sort.mb: 100
16/04/04 09:32:52 INFO mapred.MapTask: soft limit at 83886080
16/04/04 09:32:52 INFO mapred.MapTask: bufstart = 0; bufvoid = 104857600
16/04/04 09:32:52 INFO mapred.MapTask: kvstart = 26214396; length = 6553600
16/04/04 09:32:52 INFO mapred.MapTask: Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
16/04/04 09:32:52 INFO mapred.MapTask: Spilling map output
16/04/04 09:32:52 INFO mapred.MapTask: bufstart = 0; bufend = 72511698; bufvoid = 104857600
16/04/04 09:32:52 INFO mapred.MapTask: kvstart = 26214396(104857584); kvend = 23370804(93483216); length = 2843593/6553600
16/04/04 09:32:52 INFO mapred.MapTask: (EQUATOR) 75355282 kvi 18838816(75355264)
16/04/04 09:32:54 INFO mapred.MapTask: Finished spill 0
16/04/04 09:32:54 INFO mapred.MapTask: (RESET) equator 75355282 kv 18838816(75355264) kvi 18127932(72511728)
16/04/04 09:32:55 INFO mapred.LocalJobRunner:
16/04/04 09:32:55 INFO mapred.MapTask: Starting flush of map output
16/04/04 09:32:55 INFO mapred.MapTask: Spilling map output
16/04/04 09:32:55 INFO mapred.MapTask: bufstart = 75355282; bufend = 34888140; bufvoid = 104857600
16/04/04 09:32:55 INFO mapred.MapTask: kvstart = 18838816(75355264); kvend = 16313704(65254816); length = 2525113/6553600
16/04/04 09:32:56 INFO mapred.MapTask: Finished spill 1
16/04/04 09:32:56 INFO mapred.Merger: Merging 2 sorted segments
16/04/04 09:32:56 INFO mapred.Merger: Down to the last merge-pass, with 2 segments left of total size: 139586498 bytes
16/04/04 09:32:58 INFO mapred.LocalJobRunner: map > sort >
16/04/04 09:32:59 INFO mapred.Task: Task:attempt_local1770220147_0001_m_000743_0 is done. And is in the process of committing
16/04/04 09:32:59 INFO mapred.LocalJobRunner: map > sort
16/04/04 09:32:59 INFO mapred.Task: Task 'attempt_local1770220147_0001_m_000743_0' done.
16/04/04 09:32:59 INFO mapred.LocalJobRunner: Finishing task: attempt_local1770220147_0001_m_000743_0
16/04/04 09:32:59 INFO mapred.LocalJobRunner: Starting task: attempt_local1770220147_0001_m_000744_0
16/04/04 09:32:59 INFO output.FileOutputCommitter: File Output Committer Algorithm version is 1
16/04/04 09:32:59 INFO mapred.Task: Using ResourceCalculatorProcessTree : [ ]
16/04/04 09:32:59 INFO mapred.MapTask: Processing split: hdfs://{obfuscated}/benchmarks/teragen-100gb-test-3/part-m-00000:805306368+134217728
16/04/04 09:32:59 INFO mapred.MapTask: (EQUATOR) 0 kvi 26214396(104857584)
16/04/04 09:32:59 INFO mapred.MapTask: mapreduce.task.io.sort.mb: 100
16/04/04 09:32:59 INFO mapred.MapTask: soft limit at 83886080
16/04/04 09:32:59 INFO mapred.MapTask: bufstart = 0; bufvoid = 104857600
16/04/04 09:32:59 INFO mapred.MapTask: kvstart = 26214396; length = 6553600
16/04/04 09:32:59 INFO mapred.MapTask: Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
16/04/04 09:32:59 INFO mapred.MapTask: Spilling map output
16/04/04 09:32:59 INFO mapred.MapTask: bufstart = 0; bufend = 72511698; bufvoid = 104857600
16/04/04 09:32:59 INFO mapred.MapTask: kvstart = 26214396(104857584); kvend = 23370804(93483216); length = 2843593/6553600
16/04/04 09:32:59 INFO mapred.MapTask: (EQUATOR) 75355282 kvi 18838816(75355264)
16/04/04 09:33:01 INFO mapred.MapTask: Finished spill 0
16/04/04 09:33:01 INFO mapred.MapTask: (RESET) equator 75355282 kv 18838816(75355264) kvi 18127932(72511728)
16/04/04 09:33:02 INFO mapred.LocalJobRunner:
16/04/04 09:33:02 INFO mapred.MapTask: Starting flush of map output
16/04/04 09:33:02 INFO mapred.MapTask: Spilling map output
16/04/04 09:33:02 INFO mapred.MapTask: bufstart = 75355282; bufend = 34888038; bufvoid = 104857600
16/04/04 09:33:02 INFO mapred.MapTask: kvstart = 18838816(75355264); kvend = 16313708(65254832); length = 2525109/6553600
16/04/04 09:33:03 INFO mapred.MapTask: Finished spill 1
16/04/04 09:33:03 INFO mapred.Merger: Merging 2 sorted segments
16/04/04 09:33:03 INFO mapred.Merger: Down to the last merge-pass, with 2 segments left of total size: 139586394 bytes
16/04/04 09:33:05 INFO mapred.LocalJobRunner: map > sort >
16/04/04 09:33:05 INFO mapred.Task: Task:attempt_local1770220147_0001_m_000744_0 is done. And is in the process of committing
16/04/04 09:33:05 INFO mapred.LocalJobRunner: map > sort
16/04/04 09:33:05 INFO mapred.Task: Task 'attempt_local1770220147_0001_m_000744_0' done.
16/04/04 09:33:05 INFO mapred.LocalJobRunner: Finishing task: attempt_local1770220147_0001_m_000744_0
16/04/04 09:33:05 INFO mapred.LocalJobRunner: map task executor complete.
16/04/04 09:33:05 INFO mapred.LocalJobRunner: Waiting for reduce tasks
16/04/04 09:33:05 INFO mapred.LocalJobRunner: Starting task: attempt_local1770220147_0001_r_000000_0
16/04/04 09:33:05 INFO output.FileOutputCommitter: File Output Committer Algorithm version is 1
16/04/04 09:33:05 INFO mapred.Task: Using ResourceCalculatorProcessTree : [ ]
16/04/04 09:33:05 INFO mapred.ReduceTask: Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@3d467064
16/04/04 09:33:05 INFO reduce.MergeManagerImpl: MergerManager: memoryLimit=180197776, maxSingleShuffleLimit=45049444, mergeThreshold=118930536, ioSortFactor=10, memToMemMergeOutputsThreshold=10
16/04/04 09:33:05 INFO reduce.EventFetcher: attempt_local1770220147_0001_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
16/04/04 09:33:05 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000315_0: Shuffling to disk since 139586514 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:05 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000315_0 decomp: 139586514 len: 139586518 to DISK
16/04/04 09:33:07 INFO reduce.OnDiskMapOutput: Read 139586518 bytes from map-output for attempt_local1770220147_0001_m_000315_0
16/04/04 09:33:07 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000143_0: Shuffling to disk since 139586514 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:07 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000143_0 decomp: 139586514 len: 139586518 to DISK
16/04/04 09:33:08 INFO reduce.OnDiskMapOutput: Read 139586518 bytes from map-output for attempt_local1770220147_0001_m_000143_0
16/04/04 09:33:08 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000535_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:08 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000535_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:08 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000535_0
16/04/04 09:33:08 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000704_0: Shuffling to disk since 139586514 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:08 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000704_0 decomp: 139586514 len: 139586518 to DISK
16/04/04 09:33:09 INFO reduce.OnDiskMapOutput: Read 139586518 bytes from map-output for attempt_local1770220147_0001_m_000704_0
16/04/04 09:33:09 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000142_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:09 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000142_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:09 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000142_0
16/04/04 09:33:09 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000534_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:09 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000534_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:10 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000534_0
16/04/04 09:33:10 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000705_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:10 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000705_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:10 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000705_0
16/04/04 09:33:10 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000316_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:10 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000316_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:11 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000316_0
16/04/04 09:33:11 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000702_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:11 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000702_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:11 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000702_0
16/04/04 09:33:11 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000317_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:11 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000317_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:11 INFO mapred.LocalJobRunner: reduce > copy task(attempt_local1770220147_0001_m_000702_0 succeeded at 133119.98 MB/s) Aggregated copy rate(9 of 745 at 1198080.12 MB/s)
16/04/04 09:33:12 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000317_0
16/04/04 09:33:12 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000145_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:12 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000145_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:13 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000145_0
16/04/04 09:33:13 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000703_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:13 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000703_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:13 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000703_0
16/04/04 09:33:13 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000533_0: Shuffling to disk since 139586514 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:13 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000533_0 decomp: 139586514 len: 139586518 to DISK
16/04/04 09:33:14 INFO reduce.OnDiskMapOutput: Read 139586518 bytes from map-output for attempt_local1770220147_0001_m_000533_0
16/04/04 09:33:14 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000144_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:14 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000144_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:14 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000144_0
16/04/04 09:33:14 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000538_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:14 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000538_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:14 INFO mapred.LocalJobRunner: reduce > copy task(attempt_local1770220147_0001_m_000144_0 succeeded at 133119.98 MB/s) Aggregated copy rate(14 of 745 at 1863680.00 MB/s)
16/04/04 09:33:15 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000538_0
16/04/04 09:33:15 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000146_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:15 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000146_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:15 INFO mapreduce.Job: map 100% reduce 1%
16/04/04 09:33:15 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000146_0
16/04/04 09:33:15 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000318_0: Shuffling to disk since 139586514 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:15 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000318_0 decomp: 139586514 len: 139586518 to DISK
16/04/04 09:33:16 INFO reduce.OnDiskMapOutput: Read 139586518 bytes from map-output for attempt_local1770220147_0001_m_000318_0
16/04/04 09:33:16 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000701_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:16 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000701_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:17 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000701_0
16/04/04 09:33:17 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000319_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:17 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000319_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:17 INFO mapred.LocalJobRunner: reduce > copy task(attempt_local1770220147_0001_m_000701_0 succeeded at 133119.98 MB/s) Aggregated copy rate(18 of 745 at 2396160.25 MB/s)
16/04/04 09:33:18 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000319_0
16/04/04 09:33:18 INFO reduce.MergeThread: OnDiskMerger - Thread to merge on-disk map-outputs: Starting merge with 10 segments, while ignoring 9 segments
16/04/04 09:33:18 INFO Configuration.deprecation: io.bytes.per.checksum is deprecated. Instead, use dfs.bytes-per-checksum
16/04/04 09:33:18 INFO reduce.MergeManagerImpl: OnDiskMerger: We have 10 map outputs on disk. Triggering merge...
16/04/04 09:33:18 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000699_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:18 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000699_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:18 INFO mapred.Merger: Merging 10 sorted segments
16/04/04 09:33:18 INFO mapred.Merger: Down to the last merge-pass, with 10 segments left of total size: 1395863970 bytes
16/04/04 09:33:19 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000699_0
16/04/04 09:33:19 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000148_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:19 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000148_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:19 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000148_0
16/04/04 09:33:19 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000320_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:19 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000320_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:20 INFO mapred.LocalJobRunner: reduce > copy task(attempt_local1770220147_0001_m_000148_0 succeeded at 133119.98 MB/s) Aggregated copy rate(21 of 745 at 2795520.00 MB/s)
16/04/04 09:33:20 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000320_0
16/04/04 09:33:20 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000537_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:20 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000537_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:21 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000537_0
16/04/04 09:33:21 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000147_0: Shuffling to disk since 139586514 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:21 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000147_0 decomp: 139586514 len: 139586518 to DISK
16/04/04 09:33:22 INFO reduce.OnDiskMapOutput: Read 139586518 bytes from map-output for attempt_local1770220147_0001_m_000147_0
16/04/04 09:33:22 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000536_0: Shuffling to disk since 139586514 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:22 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000536_0 decomp: 139586514 len: 139586518 to DISK
16/04/04 09:33:22 INFO reduce.OnDiskMapOutput: Read 139586518 bytes from map-output for attempt_local1770220147_0001_m_000536_0
16/04/04 09:33:22 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000700_0: Shuffling to disk since 139586514 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:22 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000700_0 decomp: 139586514 len: 139586518 to DISK
16/04/04 09:33:22 INFO reduce.OnDiskMapOutput: Read 139586518 bytes from map-output for attempt_local1770220147_0001_m_000700_0
16/04/04 09:33:22 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000321_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:22 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000321_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:23 INFO mapred.LocalJobRunner: reduce > copy task(attempt_local1770220147_0001_m_000700_0 succeeded at 133120.08 MB/s) Aggregated copy rate(26 of 745 at 3461120.00 MB/s)
16/04/04 09:33:24 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000321_0
16/04/04 09:33:24 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000309_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:24 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000309_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:25 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000309_0
16/04/04 09:33:25 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000529_0: Shuffling to disk since 139586514 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:25 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000529_0 decomp: 139586514 len: 139586518 to DISK
16/04/04 09:33:25 INFO reduce.OnDiskMapOutput: Read 139586518 bytes from map-output for attempt_local1770220147_0001_m_000529_0
16/04/04 09:33:25 INFO reduce.MergeThread: OnDiskMerger - Thread to merge on-disk map-outputs: Starting merge with 10 segments, while ignoring 9 segments
16/04/04 09:33:25 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000149_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:25 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000149_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:26 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000149_0
16/04/04 09:33:26 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000528_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:26 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000528_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:26 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000528_0
16/04/04 09:33:26 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000698_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:26 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000698_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:26 INFO mapred.LocalJobRunner: reduce > copy task(attempt_local1770220147_0001_m_000528_0 succeeded at 133119.98 MB/s) Aggregated copy rate(31 of 745 at 4126720.25 MB/s)
16/04/04 09:33:27 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000698_0
16/04/04 09:33:27 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000696_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:27 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000696_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:27 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000696_0
16/04/04 09:33:27 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000151_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:27 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000151_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:28 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000151_0
16/04/04 09:33:28 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000527_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:28 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000527_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:28 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000527_0
16/04/04 09:33:28 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000310_0: Shuffling to disk since 139586410 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:28 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000310_0 decomp: 139586410 len: 139586414 to DISK
16/04/04 09:33:29 INFO mapred.LocalJobRunner: reduce > copy task(attempt_local1770220147_0001_m_000527_0 succeeded at 133119.98 MB/s) Aggregated copy rate(35 of 745 at 4659200.00 MB/s)
16/04/04 09:33:30 INFO mapreduce.Job: map 100% reduce 2%
16/04/04 09:33:30 INFO reduce.OnDiskMapOutput: Read 139586414 bytes from map-output for attempt_local1770220147_0001_m_000310_0
16/04/04 09:33:30 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000697_0: Shuffling to disk since 139586514 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:30 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000697_0 decomp: 139586514 len: 139586518 to DISK
16/04/04 09:33:31 INFO reduce.OnDiskMapOutput: Read 139586518 bytes from map-output for attempt_local1770220147_0001_m_000697_0
16/04/04 09:33:31 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_m_000311_0: Shuffling to disk since 139586514 is greater than maxSingleShuffleLimit (45049444)
16/04/04 09:33:31 INFO reduce.LocalFetcher: localfetcher#1 about to shuffle output of map attempt_local1770220147_0001_m_000311_0 decomp: 139586514 len: 139586518 to DISK
16/04/04 09:33:32 INFO mapred.LocalJobRunner: reduce > copy task(attempt_local1770220147_0001_m_000697_0 succeeded at 133120.08 MB/s) Aggregated copy rate(37 of 745 at 4925440.00 MB/s)
16/04/04 09:33:35 INFO mapred.LocalJobRunner: reduce > copy task(attempt_local1770220147_0001_m_000697_0 succeeded at 133120.08 MB/s) Aggregated copy rate(37 of 745 at 4925440.00 MB/s)
16/04/04 09:33:38 INFO mapred.LocalJobRunner: reduce > copy task(attempt_local1770220147_0001_m_000697_0 succeeded at 133120.08 MB/s) Aggregated copy rate(37 of 745 at 4925440.00 MB/s)
16/04/04 09:33:39 INFO reduce.MergeManagerImpl: attempt_local1770220147_0001_r_000000_0 Finished merging 10 map output files on disk of total-size 1406769340. Local output file is /tmp/hadoop-hdfs/mapred/local/localRunner/hdfs/jobcache/job_local1770220147_0001/attempt_local1770220147_0001_r_000000_0/tmp/hadoop-hdfs/mapred/local/localRunner/hdfs/jobcache/job_local1770220147_0001/attempt_local1770220147_0001_r_000000_0/output/map_142.out.merged of size 1395864086
16/04/04 09:33:39 INFO reduce.MergeManagerImpl: OnDiskMerger: We have 10 map outputs on disk. Triggering merge...
16/04/04 09:33:39 INFO mapred.Merger: Merging 10 sorted segments
16/04/04 09:33:39 INFO mapred.Merger: Down to the last merge-pass, with 10 segments left of total size: 1395863970 bytes
16/04/04 09:33:41 INFO mapred.LocalJobRunner: reduce > copy task(attempt_local1770220147_0001_m_000697_0 succeeded at 133120.08 MB/s) Aggregated copy rate(37 of 745 at 4925440.00 MB/s)
^C
real 86m 6.353s
user 126m 44.561s
sys 7m 38.514s
Regards,
Damion.