Java - Full GC (Garbage Collector) happening a lot in short interval causing performance hit

Question

I am seeing some abnormal behavior in our prod environment that is causing us high thread count on server that is running Tomcat. The heap size of 10,092,544K is divided between new generation and tenure generation as 2,752,512K + 7,340,032K = 10,092,544K.

I am confused as to why GC is running itself multiple times when there is enough memory available on heap (new and old gen both) (Full GC [PSYoungGen: 0K->0K(2752512K)] [ParOldGen: 2748534K->2748529K(7340032K)] )

As you can see 0K->0K for young gen and .27G -> .27G for old gen means hardly any objects are getting gc'd and there is so much of memory available. (heap size is 10G).

Since Full GC is running multiple times during short interval, it is causing slow performance and hence application can't handle the incoming user requests and hence high threads on server and eventually we have to restart server to come out of this situation.

Can you please explain what is happening here.

Here is output on gc.log.

. .

more...... . .

Jul 18 14:52:38 fwprodcontent03 gc.log: 3172.122: [GC [PSYoungGen: 0K->0K(2752512K)] 2750855K->2750855K(10092544K), 0.0515920 secs] [Times: user=0.32 sys=0.01, real=0.06 secs]

Jul 18 14:52:42 fwprodcontent03 gc.log: 3172.174: [Full GC [PSYoungGen: 0K->0K(2752512K)] [ParOldGen: 2750855K->2749937K(7340032K)] 2750855K->2749937K(10092544K) [PSPermGen: 262143K->262115K(262144K)], 4.1571260 secs] [Times: user=44.29 sys=0.06, real=4.15 secs]

Jul 18 14:52:42 fwprodcontent03 gc.log: 3176.361: [GC [PSYoungGen: 9071K->1280K(2752512K)] 2759008K->2751217K(10092544K), 0.0989600 secs] [Times: user=0.64 sys=0.01, real=0.10 secs]

Jul 18 14:52:46 fwprodcontent03 gc.log: 3176.461: [Full GC [PSYoungGen: 1280K->0K(2752512K)] [ParOldGen: 2749937K->2748847K(7340032K)] 2751217K->2748847K(10092544K) [PSPermGen: 262143K->262121K(262144K)], 3.1331910 secs] [Tim es: user=31.25 sys=0.01, real=3.14 secs]

Jul 18 14:52:46 fwprodcontent03 gc.log: 3179.616: [GC [PSYoungGen: 2161K->288K(2752512K)] 2751008K->2749135K(10092544K), 0.0688890 secs] [Times: user=0.42 sys=0.02, real=0.07 secs]

Jul 18 14:52:49 fwprodcontent03 gc.log: 3179.686: [Full GC [PSYoungGen: 288K->0K(2752512K)] [ParOldGen: 2748847K->2748930K(7340032K)] 2749135K->2748930K(10092544K) [PSPermGen: 262143K->262143K(262144K)], 3.2369940 secs] [Time s: user=32.23 sys=0.02, real=3.23 secs]

Jul 18 14:52:49 fwprodcontent03 gc.log: 3182.923: [GC [PSYoungGen: 0K->0K(2752512K)] 2748930K->2748930K(10092544K), 0.0607190 secs] [Times: user=0.39 sys=0.01, real=0.06 secs]

Jul 18 14:52:57 fwprodcontent03 gc.log: 3182.984: [Full GC [PSYoungGen: 0K->0K(2752512K)] [ParOldGen: 2748930K->2748528K(7340032K)] 2748930K->2748528K(10092544K) [PSPermGen: 262143K->262141K(262144K)], 8.5377730 secs] [Times: user=98.30 sys=0.57, real=8.54 secs]

Jul 18 14:52:58 fwprodcontent03 gc.log: 3191.533: [GC [PSYoungGen: 202K->128K(2752512K)] 2748731K->2748656K(10092544K), 0.1088430 secs] [Times: user=0.67 sys=0.00, real=0.11 secs]

Jul 18 14:53:02 fwprodcontent03 gc.log: 3191.642: [Full GC [PSYoungGen: 128K->0K(2752512K)] [ParOldGen: 2748528K->2748534K(7340032K)] 2748656K->2748534K(10092544K) [PSPermGen: 262143K->262143K(262144K)], 3.1761780 secs] [Time s: user=31.11 sys=0.02, real=3.18 secs]

Jul 18 14:53:02 fwprodcontent03 gc.log: 3194.820: [GC [PSYoungGen: 0K->0K(2752512K)] 2748534K->2748534K(10092544K), 0.0589010 secs] [Times: user=0.38 sys=0.01, real=0.06 secs]

Jul 18 14:53:05 fwprodcontent03 gc.log: 3194.879: [Full GC [PSYoungGen: 0K->0K(2752512K)] [ParOldGen: 2748534K->2748529K(7340032K)] 2748534K->2748529K(10092544K) [PSPermGen: 262143K->262143K(262144K)], 3.0554520 secs] [Times: user=30.72 sys=0.03, real=3.05 secs] . . .more.....

Thanks in advance.

Do you have the option of using the concurrent mark sweep GC instead? — fge
@fge - Using CMS is unlikely to reduce the number of full GCs. If anything, it is likely to make things worse. — Stephen C

Uwe Plonus Uwe Plonus · Accepted Answer · 2013-07-18T07:04:07

Have you looked at your gc stats?

[Full GC [PSYoungGen: 0K->0K(2752512K)] [ParOldGen: 2748534K->2748529K(7340032K)] 2748534K->2748529K(10092544K) [PSPermGen: 262143K->262143K(262144K)], 3.0554520 secs]

The important part is [PSPermGen: 262143K->262143K(262144K)]. You PermGenSpace is exhausted and therefore a full GC is done. Therefore increase you PermGenSpace further to solve this problems (perhaps by decreasing you heap space a little bit).

Also don't deploy to often on a production system without restarting Tomcat as this will exhaust your PermGenSpace very fast.

Java - Full GC (Garbage Collector) happening a lot in short interval causing performance hit

1 Answers