I am getting an issue on a production cluster where Mapreduce Job taking long time in reduce phase while running a Hive query, approximately 2 hrs for one reduce task.
Hardware specification of the cluster : Number of nodes:22 Number of Master nodes4 Number of data nodes:18 Core per nodes:24 Memory per nodes:512 GB Minimum yarn container size is 2048MB. This issue does not occur all the time. So I am not sure what might be the root cause. Please help me with your suggestions if any one experiencing similar issue Application Log: 8:02,616 INFO [main] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: MergerManager: memoryLimit=6370046464, maxSingleShuffleLimit=1592511616, mergeThreshold=4204230912, ioSortFactor=100, memToMemMergeOutputsThreshold=100 2017-06-04 18:58:02,619 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_1496358601894_1431_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events 2017-06-04 18:58:02,628 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning am1dlccmrhdd08.r1-core.r1.aig.net:13562 with 1 to fetcher#5 2017-06-04 18:58:02,628 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 1 of 1 to am1dlccmrhdd08.r1-core.r1.aig.net:13562 to fetcher#5 2017-06-04 18:58:02,628 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Ignoring obsolete output of OBSOLETE map-task: 'attempt_1496358601894_1431_m_000003_0' 2017-06-04 18:58:02,629 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Ignoring obsolete output of FAILED map-task: 'attempt_1496358601894_1431_m_000003_0' 2017-06-04 18:58:02,629 INFO [fetcher#8] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning am1dlccmrhdd01.r1-core.r1.aig.net:13562 with 1 to fetcher#8 2017-06-04 18:58:02,631 INFO [fetcher#8] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 1 of 1 to am1dlccmrhdd01.r1-core.r1.aig.net:13562 to fetcher#8 2017-06-04 18:58:02,631 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_1496358601894_1431_r_000000_0: Got 3 new map-outputs 2017-06-04 18:58:02,747 INFO [fetcher#8] org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=13562/mapOutput?job=job_1496358601894_1431&reduce=0&map=attempt_1496358601894_1431_m_000006_0 sent hash and received reply 2017-06-04 18:58:02,747 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=13562/mapOutput?job=job_1496358601894_1431&reduce=0&map=attempt_1496358601894_1431_m_000009_0 sent hash and received reply 2017-06-04 18:58:02,752 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#5 about to shuffle output of map attempt_1496358601894_1431_m_000009_0 decomp: 40205 len: 40209 to MEMORY 2017-06-04 18:58:02,752 INFO [fetcher#8] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#8 about to shuffle output of map attempt_1496358601894_1431_m_000006_0 decomp: 50946 len: 50950 to MEMORY 2017-06-04 18:58:02,755 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 40205 bytes from map-output for attempt_1496358601894_1431_m_000009_0 2017-06-04 18:58:02,755 INFO [fetcher#8] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 50946 bytes from map-output for attempt_1496358601894_1431_m_000006_0 2017-06-04 18:58:02,758 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 40205, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->91151 2017-06-04 18:58:02,759 INFO [fetcher#8] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 50946, inMemoryMapOutputs.size() -> 2, commitMemory -> 40205, usedMemory ->91151 2017-06-04 18:58:02,760 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: am1dlccmrhdd08.r1-core.r1.aig.net:13562 freed by fetcher#5 in 131ms 2017-06-04 18:58:02,760 INFO [fetcher#8] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: am1dlccmrhdd01.r1-core.r1.aig.net:13562 freed by fetcher#8 in 131ms 2017-06-04 18:58:02,760 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning am1dlccmrhdd01.r1-core.r1.aig.net:13562 with 1 to fetcher#5 2017-06-04 18:58:02,760 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 1 of 1 to am1dlccmrhdd01.r1-core.r1.aig.net:13562 to fetcher#5 2017-06-04 18:58:02,762 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=13562/mapOutput?job=job_1496358601894_1431&reduce=0&map=attempt_1496358601894_1431_m_000008_0 sent hash and received reply 2017-06-04 18:58:02,762 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#5 about to shuffle output of map attempt_1496358601894_1431_m_000008_0 decomp: 58087 len: 58091 to MEMORY 2017-06-04 18:58:02,763 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 58087 bytes from map-output for attempt_1496358601894_1431_m_000008_0 2017-06-04 18:58:02,763 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 58087, inMemoryMapOutputs.size() -> 3, commitMemory -> 91151, usedMemory ->149238 2017-06-04 18:58:02,763 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: am1dlccmrhdd01.r1-core.r1.aig.net:13562 freed by fetcher#5 in 3ms 2017-06-04 18:58:04,636 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_1496358601894_1431_r_000000_0: Got 1 new map-outputs 2017-06-04 18:58:04,636 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning am1dlccmrhdd01.r1-core.r1.aig.net:13562 with 1 to fetcher#5 2017-06-04 18:58:04,637 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 1 of 1 to am1dlccmrhdd01.r1-core.r1.aig.net:13562 to fetcher#5 2017-06-04 18:58:04,640 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=13562/mapOutput?job=job_1496358601894_1431&reduce=0&map=attempt_1496358601894_1431_m_000010_0 sent hash and received reply 2017-06-04 18:58:04,640 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#5 about to shuffle output of map attempt_1496358601894_1431_m_000010_0 decomp: 30050 len: 30054 to MEMORY 2017-06-04 18:58:04,640 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 30050 bytes from map-output for attempt_1496358601894_1431_m_000010_0 2017-06-04 18:58:04,640 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 30050, inMemoryMapOutputs.size() -> 4, commitMemory -> 149238, usedMemory ->179288 2017-06-04 18:58:04,640 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: am1dlccmrhdd01.r1-core.r1.aig.net:13562 freed by fetcher#5 in 3ms 2017-06-04 18:58:05,639 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_1496358601894_1431_r_000000_0: Got 1 new map-outputs 2017-06-04 18:58:05,639 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning am1dlccmrhdd01.r1-core.r1.aig.net:13562 with 1 to fetcher#5 2017-06-04 18:58:05,639 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 1 of 1 to am1dlccmrhdd01.r1-core.r1.aig.net:13562 to fetcher#5 2017-06-04 18:58:05,641 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=13562/mapOutput?job=job_1496358601894_1431&reduce=0&map=attempt_1496358601894_1431_m_000002_0 sent hash and received reply 2017-06-04 18:58:05,641 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#5 about to shuffle output of map attempt_1496358601894_1431_m_000002_0 decomp: 211608 len: 211612 to MEMORY 2017-06-04 18:58:05,642 WARN [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.Fetcher: Failed to shuffle for fetcher#5 java.net.SocketException: Connection reset at java.net.SocketInputStream.read(SocketInputStream.java:196) at java.net.SocketInputStream.read(SocketInputStream.java:122) at java.io.BufferedInputStream.read1(BufferedInputStream.java:273) at java.io.BufferedInputStream.read(BufferedInputStream.java:334) at java.io.FilterInputStream.read(FilterInputStream.java:133) at sun.net.www.protocol.http.HttpURLConnection$HttpInputStream.read(HttpURLConnection.java:3053) at java.io.DataInputStream.read(DataInputStream.java:149) at org.apache.hadoop.mapred.IFileInputStream.doRead(IFileInputStream.java:209) at org.apache.hadoop.mapred.IFileInputStream.read(IFileInputStream.java:152) at org.apache.hadoop.io.IOUtils.readFully(IOUtils.java:199) at org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput.shuffle(InMemoryMapOutput.java:97) at org.apache.hadoop.mapreduce.task.reduce.Fetcher.copyMapOutput(Fetcher.java:537) at org.apache.hadoop.mapreduce.task.reduce.Fetcher.copyFromHost(Fetcher.java:336) at org.apache.hadoop.mapreduce.task.reduce.Fetcher.run(Fetcher.java:193) 2017-06-04 18:58:05,647 WARN [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.Fetcher: Failed to shuffle output of attempt_1496358601894_1431_m_000002_0 from am1dlccmrhdd01.r1-core.r1.aig.net:13562 java.io.IOException: java.net.SocketException: Connection reset at org.apache.hadoop.mapreduce.task.reduce.Fetcher.copyMapOutput(Fetcher.java:541) at org.apache.hadoop.mapreduce.task.reduce.Fetcher.copyFromHost(Fetcher.java:336) at org.apache.hadoop.mapreduce.task.reduce.Fetcher.run(Fetcher.java:193) Caused by: java.net.SocketException: Connection reset at java.net.SocketInputStream.read(SocketInputStream.java:196) at java.net.SocketInputStream.read(SocketInputStream.java:122) at java.io.BufferedInputStream.read1(BufferedInputStream.java:273) at java.io.BufferedInputStream.read(BufferedInputStream.java:334) at java.io.FilterInputStream.read(FilterInputStream.java:133) at sun.net.www.protocol.http.HttpURLConnection$HttpInputStream.read(HttpURLConnection.java:3053) at java.io.DataInputStream.read(DataInputStream.java:149) at org.apache.hadoop.mapred.IFileInputStream.doRead(IFileInputStream.java:209) at org.apache.hadoop.mapred.IFileInputStream.read(IFileInputStream.java:152) at org.apache.hadoop.io.IOUtils.readFully(IOUtils.java:199) at org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput.shuffle(InMemoryMapOutput.java:97) at org.apache.hadoop.mapreduce.task.reduce.Fetcher.copyMapOutput(Fetcher.java:537) ... 2 more 2017-06-04 18:58:05,647 WARN [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.Fetcher: copyMapOutput failed for tasks [attempt_1496358601894_1431_m_000002_0] 2017-06-04 18:58:05,649 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Reporting fetch failure for attempt_1496358601894_1431_m_000002_0 to MRAppMaster. 2017-06-04 18:58:05,650 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: am1dlccmrhdd01.r1-core.r1.aig.net:13562 freed by fetcher#5 in 11ms 2017-06-04 18:58:16,671 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Ignoring obsolete output of FAILED map-task: 'attempt_1496358601894_1431_m_000002_0' 2017-06-04 18:58:18,650 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning am1dlccmrhdd01.r1-core.r1.aig.net:13562 with 1 to fetcher#5 2017-06-04 18:58:18,650 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 0 of 1 to am1dlccmrhdd01.r1-core.r1.aig.net:13562 to fetcher#5 2017-06-04 18:58:18,650 INFO [fetcher#5] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: am1dlccmrhdd01.r1-core.r1.aig.net:13562 freed by fetcher#5 in 0ms 2017-06-04 18:58:26,699 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_1496358601894_1431_r_000000_0: Got 1 new map-outputs 2017-06-04 18:58:26,699 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning am1dlccmrhdd10.r1-core.r1.aig.net:13562 with 1 to fetcher#30 2017-06-04 18:58:26,699 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 1 of 1 to am1dlccmrhdd10.r1-core.r1.aig.net:13562 to fetcher#30 2017-06-04 18:58:26,704 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=13562/mapOutput?job=job_1496358601894_1431&reduce=0&map=attempt_1496358601894_1431_m_000002_1 sent hash and received reply 2017-06-04 18:58:26,705 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#30 about to shuffle output of map attempt_1496358601894_1431_m_000002_1 decomp: 211608 len: 211612 to MEMORY 2017-06-04 18:58:26,706 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 211608 bytes from map-output for attempt_1496358601894_1431_m_000002_1 2017-06-04 18:58:26,707 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 211608, inMemoryMapOutputs.size() -> 5, commitMemory -> 179288, usedMemory ->390896 2017-06-04 18:58:26,707 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: am1dlccmrhdd10.r1-core.r1.aig.net:13562 freed by fetcher#30 in 8ms 2017-06-04 18:58:27,703 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_1496358601894_1431_r_000000_0: Got 1 new map-outputs 2017-06-04 18:58:27,703 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning am1dlccmrhdd15.r1-core.r1.aig.net:13562 with 1 to fetcher#30 2017-06-04 18:58:27,703 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 1 of 1 to am1dlccmrhdd15.r1-core.r1.aig.net:13562 to fetcher#30 2017-06-04 18:58:27,707 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=13562/mapOutput?job=job_1496358601894_1431&reduce=0&map=attempt_1496358601894_1431_m_000007_0 sent hash and received reply 2017-06-04 18:58:27,708 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#30 about to shuffle output of map attempt_1496358601894_1431_m_000007_0 decomp: 96007 len: 96011 to MEMORY 2017-06-04 18:58:27,708 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 96007 bytes from map-output for attempt_1496358601894_1431_m_000007_0 2017-06-04 18:58:27,709 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 96007, inMemoryMapOutputs.size() -> 6, commitMemory -> 390896, usedMemory ->486903 2017-06-04 18:58:27,709 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: am1dlccmrhdd15.r1-core.r1.aig.net:13562 freed by fetcher#30 in 6ms 2017-06-04 18:58:29,708 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Ignoring obsolete output of FAILED map-task: 'attempt_1496358601894_1431_m_000002_1' 2017-06-04 18:58:34,722 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning am1dlccmrhdd03.r1-core.r1.aig.net:13562 with 1 to fetcher#30 2017-06-04 18:58:34,722 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 1 of 1 to am1dlccmrhdd03.r1-core.r1.aig.net:13562 to fetcher#30 2017-06-04 18:58:34,723 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_1496358601894_1431_r_000000_0: Got 2 new map-outputs 2017-06-04 18:58:34,725 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=13562/mapOutput?job=job_1496358601894_1431&reduce=0&map=attempt_1496358601894_1431_m_000011_0 sent hash and received reply 2017-06-04 18:58:34,726 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#30 about to shuffle output of map attempt_1496358601894_1431_m_000011_0 decomp: 5783 len: 5787 to MEMORY 2017-06-04 18:58:34,726 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 5783 bytes from map-output for attempt_1496358601894_1431_m_000011_0 2017-06-04 18:58:34,726 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 5783, inMemoryMapOutputs.size() -> 7, commitMemory -> 486903, usedMemory ->492686 2017-06-04 18:58:34,727 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: am1dlccmrhdd03.r1-core.r1.aig.net:13562 freed by fetcher#30 in 4ms 2017-06-04 18:58:34,727 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning am1dlccmrhdd03.r1-core.r1.aig.net:13562 with 1 to fetcher#30 2017-06-04 18:58:34,727 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 1 of 1 to am1dlccmrhdd03.r1-core.r1.aig.net:13562 to fetcher#30 2017-06-04 18:58:34,729 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=13562/mapOutput?job=job_1496358601894_1431&reduce=0&map=attempt_1496358601894_1431_m_000001_0 sent hash and received reply 2017-06-04 18:58:34,730 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#30 about to shuffle output of map attempt_1496358601894_1431_m_000001_0 decomp: 190907 len: 190911 to MEMORY 2017-06-04 18:58:34,731 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 190907 bytes from map-output for attempt_1496358601894_1431_m_000001_0 2017-06-04 18:58:34,732 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 190907, inMemoryMapOutputs.size() -> 8, commitMemory -> 492686, usedMemory ->683593 2017-06-04 18:58:34,732 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: am1dlccmrhdd03.r1-core.r1.aig.net:13562 freed by fetcher#30 in 5ms 2017-06-04 18:58:36,729 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning am1dlccmrhdd03.r1-core.r1.aig.net:13562 with 1 to fetcher#30 2017-06-04 18:58:36,729 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 1 of 1 to am1dlccmrhdd03.r1-core.r1.aig.net:13562 to fetcher#30 2017-06-04 18:58:36,730 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_1496358601894_1431_r_000000_0: Got 2 new map-outputs 2017-06-04 18:58:36,732 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=13562/mapOutput?job=job_1496358601894_1431&reduce=0&map=attempt_1496358601894_1431_m_000004_0 sent hash and received reply 2017-06-04 18:58:36,733 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#30 about to shuffle output of map attempt_1496358601894_1431_m_000004_0 decomp: 44876 len: 44880 to MEMORY 2017-06-04 18:58:36,733 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 44876 bytes from map-output for attempt_1496358601894_1431_m_000004_0 2017-06-04 18:58:36,733 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 44876, inMemoryMapOutputs.size() -> 9, commitMemory -> 683593, usedMemory ->728469 2017-06-04 18:58:36,734 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: am1dlccmrhdd03.r1-core.r1.aig.net:13562 freed by fetcher#30 in 5ms 2017-06-04 18:58:36,734 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning am1dlccmrhdd03.r1-core.r1.aig.net:13562 with 1 to fetcher#30 2017-06-04 18:58:36,734 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 1 of 1 to am1dlccmrhdd03.r1-core.r1.aig.net:13562 to fetcher#30 2017-06-04 18:58:36,737 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=13562/mapOutput?job=job_1496358601894_1431&reduce=0&map=attempt_1496358601894_1431_m_000005_0 sent hash and received reply 2017-06-04 18:58:36,738 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#30 about to shuffle output of map attempt_1496358601894_1431_m_000005_0 decomp: 38332 len: 38336 to MEMORY 2017-06-04 18:58:36,738 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 38332 bytes from map-output for attempt_1496358601894_1431_m_000005_0 2017-06-04 18:58:36,738 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 38332, inMemoryMapOutputs.size() -> 10, commitMemory -> 728469, usedMemory ->766801 2017-06-04 18:58:36,738 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: am1dlccmrhdd03.r1-core.r1.aig.net:13562 freed by fetcher#30 in 4ms 2017-06-04 18:58:40,740 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_1496358601894_1431_r_000000_0: Got 1 new map-outputs 2017-06-04 18:58:40,740 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning am1dlccmrhdd15.r1-core.r1.aig.net:13562 with 1 to fetcher#30 2017-06-04 18:58:40,741 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 1 of 1 to am1dlccmrhdd15.r1-core.r1.aig.net:13562 to fetcher#30 2017-06-04 18:58:40,744 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=13562/mapOutput?job=job_1496358601894_1431&reduce=0&map=attempt_1496358601894_1431_m_000003_1 sent hash and received reply 2017-06-04 18:58:40,745 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#30 about to shuffle output of map attempt_1496358601894_1431_m_000003_1 decomp: 38416 len: 38420 to MEMORY 2017-06-04 18:58:40,745 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 38416 bytes from map-output for attempt_1496358601894_1431_m_000003_1 2017-06-04 18:58:40,745 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 38416, inMemoryMapOutputs.size() -> 11, commitMemory -> 766801, usedMemory ->805217 2017-06-04 18:58:40,746 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: am1dlccmrhdd15.r1-core.r1.aig.net:13562 freed by fetcher#30 in 5ms 2017-06-04 18:58:51,768 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Ignoring obsolete output of FAILED map-task: 'attempt_1496358601894_1431_m_000004_0' 2017-06-04 18:58:56,781 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Ignoring obsolete output of FAILED map-task: 'attempt_1496358601894_1431_m_000003_1' 2017-06-04 18:59:22,845 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_1496358601894_1431_r_000000_0: Got 1 new map-outputs 2017-06-04 18:59:22,845 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning am1dlccmrhdd15.r1-core.r1.aig.net:13562 with 1 to fetcher#30 2017-06-04 18:59:22,845 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 0 of 1 to am1dlccmrhdd15.r1-core.r1.aig.net:13562 to fetcher#30 2017-06-04 18:59:22,845 INFO [fetcher#30] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: am1dlccmrhdd15.r1-core.r1.aig.net:13562 freed by fetcher#30 in 0ms 2017-06-04 18:59:36,878 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_1496358601894_1431_r_000000_0: Got 1 new map-outputs 2017-06-04 18:59:36,878 INFO [fetcher#29] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: Assigning am1dlccmrhdd02.r1-core.r1.aig.net:13562 with 1 to fetcher#29 2017-06-04 18:59:36,878 INFO [fetcher#29] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: assigned 1 of 1 to am1dlccmrhdd02.r1-core.r1.aig.net:13562 to fetcher#29 2017-06-04 18:59:36,884 INFO [fetcher#29] org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=13562/mapOutput?job=job_1496358601894_1431&reduce=0&map=attempt_1496358601894_1431_m_000000_0 sent hash and received reply 2017-06-04 18:59:36,885 INFO [fetcher#29] org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#29 about to shuffle output of map attempt_1496358601894_1431_m_000000_0 decomp: 245826 len: 245830 to MEMORY 2017-06-04 18:59:36,887 INFO [fetcher#29] org.apache.hadoop.mapreduce.task.reduce.InMemoryMapOutput: Read 245826 bytes from map-output for attempt_1496358601894_1431_m_000000_0 2017-06-04 18:59:36,887 INFO [fetcher#29] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: closeInMemoryFile -> map-output of size: 245826, inMemoryMapOutputs.size() -> 12, commitMemory -> 805217, usedMemory ->1051043 2017-06-04 18:59:36,888 INFO [fetcher#29] org.apache.hadoop.mapreduce.task.reduce.ShuffleSchedulerImpl: am1dlccmrhdd02.r1-core.r1.aig.net:13562 freed by fetcher#29 in 9ms 2017-06-04 18:59:36,888 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: EventFetcher is interrupted.. Returning 2017-06-04 18:59:36,895 INFO [main] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: finalMerge called with 12 in-memory map-outputs and 0 on-disk map-outputs 2017-06-04 18:59:36,910 INFO [main] org.apache.hadoop.mapred.Merger: Merging 12 sorted segments 2017-06-04 18:59:36,910 INFO [main] org.apache.hadoop.mapred.Merger: Down to the last merge-pass, with 12 segments left of total size: 1050833 bytes 2017-06-04 18:59:37,144 INFO [main] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: Merged 12 segments, 1051043 bytes to disk to satisfy reduce memory limit 2017-06-04 18:59:37,145 INFO [main] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: Merging 1 files, 1051025 bytes from disk 2017-06-04 18:59:37,147 INFO [main] org.apache.hadoop.mapreduce.task.reduce.MergeManagerImpl: Merging 0 segments, 0 bytes from memory into reduce 2017-06-04 18:59:37,147 INFO [main] org.apache.hadoop.mapred.Merger: Merging 1 sorted segments 2017-06-04 18:59:37,153 INFO [main] org.apache.hadoop.mapred.Merger: Down to the last merge-pass, with 1 segments left of total size: 1051004 bytes