Skip to main content

Frequent Full GC?

8 replies [Last post]
tsaik
Offline
Joined: 2009-02-24

Hi,

I am running JRE 5 on a 2 processors linux server with 8G RAM. The java app is running with Xms=Xmx=1024m and only optional flags for printing gc info.

I am running into a situation where the app would completely pause for several seconds while GC is running. The log information output indicates GC/Full GC is running every other few seconds.

I thought Full GC occurs only when Tenured space usage goes over 60%. Why is Full GC occurring so frequently considering there plenty of free memory available in Tenured space?

INFO | jvm 1 | 2009/02/25 06:17:20 | 227.276: [GC
INFO | jvm 1 | 2009/02/25 06:17:20 | [PSYoungGen: 305852K->43642K(195648K)] 407995K->150863K(894720K), 0.1175680 secs]
INFO | jvm 1 | 2009/02/25 06:17:20 | 227.395: [GC
INFO | jvm 1 | 2009/02/25 06:17:20 | [PSYoungGen: 44069K->34425K(250752K)] 151290K->151017K(949824K), 0.1063990 secs]
INFO | jvm 1 | 2009/02/25 06:17:20 | 227.502: [Full GC
INFO | jvm 1 | 2009/02/25 06:17:20 | [PSYoungGen: 34425K->0K(250752K)] [PSOldGen: 116592K->150551K(699072K)] 151017K->150551K(949824K) [PSPermGen: 43975K->43975K(44096K)], 0.6086530 secs]
INFO | jvm 1 | 2009/02/25 06:17:20 | 228.115: [GC [PSYoungGen: 1977K->0K(245824K)] 152529K->150551K(944896K), 0.0036460 secs]
INFO | jvm 1 | 2009/02/25 06:17:20 | 228.118: [Full GC
INFO | jvm 1 | 2009/02/25 06:17:21 | [PSYoungGen: 0K->0K(245824K)] [PSOldGen: 150551K->150551K(699072K)] 150551K->150551K(944896K) [PSPermGen: 43975K->43975K(44096K)], 0.5450290 secs]
INFO | jvm 1 | 2009/02/25 06:17:21 | 228.668: [GC [PSYoungGen: 422K->0K(150144K)] 150973K->150551K(849216K), 0.0033150 secs]
INFO | jvm 1 | 2009/02/25 06:17:21 | 228.671: [Full GC
INFO | jvm 1 | 2009/02/25 06:17:22 | [PSYoungGen: 0K->0K(150144K)] [PSOldGen: 150551K->150551K(699072K)] 150551K->150551K(849216K) [PSPermGen: 43975K->43975K(44096K)], 0.5422360 secs]
INFO | jvm 1 | 2009/02/25 06:17:22 | 229.219: [GC [PSYoungGen: 422K->32K(247808K)] 150973K->150583K(946880K), 0.0034170 secs]
INFO | jvm 1 | 2009/02/25 06:17:22 | 229.223: [Full GC
INFO | jvm 1 | 2009/02/25 06:17:22 | [PSYoungGen: 32K->0K(247808K)] [PSOldGen: 150551K->132884K(699072K)] 150583K->132884K(946880K) [PSPermGen: 43975K->43860K(44096K)], 0.7151570 secs]
INFO | jvm 1 | 2009/02/25 06:17:22 | 229.941: [GC [PSYoungGen: 1494K->32K(248000K)] 134378K->132916K(947072K), 0.0033180 secs]
INFO | jvm 1 | 2009/02/25 06:17:22 | 229.944: [Full GC
INFO | jvm 1 | 2009/02/25 06:17:23 | [PSYoungGen: 32K->0K(248000K)] [PSOldGen: 132884K->132886K(699072K)] 132916K->132886K(947072K) [PSPermGen: 43860K->43860K(44096K)], 0.5406070 secs]
INFO | jvm 1 | 2009/02/25 06:17:23 | 230.487: [GC [PSYoungGen: 0K->0K(250560K)] 132886K->132886K(949632K), 0.0028890 secs]
INFO | jvm 1 | 2009/02/25 06:17:23 | 230.490: [Full GC
INFO | jvm 1 | 2009/02/25 06:17:23 | [PSYoungGen: 0K->0K(250560K)] [PSOldGen: 132886K->132886K(699072K)] 132886K->132886K(949632K) [PSPermGen: 43860K->43860K(82624K)], 0.5425250 secs]
INFO | jvm 1 | 2009/02/25 06:17:23 | 231.036: [GC [PSYoungGen: 0K->0K(248896K)] 132886K->132886K(947968K), 0.0033790 secs]
INFO | jvm 1 | 2009/02/25 06:17:23 | 231.039: [Full GC
INFO | jvm 1 | 2009/02/25 06:17:24 | [PSYoungGen: 0K->0K(248896K)] [PSOldGen: 132886K->132886K(699072K)] 132886K->132886K(947968K) [PSPermGen: 43860K->43860K(78336K)], 0.5411510 secs]
INFO | jvm 1 | 2009/02/25 06:17:24 | 231.586: [GC [PSYoungGen: 0K->0K(255872K)] 132886K->132886K(954944K), 0.0027420 secs]
INFO | jvm 1 | 2009/02/25 06:17:24 | 231.589: [Full GC
INFO | jvm 1 | 2009/02/25 06:17:25 | [PSYoungGen: 0K->0K(255872K)] [PSOldGen: 132886K->131908K(699072K)] 132886K->131908K(954944K) [PSPermGen: 43860K->43860K(74176K)], 0.5951160 secs]
INFO | jvm 1 | 2009/02/25 06:17:25 | 232.185: [GC [PSYoungGen: 0K->0K(252928K)] 131908K->131908K(952000K), 0.0031990 secs]
INFO | jvm 1 | 2009/02/25 06:17:25 | 232.188: [Full GC
INFO | jvm 1 | 2009/02/25 06:17:25 | [PSYoungGen: 0K->0K(252928K)] [PSOldGen: 131908K->131908K(699072K)] 131908K->131908K(952000K) [PSPermGen: 43860K->43860K(70592K)], 0.5386980 secs]

