You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@hadoop.apache.org by Clay McDonald <st...@bateswhite.com> on 2014/04/22 14:20:21 UTC
MapReduce Stuck

Any direction for troubleshooting this would be helpful.

[cid:image001.png@01CF5E03.8C7F2790]
Container logs look like this and all stop on 4/18.


2014-04-17 07:40:07,547 WARN [main] org.apache.hadoop.conf.Configuration: job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval;  Ignoring.
2014-04-17 07:40:07,603 WARN [main] org.apache.hadoop.conf.Configuration: job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts;  Ignoring.
2014-04-17 07:40:07,877 INFO [main] org.apache.hadoop.metrics2.impl.MetricsConfig: loaded properties from hadoop-metrics2.properties
2014-04-17 07:40:07,950 INFO [main] org.apache.hadoop.metrics2.impl.MetricsSinkAdapter: Sink ganglia started
2014-04-17 07:40:08,052 INFO [main] org.apache.hadoop.metrics2.impl.MetricsSystemImpl: Scheduled snapshot period at 10 second(s).
2014-04-17 07:40:08,052 INFO [main] org.apache.hadoop.metrics2.impl.MetricsSystemImpl: ReduceTask metrics system started
2014-04-17 07:40:08,063 INFO [main] org.apache.hadoop.mapred.YarnChild: Executing with tokens:
2014-04-17 07:40:08,063 INFO [main] org.apache.hadoop.mapred.YarnChild: Kind: mapreduce.job, Service: job_1397649276980_0001, Ident: (org.apache.hadoop.mapreduce.security.token.JobTokenIdentifier@29f01a29)
2014-04-17 07:40:08,238 INFO [main] org.apache.hadoop.mapred.YarnChild: Sleeping for 0ms before retrying again. Got null now.
2014-04-17 07:40:08,720 WARN [main] org.apache.hadoop.conf.Configuration: job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval;  Ignoring.
2014-04-17 07:40:08,751 WARN [main] org.apache.hadoop.conf.Configuration: job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts;  Ignoring.
2014-04-17 07:40:08,874 INFO [main] org.apache.hadoop.mapred.YarnChild: mapreduce.cluster.local.dir for child: /data/1/hadoop/yarn/local/usercache/root/appcache/application_1397649276980_0001,/data/2/hadoop/yarn/local/usercache/root/appcache/application_1397649276980_0001
2014-04-17 07:40:09,060 WARN [main] org.apache.hadoop.conf.Configuration: job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval;  Ignoring.
2014-04-17 07:40:09,066 WARN [main] org.apache.hadoop.conf.Configuration: job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts;  Ignoring.
2014-04-17 07:40:09,155 INFO [main] org.apache.hadoop.conf.Configuration.deprecation: mapred.task.id is deprecated. Instead, use mapreduce.task.attempt.id
2014-04-17 07:40:09,155 INFO [main] org.apache.hadoop.conf.Configuration.deprecation: mapred.task.is.map is deprecated. Instead, use mapreduce.task.ismap
2014-04-17 07:40:09,157 INFO [main] org.apache.hadoop.conf.Configuration.deprecation: mapred.local.dir is deprecated. Instead, use mapreduce.cluster.local.dir
2014-04-17 07:40:09,157 INFO [main] org.apache.hadoop.conf.Configuration.deprecation: mapred.map.tasks is deprecated. Instead, use mapreduce.job.maps
2014-04-17 07:40:09,157 INFO [main] org.apache.hadoop.conf.Configuration.deprecation: mapred.cache.localFiles is deprecated. Instead, use mapreduce.job.cache.local.files
2014-04-17 07:40:09,157 INFO [main] org.apache.hadoop.conf.Configuration.deprecation: mapred.job.id is deprecated. Instead, use mapreduce.job.id
2014-04-17 07:40:09,158 INFO [main] org.apache.hadoop.conf.Configuration.deprecation: mapred.tip.id is deprecated. Instead, use mapreduce.task.id
2014-04-17 07:40:09,158 INFO [main] org.apache.hadoop.conf.Configuration.deprecation: mapred.task.partition is deprecated. Instead, use mapreduce.task.partition
2014-04-17 07:40:09,159 INFO [main] org.apache.hadoop.conf.Configuration.deprecation: job.local.dir is deprecated. Instead, use mapreduce.job.local.dir
2014-04-17 07:40:09,159 INFO [main] org.apache.hadoop.conf.Configuration.deprecation: mapred.cache.localArchives is deprecated. Instead, use mapreduce.job.cache.local.archives
2014-04-17 07:40:09,547 INFO [main] org.apache.hadoop.conf.Configuration.deprecation: session.id is deprecated. Instead, use dfs.metrics.session-id
2014-04-17 07:40:10,132 INFO [main] org.apache.hadoop.mapred.Task:  Using ResourceCalculatorProcessTree : [ ]
2014-04-17 07:40:10,205 INFO [main] org.apache.hadoop.mapred.ReduceTask: Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@174323d5
2014-04-17 07:40:10,253 INFO [main] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: MergerManager: memoryLimit=1503238528, maxSingleShuffleLimit=375809632, mergeThreshold=992137472, ioSortFactor=100, memToMemMergeOutputsThreshold=100
2014-04-17 07:40:10,272 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_1397649276980_0001_r_000003_0 Thread started: EventFetcher for fetching Map Completion Events
2014-04-17 07:40:10,424 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning dc-bigdata2.bateswhite.com:13562 with 1 to fetcher#20
2014-04-17 07:40:10,424 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 1 of 1 to dc-bigdata2.bateswhite.com:13562 to fetcher#20
2014-04-17 07:40:10,427 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning dc-bigdata1.bateswhite.com:13562 with 8 to fetcher#21
2014-04-17 07:40:10,458 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 8 of 8 to dc-bigdata1.bateswhite.com:13562 to fetcher#21
2014-04-17 07:40:10,458 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning dc-bigdata3.bateswhite.com:13562 with 9 to fetcher#1
2014-04-17 07:40:10,458 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 9 of 9 to dc-bigdata3.bateswhite.com:13562 to fetcher#1
2014-04-17 07:40:10,458 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning dc-bigdata4.bateswhite.com:13562 with 10 to fetcher#2
2014-04-17 07:40:10,458 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 10 of 10 to dc-bigdata4.bateswhite.com:13562 to fetcher#2
2014-04-17 07:40:10,837 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=13562/mapOutput?job=job_1397649276980_0001&reduce=3&map=attempt_1397649276980_0001_m_000013_0,attempt_1397649276980_0001_m_000012_0,attempt_1397649276980_0001_m_000008_0,attempt_1397649276980_0001_m_000002_0,attempt_1397649276980_0001_m_000031_0,attempt_1397649276980_0001_m_000026_0,attempt_1397649276980_0001_m_000020_0,attempt_1397649276980_0001_m_000041_0,attempt_1397649276980_0001_m_000050_0 sent hash and received reply
2014-04-17 07:40:10,838 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=13562/mapOutput?job=job_1397649276980_0001&reduce=3&map=attempt_1397649276980_0001_m_000011_0 sent hash and received reply
2014-04-17 07:40:10,837 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=13562/mapOutput?job=job_1397649276980_0001&reduce=3&map=attempt_1397649276980_0001_m_000015_0,attempt_1397649276980_0001_m_000007_0,attempt_1397649276980_0001_m_000010_0,attempt_1397649276980_0001_m_000001_0,attempt_1397649276980_0001_m_000044_0,attempt_1397649276980_0001_m_000036_0,attempt_1397649276980_0001_m_000030_0,attempt_1397649276980_0001_m_000017_0 sent hash and received reply
2014-04-17 07:40:10,840 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=13562/mapOutput?job=job_1397649276980_0001&reduce=3&map=attempt_1397649276980_0001_m_000003_0,attempt_1397649276980_0001_m_000004_0,attempt_1397649276980_0001_m_000000_0,attempt_1397649276980_0001_m_000009_0,attempt_1397649276980_0001_m_000016_0,attempt_1397649276980_0001_m_000024_0,attempt_1397649276980_0001_m_000023_0,attempt_1397649276980_0001_m_000025_0,attempt_1397649276980_0001_m_000042_0,attempt_1397649276980_0001_m_000039_0 sent hash and received reply
2014-04-17 07:40:10,844 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#21 about to shuffle output of map attempt_1397649276980_0001_m_000015_0 decomp: 25850 len: 25854 to MEMORY
2014-04-17 07:40:10,845 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#1 about to shuffle output of map attempt_1397649276980_0001_m_000013_0 decomp: 30674 len: 30678 to MEMORY
2014-04-17 07:40:10,850 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#20 about to shuffle output of map attempt_1397649276980_0001_m_000011_0 decomp: 25022 len: 25026 to MEMORY
2014-04-17 07:40:10,851 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 25022 bytes from map-output for attempt_1397649276980_0001_m_000011_0
2014-04-17 07:40:10,853 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 25022, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->81546
2014-04-17 07:40:10,860 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#2 about to shuffle output of map attempt_1397649276980_0001_m_000003_0 decomp: 38126 len: 38130 to MEMORY
2014-04-17 07:40:10,860 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: dc-bigdata2.bateswhite.com:13562 freed by fetcher#20 in 436ms
2014-04-17 07:40:10,860 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning dc-bigdata2.bateswhite.com:13562 with 597 to fetcher#20
2014-04-17 07:40:10,861 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 20 of 597 to dc-bigdata2.bateswhite.com:13562 to fetcher#20
2014-04-17 07:40:10,864 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=13562/mapOutput?job=job_1397649276980_0001&reduce=3&map=attempt_1397649276980_0001_m_000006_0,attempt_1397649276980_0001_m_000005_0,attempt_1397649276980_0001_m_000014_0,attempt_1397649276980_0001_m_000019_0,attempt_1397649276980_0001_m_000018_0,attempt_1397649276980_0001_m_000021_0,attempt_1397649276980_0001_m_000022_0,attempt_1397649276980_0001_m_000027_0,attempt_1397649276980_0001_m_000029_0,attempt_1397649276980_0001_m_000032_0,attempt_1397649276980_0001_m_000028_0,attempt_1397649276980_0001_m_000035_0,attempt_1397649276980_0001_m_000037_0,attempt_1397649276980_0001_m_000033_0,attempt_1397649276980_0001_m_000038_0,attempt_1397649276980_0001_m_000040_0,attempt_1397649276980_0001_m_000043_0,attempt_1397649276980_0001_m_000047_0,attempt_1397649276980_0001_m_000046_0,attempt_1397649276980_0001_m_000051_0 sent hash and received reply
2014-04-17 07:40:10,871 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#20 about to shuffle output of map attempt_1397649276980_0001_m_000006_0 decomp: 67178 len: 67182 to MEMORY
2014-04-17 07:40:10,879 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 67178 bytes from map-output for attempt_1397649276980_0001_m_000006_0
2014-04-17 07:40:10,879 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 67178, inMemoryMapOutputs.size() -> 2, commitMemory -> 25022, usedMemory ->186850
2014-04-17 07:40:10,881 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_1397649276980_0001_r_000003_0: Got 2712 new map-outputs
2014-04-17 07:40:10,884 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#20 about to shuffle output of map attempt_1397649276980_0001_m_000005_0 decomp: 52346 len: 52350 to MEMORY
2014-04-17 07:40:10,898 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 52346 bytes from map-output for attempt_1397649276980_0001_m_000005_0
2014-04-17 07:40:10,898 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 52346, inMemoryMapOutputs.size() -> 3, commitMemory -> 92200, usedMemory ->239196
2014-04-17 07:40:10,904 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 25850 bytes from map-output for attempt_1397649276980_0001_m_000015_0
2014-04-17 07:40:10,904 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 25850, inMemoryMapOutputs.size() -> 4, commitMemory -> 144546, usedMemory ->239196
2014-04-17 07:40:10,904 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#21 about to shuffle output of map attempt_1397649276980_0001_m_000007_0 decomp: 81722 len: 81726 to MEMORY
2014-04-17 07:40:10,908 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#20 about to shuffle output of map attempt_1397649276980_0001_m_000014_0 decomp: 25022 len: 25026 to MEMORY
2014-04-17 07:40:10,909 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 30674 bytes from map-output for attempt_1397649276980_0001_m_000013_0
2014-04-17 07:40:10,909 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 30674, inMemoryMapOutputs.size() -> 5, commitMemory -> 170396, usedMemory ->345940
2014-04-17 07:40:10,910 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#1 about to shuffle output of map attempt_1397649276980_0001_m_000012_0 decomp: 26534 len: 26538 to MEMORY
2014-04-17 07:40:10,911 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 81722 bytes from map-output for attempt_1397649276980_0001_m_000007_0
2014-04-17 07:40:10,911 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 81722, inMemoryMapOutputs.size() -> 6, commitMemory -> 201070, usedMemory ->372474
2014-04-17 07:40:10,911 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#21 about to shuffle output of map attempt_1397649276980_0001_m_000010_0 decomp: 27974 len: 27978 to MEMORY
2014-04-17 07:40:10,914 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 25022 bytes from map-output for attempt_1397649276980_0001_m_000014_0
2014-04-17 07:40:10,914 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 25022, inMemoryMapOutputs.size() -> 7, commitMemory -> 282792, usedMemory ->400448
2014-04-17 07:40:10,917 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 26534 bytes from map-output for attempt_1397649276980_0001_m_000012_0
2014-04-17 07:40:10,917 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 26534, inMemoryMapOutputs.size() -> 8, commitMemory -> 307814, usedMemory ->400448
2014-04-17 07:40:10,917 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#1 about to shuffle output of map attempt_1397649276980_0001_m_000008_0 decomp: 27218 len: 27222 to MEMORY
2014-04-17 07:40:10,924 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 27974 bytes from map-output for attempt_1397649276980_0001_m_000010_0
2014-04-17 07:40:10,924 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 27218 bytes from map-output for attempt_1397649276980_0001_m_000008_0
2014-04-17 07:40:10,924 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 27974, inMemoryMapOutputs.size() -> 9, commitMemory -> 334348, usedMemory ->427666
2014-04-17 07:40:10,924 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 27218, inMemoryMapOutputs.size() -> 10, commitMemory -> 362322, usedMemory ->427666
2014-04-17 07:40:10,924 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#1 about to shuffle output of map attempt_1397649276980_0001_m_000002_0 decomp: 28478 len: 28482 to MEMORY
2014-04-17 07:40:10,926 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#21 about to shuffle output of map attempt_1397649276980_0001_m_000001_0 decomp: 30674 len: 30678 to MEMORY
2014-04-17 07:40:10,927 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#20 about to shuffle output of map attempt_1397649276980_0001_m_000019_0 decomp: 24554 len: 24558 to MEMORY
2014-04-17 07:40:10,928 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 28478 bytes from map-output for attempt_1397649276980_0001_m_000002_0
2014-04-17 07:40:10,928 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 28478, inMemoryMapOutputs.size() -> 11, commitMemory -> 389540, usedMemory ->511372
2014-04-17 07:40:10,928 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#1 about to shuffle output of map attempt_1397649276980_0001_m_000031_0 decomp: 64622 len: 64626 to MEMORY
2014-04-17 07:40:10,930 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 30674 bytes from map-output for attempt_1397649276980_0001_m_000001_0
2014-04-17 07:40:10,930 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 30674, inMemoryMapOutputs.size() -> 12, commitMemory -> 418018, usedMemory ->575994
2014-04-17 07:40:10,934 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#21 about to shuffle output of map attempt_1397649276980_0001_m_000044_0 decomp: 61166 len: 61170 to MEMORY
2014-04-17 07:40:10,937 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 64622 bytes from map-output for attempt_1397649276980_0001_m_000031_0
2014-04-17 07:40:10,937 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 64622, inMemoryMapOutputs.size() -> 13, commitMemory -> 448692, usedMemory ->637160
2014-04-17 07:40:10,937 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#1 about to shuffle output of map attempt_1397649276980_0001_m_000026_0 decomp: 77294 len: 77298 to MEMORY
2014-04-17 07:40:10,938 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 24554 bytes from map-output for attempt_1397649276980_0001_m_000019_0
2014-04-17 07:40:10,938 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 24554, inMemoryMapOutputs.size() -> 14, commitMemory -> 513314, usedMemory ->714454
2014-04-17 07:40:10,939 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 38126 bytes from map-output for attempt_1397649276980_0001_m_000003_0
2014-04-17 07:40:10,939 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 38126, inMemoryMapOutputs.size() -> 15, commitMemory -> 537868, usedMemory ->714454
2014-04-17 07:40:10,939 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#2 about to shuffle output of map attempt_1397649276980_0001_m_000004_0 decomp: 88598 len: 88602 to MEMORY
2014-04-17 07:40:10,944 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 77294 bytes from map-output for attempt_1397649276980_0001_m_000026_0
2014-04-17 07:40:10,944 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 77294, inMemoryMapOutputs.size() -> 16, commitMemory -> 575994, usedMemory ->803052
2014-04-17 07:40:10,944 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#20 about to shuffle output of map attempt_1397649276980_0001_m_000018_0 decomp: 84854 len: 84858 to MEMORY
2014-04-17 07:40:10,944 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#1 about to shuffle output of map attempt_1397649276980_0001_m_000020_0 decomp: 85142 len: 85146 to MEMORY
2014-04-17 07:40:10,945 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 88598 bytes from map-output for attempt_1397649276980_0001_m_000004_0
2014-04-17 07:40:10,946 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 88598, inMemoryMapOutputs.size() -> 17, commitMemory -> 653288, usedMemory ->973048
2014-04-17 07:40:10,946 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#2 about to shuffle output of map attempt_1397649276980_0001_m_000000_0 decomp: 30242 len: 30246 to MEMORY
2014-04-17 07:40:10,946 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 61166 bytes from map-output for attempt_1397649276980_0001_m_000044_0
2014-04-17 07:40:10,946 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 61166, inMemoryMapOutputs.size() -> 18, commitMemory -> 741886, usedMemory ->1003290
2014-04-17 07:40:10,946 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#21 about to shuffle output of map attempt_1397649276980_0001_m_000036_0 decomp: 32726 len: 32730 to MEMORY
2014-04-17 07:40:10,950 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 85142 bytes from map-output for attempt_1397649276980_0001_m_000020_0
2014-04-17 07:40:10,950 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 85142, inMemoryMapOutputs.size() -> 19, commitMemory -> 803052, usedMemory ->1036016
2014-04-17 07:40:10,950 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#1 about to shuffle output of map attempt_1397649276980_0001_m_000041_0 decomp: 56450 len: 56454 to MEMORY
2014-04-17 07:40:10,952 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 30242 bytes from map-output for attempt_1397649276980_0001_m_000000_0
2014-04-17 07:40:10,952 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 30242, inMemoryMapOutputs.size() -> 20, commitMemory -> 888194, usedMemory ->1092466
2014-04-17 07:40:10,952 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#2 about to shuffle output of map attempt_1397649276980_0001_m_000009_0 decomp: 92018 len: 92022 to MEMORY
2014-04-17 07:40:10,954 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 84854 bytes from map-output for attempt_1397649276980_0001_m_000018_0
2014-04-17 07:40:10,954 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 84854, inMemoryMapOutputs.size() -> 21, commitMemory -> 918436, usedMemory ->1184484
2014-04-17 07:40:10,954 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 32726 bytes from map-output for attempt_1397649276980_0001_m_000036_0
2014-04-17 07:40:10,954 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 32726, inMemoryMapOutputs.size() -> 22, commitMemory -> 1003290, usedMemory ->1184484
2014-04-17 07:40:10,954 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#21 about to shuffle output of map attempt_1397649276980_0001_m_000030_0 decomp: 58286 len: 58290 to MEMORY
2014-04-17 07:40:10,956 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 56450 bytes from map-output for attempt_1397649276980_0001_m_000041_0
2014-04-17 07:40:10,956 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 56450, inMemoryMapOutputs.size() -> 23, commitMemory -> 1036016, usedMemory ->1242770
2014-04-17 07:40:10,956 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#1 about to shuffle output of map attempt_1397649276980_0001_m_000050_0 decomp: 67430 len: 67434 to MEMORY
2014-04-17 07:40:10,961 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 58286 bytes from map-output for attempt_1397649276980_0001_m_000030_0
2014-04-17 07:40:10,961 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 58286, inMemoryMapOutputs.size() -> 24, commitMemory -> 1092466, usedMemory ->1310200
2014-04-17 07:40:10,961 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#21 about to shuffle output of map attempt_1397649276980_0001_m_000017_0 decomp: 27290 len: 27294 to MEMORY
2014-04-17 07:40:10,962 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#20 about to shuffle output of map attempt_1397649276980_0001_m_000021_0 decomp: 27002 len: 27006 to MEMORY
2014-04-17 07:40:10,962 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 92018 bytes from map-output for attempt_1397649276980_0001_m_000009_0
2014-04-17 07:40:10,962 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 92018, inMemoryMapOutputs.size() -> 25, commitMemory -> 1150752, usedMemory ->1364492
2014-04-17 07:40:10,963 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#2 about to shuffle output of map attempt_1397649276980_0001_m_000016_0 decomp: 25058 len: 25062 to MEMORY
2014-04-17 07:40:10,964 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 67430 bytes from map-output for attempt_1397649276980_0001_m_000050_0
2014-04-17 07:40:10,964 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 67430, inMemoryMapOutputs.size() -> 26, commitMemory -> 1242770, usedMemory ->1389550
2014-04-17 07:40:10,964 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: dc-bigdata3.bateswhite.com:13562 freed by fetcher#1 in 506ms
2014-04-17 07:40:10,964 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning dc-bigdata3.bateswhite.com:13562 with 697 to fetcher#1
2014-04-17 07:40:10,965 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 27290 bytes from map-output for attempt_1397649276980_0001_m_000017_0
2014-04-17 07:40:10,965 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 25058 bytes from map-output for attempt_1397649276980_0001_m_000016_0
2014-04-17 07:40:10,966 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 20 of 697 to dc-bigdata3.bateswhite.com:13562 to fetcher#1
2014-04-17 07:40:10,966 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 25058, inMemoryMapOutputs.size() -> 27, commitMemory -> 1310200, usedMemory ->1389550
2014-04-17 07:40:10,967 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#2 about to shuffle output of map attempt_1397649276980_0001_m_000024_0 decomp: 22862 len: 22866 to MEMORY
2014-04-17 07:40:10,967 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 27290, inMemoryMapOutputs.size() -> 28, commitMemory -> 1335258, usedMemory ->1412412
2014-04-17 07:40:10,967 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: dc-bigdata1.bateswhite.com:13562 freed by fetcher#21 in 509ms
2014-04-17 07:40:10,967 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning dc-bigdata1.bateswhite.com:13562 with 640 to fetcher#21
2014-04-17 07:40:10,968 INFO [fetcher#1] org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=13562/mapOutput?job=job_1397649276980_0001&reduce=3&map=attempt_1397649276980_0001_m_000054_0,attempt_1397649276980_0001_m_000058_0,attempt_1397649276980_0001_m_000062_0,attempt_1397649276980_0001_m_000066_0,attempt_1397649276980_0001_m_000070_0,attempt_1397649276980_0001_m_000074_0,attempt_1397649276980_0001_m_000078_0,attempt_1397649276980_0001_m_000082_0,attempt_1397649276980_0001_m_000086_0,attempt_1397649276980_0001_m_000090_0,attempt_1397649276980_0001_m_000094_0,attempt_1397649276980_0001_m_000098_0,attempt_1397649276980_0001_m_000102_0,attempt_1397649276980_0001_m_000106_0,attempt_1397649276980_0001_m_000110_0,attempt_1397649276980_0001_m_000114_0,attempt_1397649276980_0001_m_000122_0,attempt_1397649276980_0001_m_000118_0,attempt_1397649276980_0001_m_000126_0,attempt_1397649276980_0001_m_000130_0 sent hash and received reply
2014-04-17 07:40:10,969 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 20 of 640 to dc-bigdata1.bateswhite.com:13562 to fetcher#21
2014-04-17 07:40:10,970 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 27002 bytes from map-output for attempt_1397649276980_0001_m_000021_0
2014-04-17 07:40:10,972 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 27002, inMemoryMapOutputs.size() -> 29, commitMemory -> 1362548, usedMemory ->1412412
2014-04-17 07:40:10,972 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 22862 bytes from map-output for attempt_1397649276980_0001_m_000024_0
2014-04-17 07:40:10,972 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 22862, inMemoryMapOutputs.size() -> 30, commitMemory -> 1389550, usedMemory ->1412412
2014-04-17 07:40:10,972 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#2 about to shuffle output of map attempt_1397649276980_0001_m_000023_0 decomp: 23618 len: 23622 to MEMORY
2014-04-17 07:40:10,973 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#20 about to shuffle output of map attempt_1397649276980_0001_m_000022_0 decomp: 25382 len: 25386 to MEMORY
2014-04-17 07:40:10,974 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 23618 bytes from map-output for attempt_1397649276980_0001_m_000023_0
2014-04-17 07:40:10,974 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 23618, inMemoryMapOutputs.size() -> 31, commitMemory -> 1412412, usedMemory ->1461412
2014-04-17 07:40:10,974 INFO [fetcher#2] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#2 about to shuffle output of map attempt_1397649276980_0001_m_000025_0 decomp: 45182 len: 45186 to MEMORY
2014-04-17 07:40:10,974 INFO [fetcher#21] org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=13562/mapOutput?job=job_1397649276980_0001&reduce=3&map=attempt_1397649276980_0001_m_000048_0,attempt_1397649276980_0001_m_000052_0,attempt_1397649276980_0001_m_000056_0,attempt_1397649276980_0001_m_000060_0,attempt_1397649276980_0001_m_000064_0,attempt_1397649276980_0001_m_000072_0,attempt_1397649276980_0001_m_000076_0,attempt_1397649276980_0001_m_000068_0,attempt_1397649276980_0001_m_000080_0,attempt_1397649276980_0001_m_000084_0,attempt_1397649276980_0001_m_000088_0,attempt_1397649276980_0001_m_000092_0,attempt_1397649276980_0001_m_000096_0,attempt_1397649276980_0001_m_000100_0,attempt_1397649276980_0001_m_000108_0,attempt_1397649276980_0001_m_000104_0,attempt_1397649276980_0001_m_000112_0,attempt_1397649276980_0001_m_000116_0,attempt_1397649276980_0001_m_000120_0,attempt_1397649276980_0001_m_000124_0 sent hash and received reply
2014-04-17 07:40:10,979 INFO [fetcher#20] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 25382 bytes from map-output for attempt_1397649276980_0001_m_000022_0