Link to home
Start Free TrialLog in
Avatar of sharonfrench
sharonfrench

asked on

Garbage Collection - multiple sequential full gcs produces OutOfMemoryError

I am recieving an OutOfMemoryError in my tomcat logs.  I've done a bit of research, tuned parameters, logged gc etc. What I have found is that the OutOfMemoryErrors occur when the garbage collector does several back-to-back full garbage collections.  Below is the output from turning on the -Xloggc flag.

        ...
        45058.932: [GC 241734K->226138K(257164K), 0.0406180 secs]
        45069.840: [Full GC 242134K->64082K(257164K), 1.1170640 secs]
        45075.677: [GC 79503K->65708K(246232K), 0.0513280 secs]
        ...
        46517.803: [GC 189661K->189569K(246232K), 0.0840740 secs]
        46518.033: [GC 219496K->219434K(246232K), 0.0876900 secs]
        46518.287: [Full GC 245984K->168803K(246232K), 1.5587820 secs]
        46519.978: [GC 185245K->184869K(260160K), 0.1363050 secs]
        46520.281: [GC 204247K->203053K(260160K), 0.1215160 secs]
        46520.524: [GC 219385K->218914K(260160K), 0.1191330 secs]
 -->  46520.902: [Full GC 245053K->225597K(260160K), 1.8996470 secs]
 -->  46523.039: [Full GC 257946K->257356K(260160K), 0.6038950 secs]
 -->  46523.673: [Full GC 260144K->259881K(260160K), 1.3549970 secs]
 -->  46525.028: [Full GC 259881K->259881K(260160K), 0.4633640 secs]
 -->  46525.555: [Full GC 260159K->35411K(260160K), 0.5106320 secs]
        46531.403: [GC 51602K->37156K(260160K), 0.2099900 secs]
        46533.591: [GC 53348K->37075K(260160K), 0.0421670 secs]

Somewhere during the highlighted [Full GC...] lines, I get at least one OutOfMemoryError.  Because the garbage collector often runs a single time and brings the memory usage down to around 64M (see second line of output above), I believe that my real required memory is in that range, I currently have Xmx set to 256m (Could having this set so high actually be causing the problem?).   There are 4G of RAM on the machine.  

Java version information:
        # java -version
        java version "1.4.1_03"
        Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.1_03-b02)
        Java HotSpot(TM) Client VM (build 1.4.1_03-b02, mixed mode)

JAVA_OPTS
       -XX:PermSize=256m -XX:MaxPermSize=256m -Xmx256m -Xloggc:gc.log
       (PermSize and MaxPermSize are being set because at one point, we believed
        the source of the OutOfMemoryError might actually be Perm space, however,
        the addition of these settings has not changed the behavior.  Is there a flag
        similar to -Xloggc which will give me information about the Perm space?
        All of the tools that I have seen thus far are for java 5 and above).

Any insight appreciated.
Avatar of sciuriware
sciuriware

I don't know if you do, but better not call the GC explicitly.
Besides that, there's now 1.4.2_08 and NOT WITHOUT REASON!
;JOOP!
Avatar of Mick Barry
If you are getting an OOM error it is because you don't have enough spare memory available (after running gc and freeing any unreferenced objects) to meet a request for memory.
I suggest running a profiler on your code to determine where all your memory is being used.
>> OutOfMemoryErrors occur when the garbage collector does several back-to-back full garbage collections.
This normally happens when you don't have enough memory as the G.C is trying to find what ever it can (until it gives up and throw
OutOfMemoryError)

>>  -XX:PermSize=256m -XX:MaxPermSize=256m -Xmx256m -Xloggc:gc.log
PermSize is the space for stroing the classes. So normally it is much smaller and after certain point
becomes pretty static. The default size is sufficient for most uses. Are you using hot-deployment ?
Personally I think that 256m for it is way to much.
See: http://java.sun.com/docs/hotspot/gc1.4.2/faq.html (section 7 and 8) [section 8 shows how to get verbose G.C for it]

>> There are 4G of RAM on the machine.  
Then try to increase your heap size (e.g. -Xmx1024m [-Xms1024m is also recommended]).
Your program might really need it (assuming you don't have a memory leak, and if you have one then eventually even with
increasing the size you will get OOME)

>> Java HotSpot(TM) Client VM (build 1.4.1_03-b02, mixed mode)
For serverside applications you will be better of with the Server VM (using the flag -server or -Xoptimze)
There is a program that leaks memory.

Ther garbeage collecting is not the cause of your error, it is caused by it. as the amount of free memory decrease the garbage colletor get called more and more often.
Avatar of sharonfrench

ASKER

I have tried running with -Xmx1024m, and the same behavior occurs.

Perhaps someone can explain to me why I get the following behavior:
    - memory slowly grows
    - incremental garbage collection happens along the way
    - reach Xmx value (we've tried everything from 256 ->1024M and get the same result)
    - full gc reclaims some space
    - additional incrementals happen
    - reach the Xmx value
    - full gc reclaims a small portion of the space
    - repeated back to back full gcs reclaim additional space back down to around 64M

Given that the same thing occurs regardless of the Xmx value, I get the impression that there is something in the full gc logic that doesn't actually reclaim all available space, such that repeated back to back full gcs are necessary and do reclaim the space.

Because we repeatedly return to around the 64M mark after the full gcs happen, I was under the impression that this is the amount of space we actually require.  If this is the case, why the repeated back to back full-gcs.

Could there be something about tomcat in particular that is interfering with the gc?
Perhaps there is something that is happening that actually requires a large amount of memory for a small amount of time (but if so, why the same behavior regarless of the Xmx value?).

I appreciate the suggestion that we run a memory profiler, but can anyone suggest such a tool which runs against the version of the VM I am using?
     java version "1.4.1_03"
     Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.1_03-b02)
     Java HotSpot(TM) Client VM (build 1.4.1_03-b02, mixed mode)
An additional piece of information:

After the repeated full-gcs the amount of memory used drops back down to 64M, and the program continues on happily.  So although the initial full does not reclaim enough memory, subsequent full gcs (approx 1/2 second later) do.

Could it be that the the multiple full gcs are coming from distinct threads within tomcat, and it isn't until one of the threads dies (with an OOME), that enough memory is available?

Perhaps what we are really seeing is that tomcat worker threads are actually dieing off and therefore releasing memory for the others to continue on?

Again, any suggestions for memory profiling tools that will work with the 1.4.1 JVM would be appreciated.
ASKER CERTIFIED SOLUTION
Avatar of aozarov
aozarov

Link to home
membership
This solution is only available to members.
To access this solution, you must be a member of Experts Exchange.
Start Free Trial
SOLUTION
Link to home
membership
This solution is only available to members.
To access this solution, you must be a member of Experts Exchange.
Start Free Trial
Please split between aozarov and objects.
;JOOP!