Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Blocker Blocker
    • Resolution: Fixed
    • Affects Version/s: 0.17.0
    • Fix Version/s: 0.18.0
    • Component/s: None
    • Labels:
      None
    • Hadoop Flags:
      Reviewed

      Description

      The JobTracker on our 0.17.0 installation runs out of heap space rather quickly, with less than 100 jobs (at one time even after just 16 jobs).
      Running in 64-bit mode with larger heap space does not help – it will use up all available RAM.

      2008-06-28 05:17:06,661 INFO org.apache.hadoop.ipc.Server: IPC Server handler 62 on 9020, call he
      artbeat(org.apache.hadoop.mapred.TaskTrackerStatus@6f81c6, false, true, 17384) from xxx.xxx.xxx.xxx
      :51802: error: java.io.IOException: java.lang.OutOfMemoryError: GC overhead limit exceeded
      java.io.IOException: java.lang.OutOfMemoryError: GC overhead limit exceeded

      1. memory-dump.txt
        13 kB
        Amareshwari Sriramadasu
      2. patch-3670-0.17.txt
        3 kB
        Amareshwari Sriramadasu
      3. patch-3670-0.17-v2.txt
        3 kB
        Amareshwari Sriramadasu
      4. patch-3670.txt
        2 kB
        Amareshwari Sriramadasu
      5. patch-3670.txt
        2 kB
        Amareshwari Sriramadasu

        Activity

        Hide
        Hudson added a comment -
        Show
        Hudson added a comment - Integrated in Hadoop-trunk #581 (See http://hudson.zones.apache.org/hudson/job/Hadoop-trunk/581/ )
        Hide
        Devaraj Das added a comment -

        I just committed this. Thanks, Amareshwari!

        Show
        Devaraj Das added a comment - I just committed this. Thanks, Amareshwari!
        Hide
        Hadoop QA added a comment -

        -1 overall. Here are the results of testing the latest attachment
        http://issues.apache.org/jira/secure/attachment/12386035/patch-3670.txt
        against trunk revision 677127.

        +1 @author. The patch does not contain any @author tags.

        -1 tests included. The patch doesn't appear to include any new or modified tests.
        Please justify why no tests are needed for this patch.

        +1 javadoc. The javadoc tool did not generate any warning messages.

        +1 javac. The applied patch does not increase the total number of javac compiler warnings.

        +1 findbugs. The patch does not introduce any new Findbugs warnings.

        +1 release audit. The applied patch does not increase the total number of release audit warnings.

        +1 core tests. The patch passed core unit tests.

        +1 contrib tests. The patch passed contrib unit tests.

        Test results: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2868/testReport/
        Findbugs warnings: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2868/artifact/trunk/build/test/findbugs/newPatchFindbugsWarnings.html
        Checkstyle results: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2868/artifact/trunk/build/test/checkstyle-errors.html
        Console output: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2868/console

        This message is automatically generated.

        Show
        Hadoop QA added a comment - -1 overall. Here are the results of testing the latest attachment http://issues.apache.org/jira/secure/attachment/12386035/patch-3670.txt against trunk revision 677127. +1 @author. The patch does not contain any @author tags. -1 tests included. The patch doesn't appear to include any new or modified tests. Please justify why no tests are needed for this patch. +1 javadoc. The javadoc tool did not generate any warning messages. +1 javac. The applied patch does not increase the total number of javac compiler warnings. +1 findbugs. The patch does not introduce any new Findbugs warnings. +1 release audit. The applied patch does not increase the total number of release audit warnings. +1 core tests. The patch passed core unit tests. +1 contrib tests. The patch passed contrib unit tests. Test results: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2868/testReport/ Findbugs warnings: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2868/artifact/trunk/build/test/findbugs/newPatchFindbugsWarnings.html Checkstyle results: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2868/artifact/trunk/build/test/checkstyle-errors.html Console output: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2868/console This message is automatically generated.
        Hide
        Amareshwari Sriramadasu added a comment -

        Patch that applies to both trunk and 0.18

        Show
        Amareshwari Sriramadasu added a comment - Patch that applies to both trunk and 0.18
        Hide
        Amareshwari Sriramadasu added a comment -

        Canceling patch to change TIP.clearSplit() to clear bytes in the split, instead of making the split null. Because, In 0.18, the webUI shows the split locations for the map, which would be lost for the completed jobs by making them null.

        Show
        Amareshwari Sriramadasu added a comment - Canceling patch to change TIP.clearSplit() to clear bytes in the split, instead of making the split null. Because, In 0.18, the webUI shows the split locations for the map, which would be lost for the completed jobs by making them null.
        Hide
        Hadoop QA added a comment -

        -1 overall. Here are the results of testing the latest attachment
        http://issues.apache.org/jira/secure/attachment/12385383/patch-3670.txt
        against trunk revision 674645.

        +1 @author. The patch does not contain any @author tags.

        -1 tests included. The patch doesn't appear to include any new or modified tests.
        Please justify why no tests are needed for this patch.

        +1 javadoc. The javadoc tool did not generate any warning messages.

        +1 javac. The applied patch does not increase the total number of javac compiler warnings.

        +1 findbugs. The patch does not introduce any new Findbugs warnings.

        +1 release audit. The applied patch does not increase the total number of release audit warnings.

        -1 core tests. The patch failed core unit tests.

        -1 contrib tests. The patch failed contrib unit tests.

        Test results: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2805/testReport/
        Findbugs warnings: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2805/artifact/trunk/build/test/findbugs/newPatchFindbugsWarnings.html
        Checkstyle results: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2805/artifact/trunk/build/test/checkstyle-errors.html
        Console output: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2805/console

        This message is automatically generated.

        Show
        Hadoop QA added a comment - -1 overall. Here are the results of testing the latest attachment http://issues.apache.org/jira/secure/attachment/12385383/patch-3670.txt against trunk revision 674645. +1 @author. The patch does not contain any @author tags. -1 tests included. The patch doesn't appear to include any new or modified tests. Please justify why no tests are needed for this patch. +1 javadoc. The javadoc tool did not generate any warning messages. +1 javac. The applied patch does not increase the total number of javac compiler warnings. +1 findbugs. The patch does not introduce any new Findbugs warnings. +1 release audit. The applied patch does not increase the total number of release audit warnings. -1 core tests. The patch failed core unit tests. -1 contrib tests. The patch failed contrib unit tests. Test results: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2805/testReport/ Findbugs warnings: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2805/artifact/trunk/build/test/findbugs/newPatchFindbugsWarnings.html Checkstyle results: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2805/artifact/trunk/build/test/checkstyle-errors.html Console output: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2805/console This message is automatically generated.
        Hide
        Amareshwari Sriramadasu added a comment -

        Patch for the trunk.

        Show
        Amareshwari Sriramadasu added a comment - Patch for the trunk.
        Hide
        Amareshwari Sriramadasu added a comment -

        The MapTask constructor does a deep copy of the split, which is not necessary. The attached patch removes deep copy and makes it an assignment, along with the changes in the first patch.

        Show
        Amareshwari Sriramadasu added a comment - The MapTask constructor does a deep copy of the split, which is not necessary. The attached patch removes deep copy and makes it an assignment, along with the changes in the first patch.
        Hide
        Amareshwari Sriramadasu added a comment - - edited

        Here is a patch for branch 0.17, which makes the references to RawSplit as null in MapTask and JIP, after the job completion.
        I've not tested the patch yet.

        Christian, can you please use this patch and see if it is still failing with OutOfMemory error?
        And also, can you try making mapred.jobtracker.completeuserjobs.maximum lower?

        Show
        Amareshwari Sriramadasu added a comment - - edited Here is a patch for branch 0.17, which makes the references to RawSplit as null in MapTask and JIP, after the job completion. I've not tested the patch yet. Christian, can you please use this patch and see if it is still failing with OutOfMemory error? And also, can you try making mapred.jobtracker.completeuserjobs.maximum lower?
        Hide
        Amareshwari Sriramadasu added a comment -

        The split in Maptask Object can be made null once it is serialized, since that is no more needed once the LaunchTaskAction is sent out.

        For cleaning splits in TIP[] in JobInProgress, we cannot remove the split once the tip is successful, because the map may be re-executed if the reducer is not able to fetch the map output. So, we should clean up TIP[] of maps in JIP.garbageCollect(), once the job is done.

        Thoughts?

        Show
        Amareshwari Sriramadasu added a comment - The split in Maptask Object can be made null once it is serialized, since that is no more needed once the LaunchTaskAction is sent out. For cleaning splits in TIP[] in JobInProgress, we cannot remove the split once the tip is successful, because the map may be re-executed if the reducer is not able to fetch the map output. So, we should clean up TIP[] of maps in JIP.garbageCollect(), once the job is done. Thoughts?
        Hide
        Amareshwari Sriramadasu added a comment -

        Looking at the hprof file, the following are the observations:
        Job tracker's memory has reached 2.4GB, in which byte[] objects are contributing to 79% of the memory. i.e. 1.88GB.
        Detailed allocation of byte[] objects contributing the high memory is shown below.

            +---org.apache.hadoop.io.BytesWritable    |   120,168  99 %  |   1,822,933,232  97 %  |
            | +---org.apache.hadoop.mapred.JobClient$RawSplit    |    63,536  53 %  |     986,661,560  52 %  |
            | | +---org.apache.hadoop.mapred.TaskInProgress    |    60,725  50 %  |     936,490,832  50 %  |
            | | | +---org.apache.hadoop.mapred.TaskInProgress[]    |    60,478  50 %  |     936,433,528  50 %  |
            | | | | +---org.apache.hadoop.mapred.JobInProgress    |    60,478  50 %  |     936,433,528  50 %  |
            | | | |   +---<Objects are retained by instances of several classes>    |    60,478  50 %  |     936,433,528  50 %  |
            | | | |     +---java.lang.Object[]   |                  |                        |
            | | | |     +---org.apache.hadoop.mapred.TaskInProgress    |                  |                        |
            | | | |     +---java.util.TreeMap$Entry    |                  |                        |
            | +---org.apache.hadoop.mapred.MapTask    |    56,629  47 %  |     836,271,336  44 %  |
            | | +---<Objects are retained by instances of several classes>    |    56,629  47 %  |     836,271,336  44 %  |
            | |   +---java.util.TreeMap$Entry    |                  |                        |
            | |   +---org.apache.hadoop.mapred.Task$FileSystemStatisticUpdater    |                  |                        |
        

        Clearly, the RawSplits in TIP are contributing almost 1GB. And MapTask objects are contributing another 1GB .
        Again, In MapTask, the BytesWritable split is contributing to the high memory.

        Show
        Amareshwari Sriramadasu added a comment - Looking at the hprof file, the following are the observations: Job tracker's memory has reached 2.4GB, in which byte[] objects are contributing to 79% of the memory. i.e. 1.88GB. Detailed allocation of byte[] objects contributing the high memory is shown below. +---org.apache.hadoop.io.BytesWritable | 120,168 99 % | 1,822,933,232 97 % | | +---org.apache.hadoop.mapred.JobClient$RawSplit | 63,536 53 % | 986,661,560 52 % | | | +---org.apache.hadoop.mapred.TaskInProgress | 60,725 50 % | 936,490,832 50 % | | | | +---org.apache.hadoop.mapred.TaskInProgress[] | 60,478 50 % | 936,433,528 50 % | | | | | +---org.apache.hadoop.mapred.JobInProgress | 60,478 50 % | 936,433,528 50 % | | | | | +---<Objects are retained by instances of several classes> | 60,478 50 % | 936,433,528 50 % | | | | | +---java.lang.Object[] | | | | | | | +---org.apache.hadoop.mapred.TaskInProgress | | | | | | | +---java.util.TreeMap$Entry | | | | +---org.apache.hadoop.mapred.MapTask | 56,629 47 % | 836,271,336 44 % | | | +---<Objects are retained by instances of several classes> | 56,629 47 % | 836,271,336 44 % | | | +---java.util.TreeMap$Entry | | | | | +---org.apache.hadoop.mapred.Task$FileSystemStatisticUpdater | | | Clearly, the RawSplits in TIP are contributing almost 1GB. And MapTask objects are contributing another 1GB . Again, In MapTask, the BytesWritable split is contributing to the high memory.
        Hide
        Amareshwari Sriramadasu added a comment -

        Attaching the memory dump analysis.

        Show
        Amareshwari Sriramadasu added a comment - Attaching the memory dump analysis.
        Hide
        Owen O'Malley added a comment -

        In Hadoop 0.18, the hadoop scripts change the current working directory to $HADOOP_HOME to prevent this kind of confusion.

        Show
        Owen O'Malley added a comment - In Hadoop 0.18, the hadoop scripts change the current working directory to $HADOOP_HOME to prevent this kind of confusion.
        Hide
        Christian Kunz added a comment -

        This helped – I finaly found the dump file, not in cwd, but in the home directory of the JobTracker user.

        Show
        Christian Kunz added a comment - This helped – I finaly found the dump file, not in cwd, but in the home directory of the JobTracker user.
        Hide
        Arun C Murthy added a comment -

        You should also see a log msg in stderr which notes where the dump is placed...

        The JT's stderr, of course, is redirected to the jobtracker.out file.

        The message is usually along the lines of:
        "Dumping heap to <file>" or some such.

        Show
        Arun C Murthy added a comment - You should also see a log msg in stderr which notes where the dump is placed... The JT's stderr, of course, is redirected to the jobtracker .out file. The message is usually along the lines of: "Dumping heap to <file>" or some such.
        Hide
        Arun C Murthy added a comment -

        Unfortunately, for some reason, I could not find a heap dump file.

        Christian, usually the hprof dump file is in placed in the cwd of the running java process. You should also see a log msg in stderr which notes where the dump is placed...

        Show
        Arun C Murthy added a comment - Unfortunately, for some reason, I could not find a heap dump file. Christian, usually the hprof dump file is in placed in the cwd of the running java process. You should also see a log msg in stderr which notes where the dump is placed...
        Hide
        Christian Kunz added a comment -

        Because of the suspicion that GC was badly configured, I restarted JobTracker in 32-bit mode with default configuration, but with the options suggested by Owen:

        HADOOP_OPTS="-server -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+HeapDumpOnOutOfMemoryError"

        HADOOP_HEAPSIZE=2500

        RAM: 8GB

        The cluster has 200 nodes, jobs have typically at most 4000 maps and less than 400 reduces, but often 2 or 3 jobs run simultaneously.

        The JobTracker's memory footprint increased slowly close up to 2.4GB, and then after about 100 jobs a new job initialization failed:

        Job initialization failed:
        java.lang.OutOfMemoryError: Java heap space
        at org.apache.hadoop.io.BytesWritable.setCapacity(BytesWritable.java:97)
        at org.apache.hadoop.io.BytesWritable.setSize(BytesWritable.java:76)
        at org.apache.hadoop.io.BytesWritable.readFields(BytesWritable.java:131)
        at org.apache.hadoop.mapred.JobClient$RawSplit.readFields(JobClient.java:797)
        at org.apache.hadoop.mapred.JobClient.readSplitFile(JobClient.java:863)
        at org.apache.hadoop.mapred.JobInProgress.initTasks(JobInProgress.java:308)
        at org.apache.hadoop.mapred.JobTracker$JobInitThread.run(JobTracker.java:418)
        at java.lang.Thread.run(Thread.java:619)

        From then on JobTracker became unresponsive, running GC at full speed.

        Unfortunately, for some reason, I could not find a heap dump file.

        Typical GCtimestamp output (it looks as if from a certain point on full GC is running repeatedly with hardly any gain)

        33015.775: [GC [PSYoungGen: 154229K->55555K(188352K)] 2344017K->2254659K(2463936K), 0.0688110 secs]
        33027.318: [GC [PSYoungGen: 149123K->54221K(189632K)] 2348227K->2259655K(2465216K), 0.0603560 secs]
        33046.658: [GC [PSYoungGen: 149069K->18692K(189632K)] 2354503K->2259525K(2465216K), 0.0683130 secs]
        33056.766: [GC [PSYoungGen: 113537K->20288K(189632K)] 2354370K->2269026K(2465216K), 0.0415790 secs]
        33056.808: [Full GC [PSYoungGen: 20288K->0K(189632K)] [PSOldGen: 2248737K->2268912K(2275584K)] 2269026K->2268
        912K(2465216K) [PSPermGen: 11448K->11448K(16384K)], 1.7332610 secs]
        33081.667: [Full GC [PSYoungGen: 94848K->0K(189632K)] [PSOldGen: 2268912K->2272832K(2275584K)] 2363760K->2272
        832K(2465216K) [PSPermGen: 11448K->11448K(16384K)], 1.7537480 secs]
        33096.646: [Full GC [PSYoungGen: 94848K->0K(189632K)] [PSOldGen: 2272832K->2262529K(2275584K)] 2367680K->2262
        529K(2465216K) [PSPermGen: 11448K->11443K(16384K)], 3.2210170 secs]
        33120.150: [Full GC [PSYoungGen: 94848K->0K(189632K)] [PSOldGen: 2262529K->2267044K(2275584K)] 2357377K->2267
        044K(2465216K) [PSPermGen: 11443K->11443K(16384K)], 1.7487610 secs]
        33136.949: [Full GC [PSYoungGen: 94848K->0K(189632K)] [PSOldGen: 2267044K->2272689K(2275584K)] 23618

        Show
        Christian Kunz added a comment - Because of the suspicion that GC was badly configured, I restarted JobTracker in 32-bit mode with default configuration, but with the options suggested by Owen: HADOOP_OPTS="-server -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+HeapDumpOnOutOfMemoryError" HADOOP_HEAPSIZE=2500 RAM: 8GB The cluster has 200 nodes, jobs have typically at most 4000 maps and less than 400 reduces, but often 2 or 3 jobs run simultaneously. The JobTracker's memory footprint increased slowly close up to 2.4GB, and then after about 100 jobs a new job initialization failed: Job initialization failed: java.lang.OutOfMemoryError: Java heap space at org.apache.hadoop.io.BytesWritable.setCapacity(BytesWritable.java:97) at org.apache.hadoop.io.BytesWritable.setSize(BytesWritable.java:76) at org.apache.hadoop.io.BytesWritable.readFields(BytesWritable.java:131) at org.apache.hadoop.mapred.JobClient$RawSplit.readFields(JobClient.java:797) at org.apache.hadoop.mapred.JobClient.readSplitFile(JobClient.java:863) at org.apache.hadoop.mapred.JobInProgress.initTasks(JobInProgress.java:308) at org.apache.hadoop.mapred.JobTracker$JobInitThread.run(JobTracker.java:418) at java.lang.Thread.run(Thread.java:619) From then on JobTracker became unresponsive, running GC at full speed. Unfortunately, for some reason, I could not find a heap dump file. Typical GCtimestamp output (it looks as if from a certain point on full GC is running repeatedly with hardly any gain) 33015.775: [GC [PSYoungGen: 154229K->55555K(188352K)] 2344017K->2254659K(2463936K), 0.0688110 secs] 33027.318: [GC [PSYoungGen: 149123K->54221K(189632K)] 2348227K->2259655K(2465216K), 0.0603560 secs] 33046.658: [GC [PSYoungGen: 149069K->18692K(189632K)] 2354503K->2259525K(2465216K), 0.0683130 secs] 33056.766: [GC [PSYoungGen: 113537K->20288K(189632K)] 2354370K->2269026K(2465216K), 0.0415790 secs] 33056.808: [Full GC [PSYoungGen: 20288K->0K(189632K)] [PSOldGen: 2248737K->2268912K(2275584K)] 2269026K->2268 912K(2465216K) [PSPermGen: 11448K->11448K(16384K)] , 1.7332610 secs] 33081.667: [Full GC [PSYoungGen: 94848K->0K(189632K)] [PSOldGen: 2268912K->2272832K(2275584K)] 2363760K->2272 832K(2465216K) [PSPermGen: 11448K->11448K(16384K)] , 1.7537480 secs] 33096.646: [Full GC [PSYoungGen: 94848K->0K(189632K)] [PSOldGen: 2272832K->2262529K(2275584K)] 2367680K->2262 529K(2465216K) [PSPermGen: 11448K->11443K(16384K)] , 3.2210170 secs] 33120.150: [Full GC [PSYoungGen: 94848K->0K(189632K)] [PSOldGen: 2262529K->2267044K(2275584K)] 2357377K->2267 044K(2465216K) [PSPermGen: 11443K->11443K(16384K)] , 1.7487610 secs] 33136.949: [Full GC [PSYoungGen: 94848K->0K(189632K)] [PSOldGen: 2267044K->2272689K(2275584K)] 23618
        Hide
        Doug Cutting added a comment -

        1GB seems like a big "NewSize". What is HADOOP_HEAPSIZE set to? How much memory do you have on the box?

        Show
        Doug Cutting added a comment - 1GB seems like a big "NewSize". What is HADOOP_HEAPSIZE set to? How much memory do you have on the box?
        Hide
        Devaraj Das added a comment -

        Could you pls let us know once you get the heap dump. Also, how many nodes does the cluster have?

        Show
        Devaraj Das added a comment - Could you pls let us know once you get the heap dump. Also, how many nodes does the cluster have?
        Hide
        Amar Kamat added a comment -

        What is the heap size? Roughly how many tasks are there (in total)?

        Show
        Amar Kamat added a comment - What is the heap size? Roughly how many tasks are there (in total)?
        Hide
        Owen O'Malley added a comment -

        Could you run with:

        -XX:+HeapDumpOnOutOfMemoryError -XX:+PrintGCDetails -XX:+PrintGCTimeStamps
        

        That will give us a lot of info about what is going wrong.

        Show
        Owen O'Malley added a comment - Could you run with: -XX:+HeapDumpOnOutOfMemoryError -XX:+PrintGCDetails -XX:+PrintGCTimeStamps That will give us a lot of info about what is going wrong.
        Hide
        Christian Kunz added a comment -

        HADOOP_OPTS="-server -XX:+UseParallelGC -XX:ParallelGCThreads=4 -XX:NewSize=1G -XX:MaxNewSize=1G"

        Show
        Christian Kunz added a comment - HADOOP_OPTS="-server -XX:+UseParallelGC -XX:ParallelGCThreads=4 -XX:NewSize=1G -XX:MaxNewSize=1G"
        Hide
        Owen O'Malley added a comment -

        What was your garbage collector configured like?

        Show
        Owen O'Malley added a comment - What was your garbage collector configured like?

          People

          • Assignee:
            Amareshwari Sriramadasu
            Reporter:
            Christian Kunz
          • Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development