Reply
Expert Contributor
Posts: 357
Registered: ‎01-25-2017

mapreduce job that compacted daily files at HDFS failed on java heap size

Hi,

 

I have mapreduce job that compacted daily files at HDFS, sometimes it failed on Java heap size, i tried to fine tune alot of parmeters listed below but the job still failing:

 

what other parameters i can fine tune to overcome this issue, please see below the error i see and the job and enviroment configuration

=================

 

2017-02-18 07:24:11,005 FATAL org.apache.hadoop.mapred.Child: Error running child : java.lang.OutOfMemoryError: Java heap space
at org.apache.hadoop.mapred.IFile$Reader.readNextBlock(IFile.java:357)
at org.apache.hadoop.mapred.IFile$Reader.next(IFile.java:419)
at org.apache.hadoop.mapred.Merger$Segment.next(Merger.java:238)
at org.apache.hadoop.mapred.Merger$MergeQueue.adjustPriorityQueue(Merger.java:348)
at org.apache.hadoop.mapred.Merger$MergeQueue.next(Merger.java:368)
at org.apache.hadoop.mapred.Merger.writeFile(Merger.java:156)
at org.apache.hadoop.mapred.Merger$MergeQueue.merge(Merger.java:517)
at org.apache.hadoop.mapred.Merger.merge(Merger.java:142)
at org.apache.hadoop.mapred.ReduceTask$ReduceCopier.createKVIterator(ReduceTask.java:2537)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:425)
at org.apache.hadoop.mapred.Child$4.run(Child.java:268)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:396)
at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1408)
at org.apache.hadoop.mapred.Child.main(Child.java:262)

===============================================================================================

mapreduce.reduce.java.opts -Xmx5092M
mapred.reduce.child.java.opts -Xmx5092M
mapred.child.java.opts -Xmx5092M

In hadoop-env conf here is the configuration:

# The maximum amount of heap to use, in MB. Default is 1000.
#export HADOOP_HEAPSIZE=2000

export HADOOP_DATANODE_OPTS="-Xmx4g $HADOOP_DATANODE_OPTS"

=======================
File System Counters:

Counter Map Reduce Total
FILE: Number of bytes read 692,081,373,291 602,095,907,022 1,294,177,280,313
FILE: Number of bytes written 793,960,840,973 677,609,718,563 1,471,570,559,536
HDFS: Number of bytes read 199,518,684,678 0 199,518,684,678
HDFS: Number of bytes written 0 123,873,850,280 123,873,850,280

Posts: 642
Topics: 3
Kudos: 120
Solutions: 67
Registered: ‎08-16-2016

Re: mapreduce job that compacted daily files at HDFS failed on java heap size

export HADOOP_DATANODE_OPTS="-Xmx4g $HADOOP_DATANODE_OPTS"

 

This is for the Datanode heap not your job containers heap.  Best way to check those actual values is through the RM UI.  Find the job, click History (or Applicaiton Master) link.  On the left hand side click on the Configuration menu.  At the bottom of the page should be fields to search the key and value search for by 'memory' and 'opts'.  I can't seem to find my favorite link that covers how these settings work together.

 

I leave it at this, there is a minimum and maximum container size, there are settings for the containers for Map and Reduce tasks, and there is the heap size for each of those (in later versions there is a percentage for the heap that gets applied to all containers and the default is 80%).  The minimum determines the memory size of a container by default; maximum is simply a limit and should be less than what a single host can do without running out of physical  memory.  The Map and Reduce container sizes set the container memory for each for all MR jobs.  These adjust the minimum set for all containers.  The opts can set the heap or you let it do it for you.  The reason a setting for all based on a percentage was due to the large number of users that would adjust heap size without increasing the container size.  I think that is what is happening here as you only posted the opts settings.  If you increase these without increasing the container size then the container and job will easily OOM.

 

Check these settings.

YARN

yarn.nodemanager.resource.memory-mb

yarn.scheduler.minimum-allocation-mb

yarn.scheduler.maximum-allocation-mb

 

MR

mapreduce.map.memory.mb

mapreduce.reduce.memory.mb

mapreduce.map.java.opts

mapreduce.reduce.java.opts

mapreduce.job.heap.memory-mb.ratio (ratio that sets the heap size for all containers based on the container size)

 

Application Master

yarn.app.mapreduce.am.resource.mb

yarn.app.mapreduce.am.command-opts

 

Relationship between the major players:

yarn.nodemanager.resource.memory-mb > mapreduce.map.memory.mb/mapreduce.reduce.memory.mb > mapreduce.map.java.opts/mapreduce.reduce.java.opts

 

(not to be confusing; I am not saying that M and R should be divided or divisable)

Expert Contributor
Posts: 357
Registered: ‎01-25-2017

Re: mapreduce job that compacted daily files at HDFS failed on java heap size

[ Edited ]

I know the the one you mention is related to data node.

The configuration I showed the ones that I get from the job configuration
in the JobTracker UI.

 

I missed to mention that it's happens with one of the reducers only which is working on the largest HDFS parition.

Posts: 642
Topics: 3
Kudos: 120
Solutions: 67
Registered: ‎08-16-2016

Re: mapreduce job that compacted daily files at HDFS failed on java heap size

Can you post the values for all of the settings I posted?
Expert Contributor
Posts: 357
Registered: ‎01-25-2017

Re: mapreduce job that compacted daily files at HDFS failed on java heap size

Here is the workflow for my job:

 

<main-class>com.liveperson.hadoop.platform.compaction.ExecuteCompaction</main-class>
<arg>-Dmapred.reduce.child.java.opts=-Xmx5092M</arg>
<arg>-Dmapreduce.reduce.java.opts=-Xmx5092M</arg>
<arg>-Dmapreduce.map.child.java.opts=-Xmx2024M</arg>
<arg>-Dmapred.child.java.opts=-Xmx5092M</arg>
<arg>-Dmapred.job.shuffle.input.buffer.percent=0.2</arg>
<arg>-Dmapred.job.reduce.input.buffer.percent=0.0</arg>
<arg>-Dmapred.job.shuffle.merge.percent=0.2</arg>
<arg>-Dio.sort.factor=2</arg>
<arg>-Dmapred.fairscheduler.pool=data_platform_compaction</arg>
<arg>-Dio.sort.mb=256</arg>
<arg>-Dmapred.output.compression.codec=com.hadoop.compression.lzo.LzoCodec</arg>
<arg>-Dmapred.output.compress=true</arg>
<arg>-Dlp.compaction.rsjob=${rsJob}</arg>

Posts: 642
Topics: 3
Kudos: 120
Solutions: 67
Registered: ‎08-16-2016

Re: mapreduce job that compacted daily files at HDFS failed on java heap size

Ok, disregard all that I said above. Since this is CDH 4.x, I am assuming you aren't running Hadoop 2.0 beta, then it is running Hadoop 1 and YARN doesn't exist.

