Hive query taking long time in reduce phase

[Khireswar Kalita <kh...@gmail.com>]

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