Message was edited by: tsaik

Reply viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.
briand
Offline
Joined: 2005-07-11

> I am using following commands:
> -Xms=1024m
> -Xmx=1024m
> -XX:PermSize=128m
> -XX:MaxPermSize=128m

Some older versions of the JDK had a bug with NewSize not getting
set to MaxNewSize when -Xms == -Xmx, so you might want to try adding
-Xmn to your command line (which is short hand for -XX:NewSize -XX:MaxNewSize).
You'll need to decide what size to use, though; to start, you might just pick the largest
size you see in the () portion of the minor gc log enteries (eg: PSYoungGen: 44069K->34425K(250752K),
use the 250752K number or something close to it).

briand
Offline
Joined: 2005-07-11

It looks to me like your perm gen is maxed out. Increase the size of the perm gen
with -XX:MaxPermSize=N, and also consider setting -XX:PermSize=N as well (because
if the perm gen is growing from PermSize to MaxPermSize over time, those growth
operations will require a full gc event; setting PermSize==MaxPermSize will prevent
the growth and the full gcs that are needed to perform that growth).

tsaik
Offline
Joined: 2009-02-24

I tried setting MAXPermSize and PermSize to 128m. But it didn't help. This time around GC tried unloading class, which didn't happen prior to the change.

Also, since I am using the default collector, I want to rule out that isn't a cause for this behavior, right?