This setting, mapred.child.java.opts, is overridden by mapred.map.child.java.opts and mapred.reduce.child.java.opts. This will set both Map and Reduce the same value, mapred.child.java.opts.

This setting, mapreduce.reduce.java.opts, is the Hadoop 2.x version of mapred.reduce.child.java.opts. This safe to drop.

This is not a valid setting, mapreduce.map.child.java.opts. It is mapred.map.child.java.opts for Hadoop 1 and mapreduce.map.java.opts.

Right now, your mappers have a 5 GB heap and so do your reducers. Put simply you need to increase the heap until it doesn't run out of memory any longer. You mentioned it was a reducer, so just adjust mapred.reduce.child.java.opts. You also mentioned it was just one reducer and it worked on the majority of the data. Does it take a lot longer than the other reducers? If yes, I would look into building a custom partitioner to better distribute the data.
Highlighted
Expert Contributor
Posts: 357
Registered: ‎01-25-2017

Re: mapreduce job that compacted daily files at HDFS failed on java heap size

since my parition is account id, i cann't customize my partitions, Also i increase the heap size to 8GB but with no help.

Posts: 642
Topics: 3
Kudos: 120
Solutions: 67
Registered: ‎08-16-2016

Re: mapreduce job that compacted daily files at HDFS failed on java heap size

Can you upload the job logs?

Is account id the partition column for your Hive table?

I was talking about the partitioner within MapReduce. It determines how the data is partitioned in the map output. These partition files are then sent to the reducers to be processed. If one reducer (or a few) are working on the majority of the data and working harder and longer than the others you would address it by improving the partitioner so that the data is more evenly distributed between reducers.
Expert Contributor
Posts: 357
Registered: ‎01-25-2017

Re: mapreduce job that compacted daily files at HDFS failed on java heap size

It;s mapreduce and not hive,

 

in the HDFS my partition is account id and date, in each partition i save the daily data for each account at one partition, each reducer is working in one partition, since the log is huge i delete alot of the log

 

