Mark,
Have you tried tweaking the mapred.child.java.opts property in your
mapred-site.xml?
<property>
<name>mapred.child.java.opts</name>
<value>-Xmx2048m</value>
</property>
This might help.
It looks like the fatal error came right after the log truncater fired off.
Are you outputting anything to the logs manually, or have you looked at the
user logs to see if there is anything taking up lots of room?
/ * Joey */
On Wed, May 23, 2012 at 9:35 PM, Mark Kerzner <mark.kerz...@shmsoft.com>wrote:
> Joey,
>
> my errors closely resembles this
> one<
> http://mail-archives.apache.org/mod_mbox/hadoop-mapreduce-user/201006.mbox/%3caanlktikr3df4ce-tgiphv9_-evfoed_5-t684nf4y...@mail.gmail.com%3E
> >in
> the archives. I can now be much more specific with the errors message,
> and it is quoted below. I tried -Xmx3096. But I got the same error.
>
> Thank you,
> Mark
>
>
> syslog logs
> 2012-05-23 20:04:52,349 WARN org.apache.hadoop.util.NativeCodeLoader:
> Unable to load native-hadoop library for your platform... using
> builtin-java classes where applicable
> 2012-05-23 20:04:52,519 INFO org.apache.hadoop.metrics.jvm.JvmMetrics:
> Initializing JVM Metrics with processName=MAP, sessionId=
> 2012-05-23 20:04:52,695 INFO org.apache.hadoop.util.ProcessTree: setsid
> exited with exit code 0
> 2012-05-23 20:04:52,699 INFO org.apache.hadoop.mapred.Task: Using
> ResourceCalculatorPlugin :
> org.apache.hadoop.util.LinuxResourceCalculatorPlugin@d56b37
> 2012-05-23 20:04:52,813 INFO org.apache.hadoop.mapred.MapTask: io.sort.mb =
> 100
> 2012-05-23 20:04:52,998 INFO org.apache.hadoop.mapred.MapTask: data buffer
> = 79691776/99614720
> 2012-05-23 20:04:52,998 INFO org.apache.hadoop.mapred.MapTask: record
> buffer = 262144/327680
> 2012-05-23 20:04:53,010 WARN
> org.apache.hadoop.io.compress.snappy.LoadSnappy: Snappy native library not
> loaded
> 2012-05-23 20:12:29,120 INFO org.apache.hadoop.mapred.MapTask: Spilling map
> output: buffer full= true
> 2012-05-23 20:12:29,134 INFO org.apache.hadoop.mapred.MapTask: bufstart =
> 0; bufend = 79542629; bufvoid = 99614720
> 2012-05-23 20:12:29,134 INFO org.apache.hadoop.mapred.MapTask: kvstart = 0;
> kvend = 228; length = 327680
> 2012-05-23 20:12:31,248 INFO org.apache.hadoop.mapred.MapTask: Finished
> spill 0
> 2012-05-23 20:13:01,862 INFO org.apache.hadoop.mapred.MapTask: Spilling map
> output: buffer full= true
> 2012-05-23 20:13:01,862 INFO org.apache.hadoop.mapred.MapTask: bufstart =
> 79542629; bufend = 53863940; bufvoid = 99614720
> 2012-05-23 20:13:01,862 INFO org.apache.hadoop.mapred.MapTask: kvstart =
> 228; kvend = 431; length = 327680
> 2012-05-23 20:13:03,294 INFO org.apache.hadoop.mapred.MapTask: Finished
> spill 1
> 2012-05-23 20:13:48,121 INFO org.apache.hadoop.mapred.MapTask: Spilling map
> output: buffer full= true
> 2012-05-23 20:13:48,122 INFO org.apache.hadoop.mapred.MapTask: bufstart =
> 53863940; bufend = 31696780; bufvoid = 99614720
> 2012-05-23 20:13:48,122 INFO org.apache.hadoop.mapred.MapTask: kvstart =
> 431; kvend = 861; length = 327680
> 2012-05-23 20:13:49,818 INFO org.apache.hadoop.mapred.MapTask: Finished
> spill 2
> 2012-05-23 20:15:25,618 INFO org.apache.hadoop.mapred.MapTask: Spilling map
> output: buffer full= true
> 2012-05-23 20:15:25,618 INFO org.apache.hadoop.mapred.MapTask: bufstart =
> 31696780; bufend = 10267329; bufvoid = 99614720
> 2012-05-23 20:15:25,618 INFO org.apache.hadoop.mapred.MapTask: kvstart =
> 861; kvend = 1462; length = 327680
> 2012-05-23 20:15:27,068 INFO org.apache.hadoop.mapred.MapTask: Finished
> spill 3
> 2012-05-23 20:15:53,519 INFO org.apache.hadoop.mapred.MapTask: Spilling map
> output: buffer full= true
> 2012-05-23 20:15:53,519 INFO org.apache.hadoop.mapred.MapTask: bufstart =
> 10267329; bufend = 85241086; bufvoid = 99614720
> 2012-05-23 20:15:53,519 INFO org.apache.hadoop.mapred.MapTask: kvstart =
> 1462; kvend = 1642; length = 327680
> 2012-05-23 20:15:54,760 INFO org.apache.hadoop.mapred.MapTask: Finished
> spill 4
> 2012-05-23 20:16:26,284 INFO org.apache.hadoop.mapred.MapTask: Spilling map
> output: buffer full= true
> 2012-05-23 20:16:26,284 INFO org.apache.hadoop.mapred.MapTask: bufstart =
> 85241086; bufend = 51305930; bufvoid = 99614720
> 2012-05-23 20:16:26,284 INFO org.apache.hadoop.mapred.MapTask: kvstart =
> 1642; kvend = 1946; length = 327680
> 2012-05-23 20:16:27,566 INFO org.apache.hadoop.mapred.MapTask: Finished
> spill 5
> 2012-05-23 20:16:57,046 INFO org.apache.hadoop.mapred.MapTask: Spilling map
> output: buffer full= true
> 2012-05-23 20:16:57,046 INFO org.apache.hadoop.mapred.MapTask: bufstart =
> 51305930; bufend = 31353466; bufvoid = 99614720
> 2012-05-23 20:16:57,046 INFO org.apache.hadoop.mapred.MapTask: kvstart =
> 1946; kvend = 2263; length = 327680
> 2012-05-23 20:16:58,076 INFO org.apache.hadoop.mapred.MapTask: Finished
> spill 6
> 2012-05-23 20:17:52,820 INFO org.apache.hadoop.mapred.MapTask: Spilling map
> output: buffer full= true
> 2012-05-23 20:17:52,820 INFO org.apache.hadoop.mapred.MapTask: bufstart =
> 31353466; bufend = 10945750; bufvoid = 99614720
> 2012-05-23 20:17:52,820 INFO org.apache.hadoop.mapred.MapTask: kvstart =
> 2263; kvend = 2755; length = 327680
> 2012-05-23 20:17:53,939 INFO org.apache.hadoop.mapred.MapTask: Finished
> spill 7
> 2012-05-23 20:18:19,528 INFO org.apache.hadoop.mapred.MapTask: Spilling map
> output: buffer full= true
> 2012-05-23 20:18:19,528 INFO org.apache.hadoop.mapred.MapTask: bufstart =
> 10945750; bufend = 81838103; bufvoid = 99614720
> 2012-05-23 20:18:19,528 INFO org.apache.hadoop.mapred.MapTask: kvstart =
> 2755; kvend = 2967; length = 327680
> 2012-05-23 20:18:21,145 INFO org.apache.hadoop.mapred.MapTask: Finished
> spill 8
> 2012-05-23 20:18:52,353 INFO org.apache.hadoop.mapred.MapTask: Spilling map
> output: buffer full= true
> 2012-05-23 20:18:52,353 INFO org.apache.hadoop.mapred.MapTask: bufstart =
> 81838103; bufend = 61751422; bufvoid = 99614720
> 2012-05-23 20:18:52,353 INFO org.apache.hadoop.mapred.MapTask: kvstart =
> 2967; kvend = 3202; length = 327680
> 2012-05-23 20:18:53,485 INFO org.apache.hadoop.mapred.MapTask: Finished
> spill 9
> 2012-05-23 20:19:42,993 INFO org.apache.hadoop.mapred.MapTask: Spilling map
> output: buffer full= true
> 2012-05-23 20:19:42,993 INFO org.apache.hadoop.mapred.MapTask: bufstart =
> 61751422; bufend = 38440188; bufvoid = 99614720
> 2012-05-23 20:19:42,993 INFO org.apache.hadoop.mapred.MapTask: kvstart =
> 3202; kvend = 3628; length = 327680
> 2012-05-23 20:19:44,346 INFO org.apache.hadoop.mapred.MapTask: Finished
> spill 10
> 2012-05-23 20:20:47,957 INFO org.apache.hadoop.mapred.MapTask: Spilling map
> output: buffer full= true
> 2012-05-23 20:20:47,957 INFO org.apache.hadoop.mapred.MapTask: bufstart =
> 38440188; bufend = 18376423; bufvoid = 99614720
> 2012-05-23 20:20:47,957 INFO org.apache.hadoop.mapred.MapTask: kvstart =
> 3628; kvend = 4252; length = 327680
> 2012-05-23 20:20:48,767 INFO org.apache.hadoop.mapred.MapTask: Finished
> spill 11
> 2012-05-23 20:21:19,207 INFO org.apache.hadoop.mapred.MapTask: Spilling map
> output: buffer full= true
> 2012-05-23 20:21:19,207 INFO org.apache.hadoop.mapred.MapTask: bufstart =
> 18376423; bufend = 97890160; bufvoid = 99614720
> 2012-05-23 20:21:19,207 INFO org.apache.hadoop.mapred.MapTask: kvstart =
> 4252; kvend = 4488; length = 327680
> 2012-05-23 20:21:20,176 INFO org.apache.hadoop.mapred.MapTask: Finished
> spill 12
> 2012-05-23 20:21:47,395 INFO org.apache.hadoop.mapred.MapTask: Spilling map
> output: buffer full= true
> 2012-05-23 20:21:47,395 INFO org.apache.hadoop.mapred.MapTask: bufstart =
> 97890160; bufend = 77234938; bufvoid = 99614720
> 2012-05-23 20:21:47,395 INFO org.apache.hadoop.mapred.MapTask: kvstart =
> 4488; kvend = 4771; length = 327680
> 2012-05-23 20:21:48,383 INFO org.apache.hadoop.mapred.MapTask: Finished
> spill 13
> 2012-05-23 20:22:21,086 INFO org.apache.hadoop.mapred.MapTask: Spilling map
> output: buffer full= true
> 2012-05-23 20:22:21,086 INFO org.apache.hadoop.mapred.MapTask: bufstart =
> 77234938; bufend = 52962105; bufvoid = 99614720
> 2012-05-23 20:22:21,086 INFO org.apache.hadoop.mapred.MapTask: kvstart =
> 4771; kvend = 5203; length = 327680
> 2012-05-23 20:22:21,641 INFO org.apache.hadoop.mapred.MapTask: Finished
> spill 14
> 2012-05-23 20:22:46,559 INFO org.apache.hadoop.mapred.MapTask: Starting
> flush of map output
> 2012-05-23 20:22:46,615 INFO org.apache.hadoop.mapred.MapTask: Finished
> spill 15
> 2012-05-23 20:22:47,606 INFO org.apache.hadoop.mapred.Merger: Merging 16
> sorted segments
> 2012-05-23 20:22:47,696 INFO org.apache.hadoop.mapred.Merger: Merging 7
> intermediate segments out of a total of 16
> 2012-05-23 20:22:58,083 INFO org.apache.hadoop.mapred.TaskLogsTruncater:
> Initializing logs' truncater with mapRetainSize=-1 and reduceRetainSize=-1
> 2012-05-23 20:22:58,108 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:355)
> at org.apache.hadoop.mapred.IFile$Reader.next(IFile.java:417)
> at org.apache.hadoop.mapred.Merger$Segment.next(Merger.java:220)
> at
>
> org.apache.hadoop.mapred.Merger$MergeQueue.adjustPriorityQueue(Merger.java:330)
> at org.apache.hadoop.mapred.Merger$MergeQueue.next(Merger.java:350)
> at org.apache.hadoop.mapred.Merger.writeFile(Merger.java:156)
> at org.apache.hadoop.mapred.Merger$MergeQueue.merge(Merger.java:499)
> at org.apache.hadoop.mapred.Merger$MergeQueue.merge(Merger.java:381)
> at org.apache.hadoop.mapred.Merger.merge(Merger.java:77)
> at
>
> org.apache.hadoop.mapred.MapTask$MapOutputBuffer.mergeParts(MapTask.java:1548)
> at
> org.apache.hadoop.mapred.MapTask$MapOutputBuffer.flush(MapTask.java:1180)
> at
> org.apache.hadoop.mapred.MapTask$NewOutputCollector.close(MapTask.java:582)
> at org.apache.hadoop.mapred.MapTask.runNewMapper(MapTask.java:649)
> at org.apache.hadoop.mapred.MapTask.run(MapTask.java:323)
> at org.apache.hadoop.mapred.Child$4.run(Child.java:270)
> 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:1177)
> at org.apache.hadoop.mapred.Child.main(Child.java:264)
>
> On Wed, May 23, 2012 at 2:47 PM, Joey Krabacher <jkrabac...@gmail.com
> >wrote:
>
> > My experience with this sort of problem tells me one of two things and
> > maybe both:
> >
> > 1. there are some optimizations to the code that can be made (variable
> > re-creation inside of loops, etc.)
> > 2. something has gone horribly wrong with the logic in the mapper.
> >
> > To troubleshoot I would output some log entries at specific points in the
> > mapper (be careful not to log every execution of the mapper because this
> > could cause major issues with the disk filling up and that sort of
> thing.)
> >
> > Hope that helps.
> >
> > /* Joey */
> >
> > On Wed, May 23, 2012 at 2:16 PM, Mark Kerzner <mark.kerz...@shmsoft.com
> > >wrote:
> >
> > > Hi, all,
> > >
> > > I got the exception below in the mapper. I already have my global
> Hadoop
> > > heap at 5 GB, but is there a specific other setting? Or maybe I should
> > > troubleshoot for memory?
> > >
> > > But the same application works in the IDE.
> > >
> > > Thank you!
> > >
> > > Mark
> > >
> > > *stderr logs*
> > >
> > > Exception in thread "Thread for syncLogs" java.lang.OutOfMemoryError:
> > > Java heap space
> > > at
> > java.io.BufferedOutputStream.<init>(BufferedOutputStream.java:76)
> > > at
> > java.io.BufferedOutputStream.<init>(BufferedOutputStream.java:59)
> > > at
> > > org.apache.hadoop.mapred.TaskLog.writeToIndexFile(TaskLog.java:292)
> > > at org.apache.hadoop.mapred.TaskLog.syncLogs(TaskLog.java:365)
> > > at org.apache.hadoop.mapred.Child$3.run(Child.java:157)
> > > Exception in thread "communication thread" java.lang.OutOfMemoryError:
> > > Java heap space
> > >
> > > Exception: java.lang.OutOfMemoryError thrown from the
> > > UncaughtExceptionHandler in thread "communication thread"
> > >
> >
>
