JVM , CPU usage

[suja srinivasan]

Hello all,

I am facing a problem . My project , java with DB2 application is running in WAS 6.0.1 creating 100 % CPU utilization in production certain times, currently it has happened twice with in 7 days. The native_stderr.log, shows below message :

<AF[2811]: Allocation Failure. need 8208 bytes, 238208 ms since last AF>
<AF[2811]: managing allocation failure, action=1 (17720/68172368) (3447392/3588016)>
<GC(2811): GC cycle started Mon Jun 29 06:59:38 2009
<GC(2811): freed 34766936 bytes, 53% free (38232048/71760384), in 111 ms>
<GC(2811): mark: 101 ms, sweep: 10 ms, compact: 0 ms>
<GC(2811): refs: soft 0 (age >= 32), weak 7, final 633, phantom 0>
<AF[2811]: completed in 112 ms>

<AF[2812]: Allocation Failure. need 8208 bytes, 232784 ms since last AF>
<AF[2812]: managing allocation failure, action=1 (26256/68172368) (3447392/3588016)>
<GC(2812): GC cycle started Mon Jun 29 07:03:31 2009
<GC(2812): freed 34940064 bytes, 53% free (38413712/71760384), in 99 ms>
<GC(2812): mark: 88 ms, sweep: 11 ms, compact: 0 ms>
<GC(2812): refs: soft 0 (age >= 32), weak 7, final 609, phantom 0>
<AF[2812]: completed in 101 ms>

<AF[2813]: Allocation Failure. need 8208 bytes, 238911 ms since last AF>
<AF[2813]: managing allocation failure, action=1 (20880/68172368) (3447392/3588016)>
<GC(2813): mark stack overflow[5]>
<GC(2813): GC cycle started Mon Jun 29 07:07:30 2009
<GC(2813): freed 34678368 bytes, 53% free (38146640/71760384), in 124 ms>
<GC(2813): mark: 104 ms, sweep: 20 ms, compact: 0 ms>
<GC(2813): refs: soft 0 (age >= 32), weak 7, final 636, phantom 0>
<AF[2813]: completed in 126 ms>


From the admin people, we got the below info .

application on the server is doing more 20 time of GC in 1 min which is resulting in using 100% of the server CPU time. Application started normally with heap size -Xms50m -Xmx256m.

Can anyone help me out on how to proceed further. Is the problem related to heap size or any other issues?

[Duddiyanda Siraj]

Application started normally with heap size -Xms50m -Xmx256m.

Isn't this little low, try increasing the -Xmx256m to -Xmx1024m if you have enough memory or accordingly. 256m seems to be very less and thats the main reason for GC happening so often.

[suja srinivasan]

Thank you for the reply,but the support guy said that the application has been using only 70 MB it seems yet doing GC for many times. I am checking cause for the mark stack overflow in the verboseGC logs,any help is appreciated.

[Paul Sturrock]

suja srinivasan wrote:Thank you for the reply,but the support guy said that the application has been using only 70 MB it seems yet doing GC for many times. I am checking cause for the mark stack overflow in the verboseGC logs,any help is appreciated.

Does the support guy mean physical or virtual memory? Like Duddiyanda says, frequent CG usually suggests the heap is filling up and the JVM is trying to do something to it, and I agree for a proper enterprise application the heap settings do sound low.

Also have you tried the verbosegc option? This should get your JVM to tell you what is being garbage collected (I think IBM's JVM supports this option - you might want to check the docs though).

[David Newton]

256m is *very* low for a WAS6 app.

[Lucas Lech]

256 heap is one thing - very small
the way your application behaves might also be an issue - allocating many short-lived objects in a
short amount of time ? Try experimenting the GC options for sizing the space allocated to object generations -
decent read on that here: http://java.sun.com/docs/hotspot/gc5.0/gc_tuning_5.html

[Paul Sturrock]

Lucas Lech wrote:256 heap is one thing - very small
the way your application behaves might also be an issue - allocating many short-lived objects in a
short amount of time ? Try experimenting the GC options for sizing the space allocated to object generations -
decent read on that here: http://java.sun.com/docs/hotspot/gc5.0/gc_tuning_5.html

WAS will not be using the Hotspot JVM, so this is maybe better.