2017-02-18 07:05:07,028 WARN mapreduce.Counters: Group org.apache.hadoop.mapred.Task$Counter is deprecated. Use org.apache.hadoop.mapreduce.TaskCounter instead
2017-02-18 07:05:07,303 WARN org.apache.hadoop.conf.Configuration: session.id is deprecated. Instead, use dfs.metrics.session-id
2017-02-18 07:05:07,304 INFO org.apache.hadoop.metrics.jvm.JvmMetrics: Initializing JVM Metrics with processName=SHUFFLE, sessionId=
2017-02-18 07:05:08,390 INFO org.apache.hadoop.util.ProcessTree: setsid exited with exit code 0
2017-02-18 07:05:08,394 INFO org.apache.hadoop.mapred.Task: Using ResourceCalculatorPlugin : org.apache.hadoop.util.LinuxResourceCalculatorPlugin@6bb54362
2017-02-18 07:05:08,467 INFO com.hadoop.compression.lzo.GPLNativeCodeLoader: Loaded native gpl library
2017-02-18 07:05:08,469 INFO com.hadoop.compression.lzo.LzoCodec: Successfully loaded & initialized native-lzo library [hadoop-lzo rev 6298911ef75545c61859c08add6a74a83e0183ad]
2017-02-18 07:05:08,473 INFO org.apache.hadoop.mapred.ReduceTask: Using ShuffleConsumerPlugin: org.apache.hadoop.mapred.ReduceTask$ReduceCopier
2017-02-18 07:05:08,477 INFO org.apache.hadoop.mapred.ReduceTask: ShuffleRamManager: MemoryLimit=429496736, MaxSingleShuffleLimit=107374184
2017-02-18 07:05:08,484 WARN org.apache.hadoop.conf.Configuration: hadoop.native.lib is deprecated. Instead, use io.native.lib.available
2017-02-18 07:05:08,485 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.lzo_deflate]
2017-02-18 07:05:08,494 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.lzo_deflate]
2017-02-18 07:05:08,495 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.lzo_deflate]
2017-02-18 07:05:08,495 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.lzo_deflate]
2017-02-18 07:05:08,497 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Thread started: Thread for merging on-disk files
2017-02-18 07:05:08,497 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Thread waiting: Thread for merging on-disk files
2017-02-18 07:05:08,497 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Thread started: Thread for merging in memory files
2017-02-18 07:05:08,498 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Need another 3808 map output(s) where 0 is already in progress
2017-02-18 07:05:08,498 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Thread started: Thread for polling Map Completion Events
2017-02-18 07:05:08,498 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 0 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:05:08,693 INFO org.apache.hadoop.mapred.ReduceTask: Ignoring obsolete output of KILLED map-task: 'attempt_201609250558_700443_m_003703_1'
2017-02-18 07:05:08,693 INFO org.apache.hadoop.mapred.ReduceTask: Ignoring obsolete output of KILLED map-task: 'attempt_201609250558_700443_m_003807_1'
2017-02-18 07:05:08,693 INFO org.apache.hadoop.mapred.ReduceTask: Ignoring obsolete output of KILLED map-task: 'attempt_201609250558_700443_m_002257_1'
2017-02-18 07:05:08,693 INFO org.apache.hadoop.mapred.ReduceTask: Ignoring obsolete output of KILLED map-task: 'attempt_201609250558_700443_m_002024_1'
2017-02-18 07:05:08,693 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 22 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:05:09,700 INFO org.apache.hadoop.mapred.ReduceTask: Read 134101410 bytes from map-output for attempt_201609250558_700443_m_000205_0
2017-02-18 07:05:09,706 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Thread waiting: Thread for merging on-disk files
2017-02-18 07:05:09,733 INFO org.apache.hadoop.mapred.ReduceTask: Read 133939439 bytes from map-output for attempt_201609250558_700443_m_000040_0
2017-02-18 07:05:09,738 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Thread waiting: Thread for merging on-disk files
2017-02-18 07:05:09,811 INFO org.apache.hadoop.mapred.ReduceTask: Read 137869403 bytes from map-output for attempt_201609250558_700443_m_000014_0
2017-02-18 07:05:09,816 WARN org.apache.hadoop.conf.Configuration: io.bytes.per.checksum is deprecated. Instead, use dfs.bytes-per-checksum
2017-02-18 07:05:09,816 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1We have 3 map outputs on disk. Triggering merge of 2 files
2017-02-18 07:05:09,821 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new compressor [.lzo_deflate]
2017-02-18 07:05:09,829 INFO org.apache.hadoop.mapred.Merger: Merging 2 sorted segments
2017-02-18 07:05:09,832 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.lzo_deflate]
2017-02-18 07:05:09,837 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.lzo_deflate]
2017-02-18 07:05:09,841 INFO org.apache.hadoop.mapred.Merger: Down to the last merge-pass, with 2 segments left of total size: 268040841 bytes
2017-02-18 07:05:09,910 INFO org.apache.hadoop.mapred.ReduceTask: Read 133891406 bytes from map-output for attempt_201609250558_700443_m_000145_0
2017-02-18 07:05:10,483 INFO org.apache.hadoop.mapred.ReduceTask: Read 133842809 bytes from map-output for attempt_201609250558_700443_m_000146_0
2017-02-18 07:05:11,405 INFO org.apache.hadoop.mapred.ReduceTask: Read 133950603 bytes from map-output for attempt_201609250558_700443_m_001141_0
2017-02-18 07:05:11,557 INFO org.apache.hadoop.mapred.ReduceTask: Read 133841767 bytes from map-output for attempt_201609250558_700443_m_000132_0
2017-02-18 07:05:11,563 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 22 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:05:12,905 INFO org.apache.hadoop.mapred.ReduceTask: Read 133912704 bytes from map-output for attempt_201609250558_700443_m_000288_0
2017-02-18 07:05:13,039 INFO org.apache.hadoop.mapred.ReduceTask: Read 133960111 bytes from map-output for attempt_201609250558_700443_m_000052_0
2017-02-18 07:05:13,056 INFO org.apache.hadoop.mapred.ReduceTask: Read 133973341 bytes from map-output for attempt_201609250558_700443_m_000998_0
2017-02-18 07:05:13,234 INFO org.apache.hadoop.mapred.ReduceTask: Read 133735978 bytes from map-output for attempt_201609250558_700443_m_000142_0
2017-02-18 07:05:13,314 INFO org.apache.hadoop.mapred.ReduceTask: Read 135392612 bytes from map-output for attempt_201609250558_700443_m_000019_0
2017-02-18 07:05:13,535 INFO org.apache.hadoop.mapred.ReduceTask: Read 134014813 bytes from map-output for attempt_201609250558_700443_m_000221_0
2017-02-18 07:05:13,541 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 22 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:05:13,729 INFO org.apache.hadoop.mapred.ReduceTask: Read 16423949 bytes from map-output for attempt_201609250558_700443_m_001737_0
2017-02-18 07:05:14,303 INFO org.apache.hadoop.mapred.ReduceTask: Read 134052745 bytes from map-output for attempt_201609250558_700443_m_000175_0
14,769 INFO org.apache.hadoop.mapred.ReduceTask: Read 133946652 bytes from map-output for attempt_201609250558_700443_m_000169_0
2017-02-18 07:05:14,972 INFO org.apache.hadoop.mapred.ReduceTask: Read 133966336 bytes from map-output for attempt_201609250558_700443_m_000180_0
2017-02-18 07:05:14,977 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 22 outputs (0 slow hosts and0 dup hosts)
5:16,928 INFO org.apache.hadoop.mapred.ReduceTask: Read 134146743 bytes from map-output for attempt_201609250558_700443_m_000023_0
2017-02-18 07:05:17,120 INFO org.apache.hadoop.mapred.ReduceTask: Read 133906907 bytes from map-output for attempt_201609250558_700443_m_000214_0
2017-02-18 07:05:17,129 INFO org.apache.hadoop.mapred.ReduceTask: Read 133901826 bytes from map-output for attempt_201609250558_700443_m_000315_0
2017-02-18 07:05:20,221 INFO org.apache.hadoop.mapred.ReduceTask: Read 133972394 bytes from map-output for attempt_201609250558_700443_m_000041_0
2017-02-18 07:05:20,226 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 22 outputs (0 slow hosts and0 dup hosts)
35 INFO org.apache.hadoop.mapred.ReduceTask: Read 134017124 bytes from map-output for attempt_201609250558_700443_m_000519_0
2017-02-18 07:05:56,536 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 18 outputs (0 slow hosts and664 dup hosts)
2017-02-18 07:05:57,146 INFO org.apache.hadoop.mapred.ReduceTask: Read 133879368 bytes from map-output for attempt_201609250558_700443_m_000608_0
2017-02-18 07:05:57,680 INFO org.apache.hadoop.mapred.ReduceTask: Read 134061127 bytes from map-output for attempt_201609250558_700443_m_000756_0
2017-02-18 07:05:57,800 INFO org.apache.hadoop.mapred.ReduceTask: Read 133959190 bytes from map-output for attempt_201609250558_700443_m_000327_0
2017-02-18 07:05:58,088 INFO org.apache.hadoop.mapred.ReduceTask: Read 133771657 bytes from map-output for attempt_201609250558_700443_m_000705_0
2017-02-18 07:05:58,171 INFO org.apache.hadoop.mapred.ReduceTask: Read 133853630 bytes from map-output for attempt_201609250558_700443_m_000715_0
2017-02-18 07:05:58,622 INFO org.apache.hadoop.mapred.ReduceTask: Read 133979624 bytes from map-output for attempt_201609250558_700443_m_000136_0
2017-02-18 07:05:58,626 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 22 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:05:59,355 INFO org.apache.hadoop.mapred.ReduceTask: Read 134049141 bytes from map-output for attempt_201609250558_700443_m_000480_0
2017-02-18 07:05:59,355 INFO org.apache.hadoop.mapred.ReduceTask: Read 134026879 bytes from map-output for attempt_201609250558_700443_m_000355_0
2017-02-18 07:05:59,717 INFO org.apache.hadoop.mapred.ReduceTask: Read 133861557 bytes from map-output for attempt_201609250558_700443_m_000429_0
2017-02-18 07:05:59,836 INFO org.apache.hadoop.mapred.ReduceTask: Read 133835097 bytes from map-output for attempt_201609250558_700443_m_000718_0
2017-02-18 07:06:01,086 INFO org.apache.hadoop.mapred.ReduceTask: Read 134076607 bytes from map-output for attempt_201609250558_700443_m_000368_0
2017-02-18 07:06:01,204 INFO org.apache.hadoop.mapred.ReduceTask: Read 133872351 bytes from map-output for attempt_201609250558_700443_m_000148_0
2017-02-18 07:06:01,209 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 22 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:06:01,434 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Finished merging 2 map output files on disk of total-size 269569226. Local output file is file:/liveperson/data/server_hdfs/data/disk6/mapred/local/taskTracker/dataint/jobcache/job_201609250558_700443/attempt_201609250558_700443_r_000043_1/output/map_360.out.merged of size 267479185
2017-02-18 07:06:01,434 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1We have 226 map outputs on disk. Triggering merge of 2 files
2017-02-18 07:06:01,436 INFO org.apache.hadoop.mapred.Merger: Merging 2 sorted segments
2017-02-18 07:06:01,442 INFO org.apache.hadoop.mapred.Merger: Down to the last merge-pass, with 2 segments left of total size: 128326957 bytes
2017-02-18 07:06:01,919 INFO org.apache.hadoop.mapred.ReduceTask: Read 133945167 bytes from map-output for attempt_201609250558_700443_m_000534_0
2017-02-18 07:06:02,070 INFO org.apache.hadoop.mapred.ReduceTask: Read 133952436 bytes from map-output for attempt_201609250558_700443_m_000761_0
2017-02-18 07:06:02,102 INFO org.apache.hadoop.mapred.ReduceTask: Read 133923390 bytes from map-output for attempt_201609250558_700443_m_000325_0
2017-02-18 07:06:02,118 INFO org.apache.hadoop.mapred.ReduceTask: Read 134090486 bytes from map-output for attempt_201609250558_700443_m_000767_0
2017-02-18 07:06:02,147 INFO org.apache.hadoop.mapred.ReduceTask: Read 133953853 bytes from map-output for attempt_201609250558_700443_m_000185_0
2017-02-18 07:06:02,249 INFO org.apache.hadoop.mapred.ReduceTask: Read 133909410 bytes from map-output for attempt_201609250558_700443_m_000836_0
2017-02-18 07:06:02,430 INFO org.apache.hadoop.mapred.ReduceTask: Read 133843326 bytes from map-output for attempt_201609250558_700443_m_000375_0
2017-02-18 07:06:02,435 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 22 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:06:03,148 INFO org.apache.hadoop.mapred.ReduceTask: Read 133948959 bytes from map-output for attempt_201609250558_700443_m_000610_0
2017-02-18 07:06:03,284 INFO org.apache.hadoop.mapred.ReduceTask: Read 133845070 bytes from map-output for attempt_201609250558_700443_m_000183_0
2017-02-18 07:06:03,307 INFO org.apache.hadoop.mapred.ReduceTask: Read 133936984 bytes from map-output for attempt_201609250558_700443_m_000208_0
2017-02-18 07:06:03,471 INFO org.apache.hadoop.mapred.ReduceTask: Read 133820301 bytes from map-output for attempt_201609250558_700443_m_000340_0
2017-02-18 07:06:03,546 INFO org.apache.hadoop.mapred.ReduceTask: Read 133742005 bytes from map-output for attempt_201609250558_700443_m_000695_0
2017-02-18 07:06:03,579 INFO org.apache.hadoop.mapred.ReduceTask: Read 133829793 bytes from map-output for attempt_201609250558_700443_m_000798_0
2017-02-18 07:06:03,620 INFO org.apache.hadoop.mapred.ReduceTask: Read 133953190 bytes from map-output for attempt_201609250558_700443_m_000845_0
2017-02-18 07:06:03,632 INFO org.apache.hadoop.mapred.ReduceTask: Read 133984874 bytes from map-output for attempt_201609250558_700443_m_000400_0
2017-02-18 07:06:03,736 INFO org.apache.hadoop.mapred.ReduceTask: Read 133953236 bytes from map-output for attempt_201609250558_700443_m_000799_0
2017-02-18 07:06:03,748 INFO org.apache.hadoop.mapred.ReduceTask: Read 134071639 bytes from map-output for attempt_201609250558_700443_m_000380_0
2017-02-18 07:06:04,143 INFO org.apache.hadoop.mapred.ReduceTask: Read 133896456 bytes from map-output for attempt_201609250558_700443_m_000609_0
2017-02-18 07:06:04,150 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 22 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:06:04,849 INFO org.apache.hadoop.mapred.ReduceTask: Read 133840010 bytes from map-output for attempt_201609250558_700443_m_000612_0
2017-02-18 07:06:04,861 INFO org.apache.hadoop.mapred.ReduceTask: Read 133791007 bytes from map-output for attempt_201609250558_700443_m_000530_0
2017-02-18 07:06:04,877 INFO org.apache.hadoop.mapred.ReduceTask: Read 73873446 bytes from map-output for attempt_201609250558_700443_m_001322_0
2017-02-18 07:06:05,059 INFO org.apache.hadoop.mapred.ReduceTask: Read 133850461 bytes from map-output for attempt_201609250558_700443_m_000242_0
2017-02-18 07:06:05,134 INFO org.apache.hadoop.mapred.ReduceTask: Read 133936394 bytes from map-output for attempt_201609250558_700443_m_000771_0
org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 20 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:06:42,640 INFO org.apache.hadoop.mapred.ReduceTask: Read 63634601 bytes from map-output for attempt_201609250558_700443_m_001356_0
2017-02-18 07:06:43,056 INFO org.apache.hadoop.mapred.ReduceTask: Read 133880381 bytes from map-output for attempt_201609250558_700443_m_000950_0
2017-02-18 07:06:43,070 INFO org.apache.hadoop.mapred.ReduceTask: Read 133976503 bytes from map-output for attempt_201609250558_700443_m_001145_0
2017-02-18 07:06:43,078 INFO org.apache.hadoop.mapred.ReduceTask: Read 133971313 bytes from map-output for attempt_201609250558_700443_m_001018_0
2017-02-18 07:06:43,080 INFO org.apache.hadoop.mapred.ReduceTask: Read 133930028 bytes from map-output for attempt_201609250558_700443_m_000702_0
2017-02-18 07:06:43,106 INFO org.apache.hadoop.mapred.ReduceTask: Read 133990901 bytes from map-output for attempt_201609250558_700443_m_000842_0
2017-02-18 07:06:43,134 INFO org.apache.hadoop.mapred.ReduceTask: Read 133924816 bytes from map-output for attempt_201609250558_700443_m_001114_0
2017-02-18 07:06:43,159 INFO org.apache.hadoop.mapred.ReduceTask: Read 134041123 bytes from map-output for attempt_201609250558_700443_m_000793_0
2017-02-18 07:06:43,727 INFO org.apache.hadoop.mapred.ReduceTask: Read 134006807 bytes from map-output for attempt_201609250558_700443_m_000794_0
2017-02-18 07:06:43,732 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 20 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:06:44,452 INFO org.apache.hadoop.mapred.ReduceTask: Read 133870897 bytes from map-output for attempt_201609250558_700443_m_000958_0
2017-02-18 07:06:44,461 INFO org.apache.hadoop.mapred.ReduceTask: Read 115491377 bytes from map-output for attempt_201609250558_700443_m_001203_0
2017-02-18 07:06:44,522 INFO org.apache.hadoop.mapred.ReduceTask: Read 133974196 bytes from map-output for attempt_201609250558_700443_m_000844_0
2017-02-18 07:06:44,642 INFO org.apache.hadoop.mapred.ReduceTask: Read 133950910 bytes from map-output for attempt_201609250558_700443_m_000707_0
2017-02-18 07:06:44,696 INFO org.apache.hadoop.mapred.ReduceTask: Read 133908816 bytes from map-output for attempt_201609250558_700443_m_000802_0
2017-02-18 07:06:44,708 INFO org.apache.hadoop.mapred.ReduceTask: Read 134060194 bytes from map-output for attempt_201609250558_700443_m_001151_0
2017-02-18 07:06:44,987 INFO org.apache.hadoop.mapred.ReduceTask: Read 133969920 bytes from map-output for attempt_201609250558_700443_m_001121_0
2017-02-18 07:06:44,993 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 20 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:06:45,724 INFO org.apache.hadoop.mapred.ReduceTask: Read 134026130 bytes from map-output for attempt_201609250558_700443_m_000853_0
2017-02-18 07:06:45,764 INFO org.apache.hadoop.mapred.ReduceTask: Read 133765983 bytes from map-output for attempt_201609250558_700443_m_001031_0
2017-02-18 07:06:45,811 INFO org.apache.hadoop.mapred.ReduceTask: Read 133974062 bytes from map-output for attempt_201609250558_700443_m_000860_0
2017-02-18 07:06:45,899 INFO org.apache.hadoop.mapred.ReduceTask: Read 133879250 bytes from map-output for attempt_201609250558_700443_m_000720_0
2017-02-18 07:06:45,914 INFO org.apache.hadoop.mapred.ReduceTask: Read 134029934 bytes from map-output for attempt_201609250558_700443_m_000858_0
2017-02-18 07:06:45,940 INFO org.apache.hadoop.mapred.ReduceTask: Read 134053391 bytes from map-output for attempt_201609250558_700443_m_001011_0
2017-02-18 07:06:46,028 INFO org.apache.hadoop.mapred.ReduceTask: Read 133996519 bytes from map-output for attempt_201609250558_700443_m_001147_0
2017-02-18 07:06:46,034 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 20 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:06:46,288 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Finished merging 2 map output files on disk of total-size 184413984. Local output file is file:/liveperson/data/server_hdfs/data/disk2/mapred/local/taskTracker/dataint/jobcache/job_201609250558_700443/attempt_201609250558_700443_r_000043_1/output/map_1321.out.merged of size 182983905
2017-02-18 07:06:46,288 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1We have 443 map outputs on disk. Triggering merge of 2 files
2017-02-18 07:06:46,289 INFO org.apache.hadoop.mapred.Merger: Merging 2 sorted segments
2017-02-18 07:06:46,291 INFO org.apache.hadoop.mapred.Merger: Down to the last merge-pass, with 2 segments left of total size: 179125970 bytes
2017-02-18 07:06:46,766 INFO org.apache.hadoop.mapred.ReduceTask: Read 134059507 bytes from map-output for attempt_201609250558_700443_m_000890_0
2017-02-18 07:06:46,868 INFO org.apache.hadoop.mapred.ReduceTask: Read 133986138 bytes from map-output for attempt_201609250558_700443_m_000834_0
2017-02-18 07:06:46,932 INFO org.apache.hadoop.mapred.ReduceTask: Read 133873171 bytes from map-output for attempt_201609250558_700443_m_000733_0
2017-02-18 07:06:46,963 INFO org.apache.hadoop.mapred.ReduceTask: Read 133972780 bytes from map-output for attempt_201609250558_700443_m_000515_0
2017-02-18 07:06:46,968 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 20 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:06:47,843 INFO org.apache.hadoop.mapred.ReduceTask: Read 133974772 bytes from map-output for attempt_201609250558_700443_m_000516_0
2017-02-18 07:06:47,863 INFO org.apache.hadoop.mapred.ReduceTask: Read 133887596 bytes from map-output for attempt_201609250558_700443_m_000755_0
2017-02-18 07:06:47,865 INFO org.apache.hadoop.mapred.ReduceTask: Read 134003214 bytes from map-output for attempt_201609250558_700443_m_000942_0
2017-02-18 07:06:47,899 INFO org.apache.hadoop.mapred.ReduceTask: Read 133979609 bytes from map-output for attempt_201609250558_700443_m_000893_0
2017-02-18 07:06:47,952 INFO org.apache.hadoop.mapred.ReduceTask: Read 133965838 bytes from map-output for attempt_201609250558_700443_m_001068_0
2017-02-18 07:06:48,163 INFO org.apache.hadoop.mapred.ReduceTask: Read 133992609 bytes from map-output for attempt_201609250558_700443_m_000852_0
2017-02-18 07:06:48,208 INFO org.apache.hadoop.mapred.ReduceTask: Read 133759913 bytes from map-output for attempt_201609250558_700443_m_001042_0
2017-02-18 07:06:48,212 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 20 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:06:48,564 INFO org.apache.hadoop.mapred.ReduceTask: Read 45075609 bytes from map-output for attempt_201609250558_700443_m_001456_0
2017-02-18 07:06:49,065 INFO org.apache.hadoop.mapred.ReduceTask: Read 133857271 bytes from map-output for attempt_201609250558_700443_m_000859_0
2017-02-18 07:06:49,102 INFO org.apache.hadoop.mapred.ReduceTask: Read 95862008 bytes from map-output for attempt_201609250558_700443_m_001249_0
2017-02-18 07:06:49,130 INFO org.apache.hadoop.mapred.ReduceTask: Read 133836170 bytes from map-output for attempt_201609250558_700443_m_000765_0
2017-02-18 07:06:49,736 INFO org.apache.hadoop.mapred.ReduceTask: Read 134049362 bytes from map-output for attempt_201609250558_700443_m_000894_0
2017-02-18 07:06:49,741 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 20 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:06:50,606 INFO org.apache.hadoop.mapred.ReduceTask: Read 133878596 bytes from map-output for attempt_201609250558_700443_m_000777_0
2017-02-18 07:06:50,771 INFO org.apache.hadoop.mapred.ReduceTask: Read 134066825 bytes from map-output for attempt_201609250558_700443_m_000897_0
2017-02-18 07:06:50,778 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 20 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:06:51,533 INFO org.apache.hadoop.mapred.ReduceTask: Read 134035278 bytes from map-output for attempt_201609250558_700443_m_000899_0
2017-02-18 07:06:51,736 INFO org.apache.hadoop.mapred.ReduceTask: Read 134089846 bytes from map-output for attempt_201609250558_700443_m_000949_0
2017-02-18 07:06:51,751 INFO org.apache.hadoop.mapred.ReduceTask: Read 134134806 bytes from map-output for attempt_201609250558_700443_m_000869_0
2017-02-18 07:06:51,828 INFO org.apache.hadoop.mapred.ReduceTask: Read 133874482 bytes from map-output for attempt_201609250558_700443_m_000851_0
2017-02-18 07:06:51,880 INFO org.apache.hadoop.mapred.ReduceTask: Read 134050562 bytes from map-output for attempt_201609250558_700443_m_001057_0
2017-02-18 07:06:52,019 INFO org.apache.hadoop.mapred.ReduceTask: Read 134224557 bytes from map-output for attempt_201609250558_700443_m_000956_0
2017-02-18 07:06:52,024 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 20 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:06:52,378 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Finished merging 2 map output files on disk of total-size 180525410. Local output file is file:/liveperson/data/server_hdfs/data/disk4/mapred/local/taskTracker/dataint/jobcache/job_201609250558_700443/attempt_201609250558_700443_r_000043_1/output/map_1356.out.merged of size 179126599
2017-02-18 07:06:52,378 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1We have 466 map outputs on disk. Triggering merge of 2 files
2017-02-18 07:06:52,379 INFO org.apache.hadoop.mapred.Merger: Merging 2 sorted segments
2017-02-18 07:06:52,381 INFO org.apache.hadoop.mapred.Merger: Down to the last merge-pass, with 2 segments left of total size: 140937609 bytes
2017-02-18 07:06:52,506 INFO org.apache.hadoop.mapred.ReduceTask: Read 68720766 bytes from map-output for attempt_201609250558_700443_m_001336_0
2017-02-18 07:06:52,574 INFO org.apache.hadoop.mapred.ReduceTask: Read 85077667 bytes from map-output for attempt_201609250558_700443_m_001277_0
2017-02-18 07:06:52,737 INFO org.apache.hadoop.mapred.ReduceTask: Read 134042593 bytes from map-output for attempt_201609250558_700443_m_000900_0
2017-02-18 07:06:52,751 INFO org.apache.hadoop.mapred.ReduceTask: Read 133972796 bytes from map-output for attempt_201609250558_700443_m_000952_0
2017-02-18 07:06:52,892 INFO org.apache.hadoop.mapred.ReduceTask: Read 133786992 bytes from map-output for attempt_201609250558_700443_m_000870_0
2017-02-18 07:06:53,134 INFO org.apache.hadoop.mapred.ReduceTask: Read 133857938 bytes from map-output for attempt_201609250558_700443_m_000957_0
2017-02-18 07:06:53,139 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 20 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:06:53,390 INFO org.apache.hadoop.mapred.ReduceTask: Read 30241413 bytes from map-output for attempt_201609250558_700443_m_001562_0
2017-02-18 07:06:54,312 INFO org.apache.hadoop.mapred.ReduceTask: Read 133895474 bytes from map-output for attempt_201609250558_700443_m_000556_0
2017-02-18 07:06:54,315 INFO org.apache.hadoop.mapred.ReduceTask: Read 134038554 bytes from map-output for attempt_201609250558_700443_m_000959_0
2017-02-18 07:06:54,383 INFO org.apache.hadoop.mapred.ReduceTask: Read 134144807 bytes from map-output for attempt_201609250558_700443_m_000872_0
2017-02-18 07:06:54,439 INFO org.apache.hadoop.mapred.ReduceTask: Read 133891337 bytes from map-output for attempt_201609250558_700443_m_000892_0
2017-02-18 07:06:54,443 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 20 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:06:55,366 INFO org.apache.hadoop.mapred.ReduceTask: Read 133844280 bytes from map-output for attempt_201609250558_700443_m_000843_0
2017-02-18 07:06:55,469 INFO org.apache.hadoop.mapred.ReduceTask: Read 134022145 bytes from map-output for attempt_201609250558_700443_m_000962_0
2017-02-18 07:06:55,797 INFO org.apache.hadoop.mapred.ReduceTask: Read 134066705 bytes from map-output for attempt_201609250558_700443_m_000903_0
2017-02-18 07:06:56,097 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 19 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:06:56,804 INFO org.apache.hadoop.mapred.ReduceTask: Read 134115730 bytes from map-output for attempt_201609250558_700443_m_000960_0
2017-02-18 07:06:57,013 INFO org.apache.hadoop.mapred.ReduceTask: Read 133816335 bytes from map-output for attempt_201609250558_700443_m_000850_0
2017-02-18 07:06:57,032 INFO org.apache.hadoop.mapred.ReduceTask: Read 133862121 bytes from map-output for attempt_201609250558_700443_m_000966_0
2017-02-18 07:06:57,037 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 19 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:06:57,423 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Finished merging 2 map output files on disk of total-size 142038701. Local output file is file:/liveperson/data/server_hdfs/data/disk12/mapred/local/taskTracker/dataint/jobcache/job_201609250558_700443/attempt_201609250558_700443_r_000043_1/output/map_1456.out.merged of size 140937807
2017-02-18 07:06:57,423 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1We have 482 map outputs on disk. Triggering merge of 2 files
2017-02-18 07:06:57,424 INFO org.apache.hadoop.mapred.Merger: Merging 2 sorted segments
2017-02-18 07:06:57,429 INFO org.apache.hadoop.mapred.Merger: Down to the last merge-pass, with 2 segments left of total size: 98962171 bytes
2017-02-18 07:06:57,458 INFO org.apache.hadoop.mapred.ReduceTask: Read 63880513 bytes from map-output for attempt_201609250558_700443_m_001354_0
2017-02-18 07:06:57,518 INFO org.apache.hadoop.mapred.ReduceTask: Read 52633078 bytes from map-output for attempt_201609250558_700443_m_001406_0
2017-02-18 07:06:57,944 INFO org.apache.hadoop.mapred.ReduceTask: Read 133916826 bytes from map-output for attempt_201609250558_700443_m_000874_0
2017-02-18 07:06:58,004 INFO org.apache.hadoop.mapred.ReduceTask: Read 133982717 bytes from map-output for attempt_201609250558_700443_m_001069_0
2017-02-18 07:06:58,410 INFO org.apache.hadoop.mapred.ReduceTask: Read 133965632 bytes from map-output for attempt_201609250558_700443_m_001142_0
2017-02-18 07:06:58,432 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 19 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:06:59,310 INFO org.apache.hadoop.mapred.ReduceTask: Read 133949212 bytes from map-output for attempt_201609250558_700443_m_001150_0
2017-02-18 07:06:59,315 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 19 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:07:00,002 INFO org.apache.hadoop.mapred.ReduceTask: Read 133893312 bytes from map-output for attempt_201609250558_700443_m_000997_0
2017-02-18 07:07:00,081 INFO org.apache.hadoop.mapred.ReduceTask: Read 109781775 bytes from map-output for attempt_201609250558_700443_m_001218_0
2017-02-18 07:07:00,152 INFO org.apache.hadoop.mapred.ReduceTask: Read 134030499 bytes from map-output for attempt_201609250558_700443_m_000611_0
2017-02-18 07:07:00,226 INFO org.apache.hadoop.mapred.ReduceTask: Read 133841087 bytes from map-output for attempt_201609250558_700443_m_000896_0
2017-02-18 07:07:00,443 INFO org.apache.hadoop.mapred.ReduceTask: Read 133944269 bytes from map-output for attempt_201609250558_700443_m_001115_0
2017-02-18 07:07:00,447 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 19 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:07:00,738 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Finished merging 2 map output files on disk of total-size 99735331. Local output file is file:/liveperson/data/server_hdfs/data/disk5/mapred/local/taskTracker/dataint/jobcache/job_201609250558_700443/attempt_201609250558_700443_r_000043_1/output/map_1562.out.merged of size 98962757
2017-02-18 07:07:00,738 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1We have 492 map outputs on disk. Triggering merge of 2 files
2017-02-18 07:07:00,739 INFO org.apache.hadoop.mapred.Merger: Merging 2 sorted segments
2017-02-18 07:07:00,741 INFO org.apache.hadoop.mapred.Merger: Down to the last merge-pass, with 2 segments left of total size: 116513583 bytes
2017-02-18 07:07:01,168 INFO org.apache.hadoop.mapred.ReduceTask: Read 133951312 bytes from map-output for attempt_201609250558_700443_m_001012_0
2017-02-18 07:07:01,551 INFO org.apache.hadoop.mapred.ReduceTask: Read 134088518 bytes from map-output for attempt_201609250558_700443_m_001126_0
2017-02-18 07:07:01,557 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 19 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:07:02,270 INFO org.apache.hadoop.mapred.ReduceTask: Read 133974613 bytes from map-output for attempt_201609250558_700443_m_001013_0
2017-02-18 07:07:02,463 INFO org.apache.hadoop.mapred.ReduceTask: Read 133991680 bytes from map-output for attempt_201609250558_700443_m_000943_0
2017-02-18 07:07:02,560 INFO org.apache.hadoop.mapred.ReduceTask: Read 125637491 bytes from map-output for attempt_201609250558_700443_m_001180_0
2017-02-18 07:07:02,565 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 19 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:07:03,222 INFO org.apache.hadoop.mapred.ReduceTask: Read 133913412 bytes from map-output for attempt_201609250558_700443_m_001015_0
2017-02-18 07:07:03,469 INFO org.apache.hadoop.mapred.ReduceTask: Read 133898336 bytes from map-output for attempt_201609250558_700443_m_000948_0
2017-02-18 07:07:03,617 INFO org.apache.hadoop.mapred.ReduceTask: Read 133825858 bytes from map-output for attempt_201609250558_700443_m_001155_0
2017-02-18 07:07:03,744 INFO org.apache.hadoop.mapred.ReduceTask: Read 134058937 bytes from map-output for attempt_201609250558_700443_m_001019_0
2017-02-18 07:07:03,749 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 18 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:07:04,494 INFO org.apache.hadoop.mapred.ReduceTask: Read 133983681 bytes from map-output for attempt_201609250558_700443_m_001016_0
2017-02-18 07:07:04,845 INFO org.apache.hadoop.mapred.ReduceTask: Read 133743856 bytes from map-output for attempt_201609250558_700443_m_000657_0
2017-02-18 07:07:04,850 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 18 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:07:05,179 INFO org.apache.hadoop.mapred.ReduceTask: Read 38467745 bytes from map-output for attempt_201609250558_700443_m_001513_0
2017-02-18 07:07:05,347 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Finished merging 2 map output files on disk of total-size 117423863. Local output file is file:/liveperson/data/server_hdfs/data/disk5/mapred/local/taskTracker/dataint/jobcache/job_201609250558_700443/attempt_201609250558_700443_r_000043_1/output/map_1406.out.merged of size 116513454
2017-02-18 07:07:05,347 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1We have 503 map outputs on disk. Triggering merge of 2 files
2017-02-18 07:07:05,348 INFO org.apache.hadoop.mapred.Merger: Merging 2 sorted segments
2017-02-18 07:07:05,362 INFO org.apache.hadoop.mapred.Merger: Down to the last merge-pass, with 2 segments left of total size: 123545404 bytes
2017-02-18 07:07:05,438 INFO org.apache.hadoop.mapred.ReduceTask: Read 33094780 bytes from map-output for attempt_201609250558_700443_m_001548_0
2017-02-18 07:07:05,575 INFO org.apache.hadoop.mapred.ReduceTask: Read 133874532 bytes from map-output for attempt_201609250558_700443_m_001017_0
2017-02-18 07:07:05,581 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 18 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:07:06,380 INFO org.apache.hadoop.mapred.ReduceTask: Read 133841002 bytes from map-output for attempt_201609250558_700443_m_001020_0
2017-02-18 07:07:06,413 INFO org.apache.hadoop.mapred.ReduceTask: Read 133911924 bytes from map-output for attempt_201609250558_700443_m_001030_0
2017-02-18 07:07:06,418 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 18 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:07:07,179 INFO org.apache.hadoop.mapred.ReduceTask: Read 122004960 bytes from map-output for attempt_201609250558_700443_m_001186_0
2017-02-18 07:07:07,285 INFO org.apache.hadoop.mapred.ReduceTask: Read 133997124 bytes from map-output for attempt_201609250558_700443_m_000694_0
2017-02-18 07:07:07,441 INFO org.apache.hadoop.mapred.ReduceTask: Read 133729765 bytes from map-output for attempt_201609250558_700443_m_001032_0
2017-02-18 07:07:08,420 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 3 outputs (0 slow hosts and2095 dup hosts)
2017-02-18 07:07:10,420 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Need another 2283 map output(s) where 18 is already in progress
2017-02-18 07:07:10,420 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 0 outputs (0 slow hosts and2265 dup hosts)
2017-02-18 07:07:11,088 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Finished merging 2 map output files on disk of total-size 124510620. Local output file is file:/liveperson/data/server_hdfs/data/disk3/mapred/local/taskTracker/dataint/jobcache/job_201609250558_700443/attempt_201609250558_700443_r_000043_1/output/map_1513.out.merged of size 123545941
2017-02-18 07:07:11,088 WARN org.apache.hadoop.conf.Configuration: io.bytes.per.checksum is deprecated. Instead, use dfs.bytes-per-checksum
2017-02-18 07:07:11,088 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1We have 506 map outputs on disk. Triggering merge of 2 files
2017-02-18 07:07:11,089 INFO org.apache.hadoop.mapred.Merger: Merging 2 sorted segments
2017-02-18 07:07:11,096 INFO org.apache.hadoop.mapred.Merger: Down to the last merge-pass, with 2 segments left of total size: 132057529 bytes
2017-02-18 07:07:18,416 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Finished merging 2 map output files on disk of total-size 133089245. Local output file is file:/liveperson/data/server_hdfs/data/disk4/mapred/local/taskTracker/dataint/jobcache/job_201609250558_700443/attempt_201609250558_700443_r_000043_1/output/map_1548.out.merged of size 132057682
2017-02-18 07:07:18,416 WARN org.apache.hadoop.conf.Configuration: io.bytes.per.checksum is deprecated. Instead, use dfs.bytes-per-checksum
2017-02-18 07:07:18,416 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1We have 505 map outputs on disk. Triggering merge of 2 files
2017-02-18 07:07:18,416 INFO org.apache.hadoop.mapred.Merger: Merging 2 sorted segments
2017-02-18 07:07:18,420 INFO org.apache.hadoop.mapred.Merger: Down to the last merge-pass, with 2 segments left of total size: 226295221 bytes
2017-02-18 07:07:19,749 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new compressor [.lzo_deflate]
2017-02-18 07:07:19,750 INFO org.apache.hadoop.mapred.ReduceTask: Initiating in-memory merge with 1002 segments...
2017-02-18 07:07:19,750 INFO org.apache.hadoop.mapred.Merger: Merging 1002 sorted segments
2017-02-18 07:07:19,752 INFO org.apache.hadoop.mapred.Merger: Down to the last merge-pass, with 1 segments left of total size: 757026 bytes
2017-02-18 07:07:19,755 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Merge of the 1002 files in-memory complete. Local file is /liveperson/data/server_hdfs/data/disk2/mapred/local/taskTracker/dataint/jobcache/job_201609250558_700443/attempt_201609250558_700443_r_000043_1/output/map_17.out of size 53130
2017-02-18 07:07:19,804 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 18 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:07:19,828 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 18 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:07:20,626 INFO org.apache.hadoop.mapred.ReduceTask: Read 133877645 bytes from map-output for attempt_201609250558_700443_m_001067_0
2017-02-18 07:07:20,736 INFO org.apache.hadoop.mapred.ReduceTask: Read 133797220 bytes from map-output for attempt_201609250558_700443_m_001058_0
2017-02-18 07:07:20,865 INFO org.apache.hadoop.mapred.ReduceTask: Read 134050720 bytes from map-output for attempt_201609250558_700443_m_000711_0
2017-02-18 07:07:20,870 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Scheduled 18 outputs (0 slow hosts and0 dup hosts)
2017-02-18 07:07:21,409 INFO org.apache.hadoop.mapred.ReduceTask: Read 83437249 bytes from map-output for attempt_201609250558_700443_m_001284_0
2017-02-18 07:07:21,588 INFO org.apache.hadoop.mapred.ReduceTask: Read 133943150 bytes from map-output for attempt_201609250558_700443_m_001092_0
2017-02-18 07:07:21,829 INFO org.apache.hadoop.mapred.ReduceTask: Read 134096717 bytes from map-output for attempt_201609250558_700443_m_001059_0
2017-02-18 07:07:21,970 INFO org.apache.hadoop.mapred.ReduceTask: Read 134176685 bytes from map-output for attempt_201609250558_700443_m_001072_0
2017-02-18 07:08:17,956 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.lzo_deflate]
2017-02-18 07:08:17,957 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.lzo_deflate]
2017-02-18 07:08:17,959 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.lzo_deflate]
2017-02-18 07:08:17,960 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor [.lzo_deflate]
2017-02-18 07:08:17,964 INFO org.apache.hadoop.mapred.Merger: Merging 549 intermediate segments out of a total of 565
2017-02-18 07:24:11,004 INFO org.apache.hadoop.mapred.TaskLogsTruncater: Initializing logs' truncater with mapRetainSize=-1 and reduceRetainSize=-1
2017-02-18 07:24:11,005 FATAL org.apache.hadoop.mapred.Child: Error running child : java.lang.OutOfMemoryError: Java heap space
at org.apache.hadoop.mapred.IFile$Reader.readNextBlock(IFile.java:357)
at org.apache.hadoop.mapred.IFile$Reader.next(IFile.java:419)
at org.apache.hadoop.mapred.Merger$Segment.next(Merger.java:238)
at org.apache.hadoop.mapred.Merger$MergeQueue.adjustPriorityQueue(Merger.java:348)
at org.apache.hadoop.mapred.Merger$MergeQueue.next(Merger.java:368)
at org.apache.hadoop.mapred.Merger.writeFile(Merger.java:156)
at org.apache.hadoop.mapred.Merger$MergeQueue.merge(Merger.java:517)
at org.apache.hadoop.mapred.Merger.merge(Merger.java:142)
at org.apache.hadoop.mapred.ReduceTask$ReduceCopier.createKVIterator(ReduceTask.java:2537)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:425)
at org.apache.hadoop.mapred.Child$4.run(Child.java:268)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:396)
at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1408)
at org.apache.hadoop.mapred.Child.main(Child.java:262)

 

