2

I'm learning and testing some graph libraries and am running into a weird problem(but this isn't specific to graphs, I am pretty sure this is general Java related). I'm getting:'java.lang.OutOfMemoryError: GC overhead limit exceeded'. I understand this error means that garbage collecting spending most of the cpu time and not returning any memory but I'm not sure how to work around this.

Basically I(for learning purposes) want to see how long it takes to create a large number of graphs node in memory. My system is running cents and I have 7 gigs of ram but the program never exceeds more than 25%(I can see via 'top') even though I'm giving it all the memory in the system by running 'java -jar jungtester.jar -Xmx7g -XX:+UseConcMarkSweepGC -XX:-UseGCOverheadLimit'(jungtester.jar is my program). It seems its not using all the available memory and dies after about 3.5 million nodes, which is weird because its just a for loops so I thought it would just be chugging along adding nodes until the memory is full.

I'm pretty new to the inner workings of the JVM so any suggestions of how to get past this would be great.

If it helps, here's the code:

import edu.uci.ics.jung.graph.DirectedGraph;
import edu.uci.ics.jung.graph.DirectedSparseGraph;

public class main {

    /**
     * @param args
     */
    public static void main(String[] args) {
        // TODO Auto-generated method stub
        System.out.println("starting...");
        long startTime = System.currentTimeMillis();
        DirectedGraph<Integer,Integer> graph = new DirectedSparseGraph<Integer, Integer>();;
        graph.addVertex(1);
        graph.addVertex(2);
        graph.addEdge(1, 1,2);

        for (int i = 0; i < 1000000; i++) {
            graph.addVertex(i);
            //System.out.println(i + " means we are " + (float) i/1000000 + "% done.");
        }
        long endTime1 = System.currentTimeMillis();
        System.out.println("done adding 1000000 in " + (endTime1 - startTime));


        for (int i = 1000001; i < 10000000; i++) {
            graph.addVertex(i);
            graph.addEdge(i, i, i-1000000);
            System.out.println(i + " means we are " + (float) i/1000000000 + "% done.");
        }

        long endTime = System.currentTimeMillis();

        System.out.println("It took " + (endTime - startTime));
    }

}

UPDATE: I got it to work, I'm not sure why but order matters. My above command didn't take anything after I put -jar, but when I added the -jar to the end it seems to work.

Community
  • 1
  • 1
Lostsoul
  • 25,013
  • 48
  • 144
  • 239
  • 1
    Use jconsole (if you have X available) to monitor the JVM as your application is running, it will show you what's going on. Top isn't nearly as granular in showing you JVM real-time statistics as jconsole is. – robertvoliva Mar 29 '12 at 14:53
  • 1
    Are you running this on a 32-bit or 64-bit machine? 32-bit systems are not able to use 7G of RAM. – Péter Török Mar 29 '12 at 14:54
  • 2
    @PéterTörök - That is true, but if you use `-Xmx7g` on a 32 bit machine, the JVM will not start. So I don't think this is the problem. – Stephen C Mar 29 '12 at 15:00
  • Sorry, I'm running it on the command line(I don't have graphics avail) @PéterTörök its a 64-bit machine. – Lostsoul Mar 29 '12 at 15:01
  • @learningJava Is it a 64 bit JVM? – mdakin Mar 29 '12 at 15:14
  • @learningJava You may want to take a heap dump when you hit the GC overhead limit reached. The heap dump should be ~7G if it is you know you're actually using the entire heap and not the 25% you are thinking – John Vint Mar 29 '12 at 15:40

2 Answers2

1

I'm by no means an expert, but this would be my guess.

If it wouldn't do GC until it was completely out of memory, it would ...

A) ... consume an incredibly large / unnecessarily large amount of memory

B) ... suffer from a huge performance impact the time it actualy had to do the GC.

So, it does perform GC before the memory is out, and this GC process just can't keep up with the millions of nodes you're creating and throwing away in a possibly deep object graph.

aioobe
  • 413,195
  • 112
  • 811
  • 826
  • But doesn't -XX:-UseGCOverheadLimit tell it not to do GC at all? In the question I linked people wrote that it would cause the issue not to be checked. Also, you triggered a few more questions, how does it judge something is too large or unnecessarily? For all it knows I could be using the data somewhere else? Is there a way to shut this off? I'm just so confused by the background tasks the JVM is doing right sorry if the questions don't make sense. – Lostsoul Mar 29 '12 at 15:04
  • Good point with the `-UseGCOverheadLimit`. I don't have a good answer. Regarding your follow-up questions: These things can also be finetuned using `-XX`-options. You have for instance `-XX:MaxHeapFreeRatio=70` ([source](http://www.oracle.com/technetwork/java/javase/tech/vmoptions-jsp-140102.html)). – aioobe Mar 29 '12 at 15:08
1

I think that what is happening here is an unfortunate consequence of the nature of your program and the GC settings that you have chosen

Basically, your program is creating huge numbers of nodes very quickly, and (at looks like) never releasing any of them until the very end of the run. So each time that the GC runs, it has to trace and evacuate essentially every object in the "from" space that it is working on. This work is proportional to the number of objects in the space. As your application progresses, the spaces keep getting bigger and the numbers of objects keep getting bigger, and a larger and larger percentage of your time is spent by the GC moving the objects around. This is possibly exacerbated by the fact that you are running the CMS collector which has greater overheads than the throughput collector.

This possibly explains why you only appear to be using 25% of the available memory. But it is also possible that the numbers you are getting from top are misleading. I would be more inclined to believe numbers that you get from jconsole, et al.

I'd also turn on GC logging, look to see if there is something strange going on. For instance, your application's behaviour may be overwhelming the CMS collector, and causing the JVM to switch to the stop-the-world GC. (I vaguely recall hearing that you take a big performance hit when this happens, and that could be enough to cause the JVM to hit the GC overhead limit.)


So what could you do to improve the behaviour of the JVM running this application. I'd suggest the following:

  • Try using the throughput collector instead of CMS.
  • If you have a JVM that is capable, try using the new G1 collector.
  • Set the initial heap size to 7gigabytes too: use -Xms7g.

A careful analysis of the GC logs may be able to suggest other things to try.

But probably the best thing you could do is to ditch this (I hope) unrealistic benchmark.

Stephen C
  • 698,415
  • 94
  • 811
  • 1,216
  • You maybe right. What I noticed was that within a min top ramps up to 25% memory usage and then a min later it gives me the error. I'll research on how to do logging and I'll try it without the CMS collector(I used it because I read in the linked question that it may allow me use more memory) – Lostsoul Mar 29 '12 at 15:36