Running "terasort" on brand new CDH 5.6.0 Cluster is very very slow

ozzielabrat — Fri, 16 Sep 2022 10:12:11 GMT

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:

$  time hadoop jar /opt/cloudera/parcels/CDH/lib/hadoop-0.20-mapreduce/hadoop-examples.jar teragen 1000000000 /benchmarks/teragen-100gb-test-3

      16/04/04 08:05:13 INFO mapreduce.Job: Counters: 24
       File System Counters
       FILE: Number of bytes read=276326
       FILE: Number of bytes written=550410
       FILE: Number of read operations=0
       FILE: Number of large read operations=0
       FILE: Number of write operations=0
       HDFS: Number of bytes read=0
       HDFS: Number of bytes written=100000000000
       HDFS: Number of read operations=4
       HDFS: Number of large read operations=0
       HDFS: Number of write operations=3
       Map-Reduce Framework
       Map input records=1000000000
       Map output records=1000000000
       Input split bytes=83
       Spilled Records=0
       Failed Shuffles=0
       Merged Map outputs=0
       GC time elapsed (ms)=8211
       CPU time spent (ms)=0
       Physical memory (bytes) snapshot=0
       Virtual memory (bytes) snapshot=0
       Total committed heap usage (bytes)=261619712
       org.apache.hadoop.examples.terasort.TeraGen$Counters
       CHECKSUM=2147523228284173905
       File Input Format Counters 
       Bytes Read=0
       File Output Format Counters 
       Bytes Written=100000000000

      real 15m 0.469s
      user 17m 35.634s
      sys 0m 46.904s

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.

question Re: Running "terasort" on brand new CDH 5.6.0 Cluster is very very slow in Archives of Support Questions (Read Only)

Running "terasort" on brand new CDH 5.6.0 Cluster is very very slow

Re: Running "terasort" on brand new CDH 5.6.0 Cluster is very very slow

Re: Running "terasort" on brand new CDH 5.6.0 Cluster is very very slow

Re: Running "terasort" on brand new CDH 5.6.0 Cluster is very very slow