Posts: 642
Topics: 3
Kudos: 120
Solutions: 67
Registered: ‎08-16-2016

Re: mapreduce job that compacted daily files at HDFS failed on java heap size

I meant to make a comment on the low sort factor..  And I should've paid closer attention to the OOM exception.  It is OOM while merging files in the reducers.

 



io.sort.factor - number of segments/files to merger in each pass

mapred.reduce.parallel.copies - number of threads used to copy map output data from mappers in parallel

 

mapred.job.shuffle.input.buffer.percent - this determines how much of the reducer heap is available for the RAMManager
mapred.job.shuffle.merge.percent - this is the threshold on when it decides to merge, based on memory conusmed
mapred.inmem.merge.threshold - this is the threshold on when it decides to merge, based on number of segements

 

I'm not going to get into the details of what happens in the reducer when it is mergering.  The key is that it tries to stay in memory but can spill to disk, this can get expensive.  The process is completed in waves with the number for the sort factor determining how many files per wave.  It goes through wave after wave until it has merged all files.

 

Lets cover the number using the 8 GB reducer you tried last run.  The amount of heap used by the RAMManager is 5734.4 MB.  The threshold for starting the merge process is 3784.7 MB.  The default number for the segements threshold is 1000.

 

Based on those numbers and what is in the logs, it initiated the merge process over 1002 segments as it exceed the 1k threshold.  The merge process began on 549 of those and the OOM'd.

 