INFO | jvm 1 | 2009/02/25 14:36:17 | 21.609: [GC
INFO | jvm 1 | 2009/02/25 14:36:17 | [PSYoungGen: 305841K->43643K(305856K)] 401298K->144841K(1004928K), 0.0668780 secs]
INFO | jvm 1 | 2009/02/25 14:36:17 | 21.718: [GC
INFO | jvm 1 | 2009/02/25 14:36:17 | [PSYoungGen: 49169K->43622K(192832K)] 150367K->144827K(891904K), 0.0485750 secs]
INFO | jvm 1 | 2009/02/25 14:36:17 | 21.766: [Full GC
INFO | jvm 1 | 2009/02/25 14:36:17 | [Unloading class sun.reflect.GeneratedMethodAccessor126]
INFO | jvm 1 | 2009/02/25 14:36:17 | [Unloading class sun.reflect.GeneratedMethodAccessor117]
INFO | jvm 1 | 2009/02/25 14:36:17 | [Unloading class sun.reflect.GeneratedMethodAccessor143]
INFO | jvm 1 | 2009/02/25 14:36:17 | [Unloading class sun.reflect.GeneratedMethodAccessor132]
INFO | jvm 1 | 2009/02/25 14:36:17 | [Unloading class sun.reflect.GeneratedMethodAccessor128]
INFO | jvm 1 | 2009/02/25 14:36:17 | [Unloading class sun.reflect.GeneratedMethodAccessor122]
INFO | jvm 1 | 2009/02/25 14:36:17 | [Unloading class sun.reflect.GeneratedMethodAccessor141]
INFO | jvm 1 | 2009/02/25 14:36:17 | [Unloading class sun.reflect.GeneratedMethodAccessor134]
INFO | jvm 1 | 2009/02/25 14:36:17 | [Unloading class sun.reflect.GeneratedMethodAccessor124]
INFO | jvm 1 | 2009/02/25 14:36:17 | [Unloading class sun.reflect.GeneratedMethodAccessor136]
INFO | jvm 1 | 2009/02/25 14:36:17 | [Unloading class sun.reflect.GeneratedMethodAccessor145]
INFO | jvm 1 | 2009/02/25 14:36:17 | [Unloading class sun.reflect.GeneratedMethodAccessor139]
INFO | jvm 1 | 2009/02/25 14:36:17 | [Unloading class sun.reflect.GeneratedMethodAccessor130]
INFO | jvm 1 | 2009/02/25 14:36:17 | [Unloading class sun.reflect.GeneratedMethodAccessor120]
INFO | jvm 1 | 2009/02/25 14:36:18 | [PSYoungGen: 43622K->0K(192832K)] [PSOldGen: 101205K->144563K(699072K)] 144827K->144563K(891904K) [PSPermGen: 41903K->41903K(84096K)], 0.4635120 secs]
INFO | jvm 1 | 2009/02/25 14:36:18 | 22.231: [GC [PSYoungGen: 0K->0K(149248K)] 144563K->144563K(848320K), 0.0028530 secs]
INFO | jvm 1 | 2009/02/25 14:36:18 | 22.234: [Full GC
INFO | jvm 1 | 2009/02/25 14:36:18 | [PSYoungGen: 0K->0K(149248K)] [PSOldGen: 144563K->144563K(699072K)] 144563K->144563K(848320K) [PSPermGen: 41903K->41903K(84096K)], 0.3831850 secs]
INFO | jvm 1 | 2009/02/25 14:36:18 | 22.620: [GC [PSYoungGen: 877K->128K(243328K)] 145441K->144691K(942400K), 0.0032080 secs]
INFO | jvm 1 | 2009/02/25 14:36:18 | 22.623: [Full GC
INFO | jvm 1 | 2009/02/25 14:36:19 | [PSYoungGen: 128K->0K(243328K)] [PSOldGen: 144563K->144565K(699072K)] 144691K->144565K(942400K) [PSPermGen: 41903K->41903K(84096K)], 0.3837610 secs]
INFO | jvm 1 | 2009/02/25 14:36:19 | 23.010: [GC [PSYoungGen: 1137K->64K(244352K)] 145703K->144629K(943424K), 0.0033800 secs]
INFO | jvm 1 | 2009/02/25 14:36:19 | 23.013: [Full GC
INFO | jvm 1 | 2009/02/25 14:36:19 | [PSYoungGen: 64K->0K(244352K)] [PSOldGen: 144565K->141070K(699072K)] 144629K->141070K(943424K) [PSPermGen: 41905K->41769K(84096K)], 0.5136410 secs]

briand
Offline
Joined: 2005-07-11

What does your command line look like?

One guess at this point is that I see signs of the various spaces growing and
shrinking. In order to grow a space, a full gc is needed. So, I would suggest
trying a run with -Xms == -Xmx, -Xmn (or -XX:NewSize==-XX:MaxNewSize),
and -XX:PermSize==-XX:MaxPermSize. This will make the full heap fully
committed at startup, which will prevent the grow/shrink operations, which
in turn will prevent any associated full gc events.

Brian

tsaik
Offline
Joined: 2009-02-24

I am using following commands:
-Xms=1024m
-Xmx=1024m
-XX:PermSize=128m
-XX:MaxPermSize=128m

BTW, I read somewhere that System.gc() call in code could potentially play a role in this. I searched and did find a external lib class that explicitly issues this call on finalize() method. Could this be an issue?

Tsai

briand
Offline
Joined: 2005-07-11

> I am using following commands:
> -Xms=1024m
> -Xmx=1024m
> -XX:PermSize=128m
> -XX:MaxPermSize=128m
>
> BTW, I read somewhere that System.gc() call in code
> could potentially play a role in this. I searched

Yes, that's true, but usually such calls are quite periodic.

> and did find a external lib class that explicitly
> issues this call on finalize() method. Could this be
> an issue?

Yikes! That's really ugly! Add -XX:+DisableExplictGC to your command line!
You might also consider investigating ways of eliminating that finalize()
method - investigating things like Reference objects of various kinds.

Brian

tsaik
Offline
Joined: 2009-02-24

It turns out it was the System.gc() call. After removing the finalize() method - no more full gc.

Thanks for you help!

Tsai

peter__lawrey
Offline
Joined: 2005-11-01

I suggest you use a memory profiler to look at the number of objects you are creating.
Note: some objects, such those with circular links are only cleaned up on a full GC. One way to fix this is to break such circular links when the object is not needed.