In my opinion you need to increase the io.sort.factor.  The default is 10 but I set all my cluster to 60 - 100.  This means that more files will be merging in each pass but decreases the likelihood of hiting the thresholds and trigger a merge of a lot more.

 

Here are some snippets that may help to understand what is happening.

 

2017-02-18 07:05:09,816 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1We have 3 map outputs on disk. Triggering merge of 2 files

2017-02-18 07:05:09,910 INFO org.apache.hadoop.mapred.ReduceTask: Read 133891406 bytes from map-output for attempt_201609250558_700443_m_000145_0

2017-02-18 07:06:01,434 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Finished merging 2 map output files on disk of total-size 269569226. Local output file is file:/liveperson/data/server_hdfs/data/disk6/mapred/local/taskTracker/dataint/jobcache/job_201609250558_700443/attempt_201609250558_700443_r_000043_1/output/map_360.out.merged of size 267479185

2017-02-18 07:06:01,434 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1We have 226 map outputs on disk. Triggering merge of 2 files

2017-02-18 07:06:57,423 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1We have 482 map outputs on disk. Triggering merge of 2 files

2017-02-18 07:07:00,738 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1We have 492 map outputs on disk. Triggering merge of 2 files

2017-02-18 07:07:05,347 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1We have 503 map outputs on disk. Triggering merge of 2 files

2017-02-18 07:07:10,420 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1 Need another 2283 map output(s) where 18 is already in progress

2017-02-18 07:07:11,088 INFO org.apache.hadoop.mapred.ReduceTask: attempt_201609250558_700443_r_000043_1We have 506 map outputs on disk. Triggering merge of 2 files

2017-02-18 07:07:19,750 INFO org.apache.hadoop.mapred.ReduceTask: Initiating in-memory merge with 1002 segments...

2017-02-18 07:08:17,964 INFO org.apache.hadoop.mapred.Merger: Merging 549 intermediate segments out of a total of 565

Announcements