Skip to main content

Questions on understanding Full GC Cycles.

6 replies [Last post]
sumit_only
Offline
Joined: 2003-06-10

Recently I tuned my VM options to address some critical issues and made the following changes:

-XX:NewSize=254M
-XX:+AggressiveHeap
-XX:+UseParallelGC
-Xms256M
-Xmx1024M

This gave me good outcome because earlier I had huge pauses with default collector and small young (default) generation. But with the above change, I see many FullGC events. They are spread a few seconds apart. Do note that I still do not see any issues with application but I would like to be prepared if this GC output is indicating a potential issue.

Here are some lines:

38.534: [GC 262945K->41161K(300032K), 0.0332940 secs]
38.567: [Full GC 41161K->32005K(303616K), 0.1773490 secs]

213.722: [GC 254516K->266866K(330240K), 0.2098050 secs]
213.932: [Full GC 266866K->73362K(338240K), 0.3870610 secs]
...
452.924: [GC 329334K->100106K(366528K), 0.0055360 secs]
452.930: [Full GC 100106K->55356K(326016K), 0.3637280 secs]
..

464.915: [GC 328049K->292487K(357120K), 0.0082640 secs]
464.924: [Full GC 292487K->62770K(341056K), 0.3857490 secs]
...
475.907: [GC 335094K->93216K(365184K), 0.0079970 secs]
475.915: [Full GC 93216K->64029K(342464K), 0.4167880 secs]
...

479.202: [GC 337330K->93778K(367936K), 0.0059040 secs]
479.208: [Full GC 93778K->67714K(346944K), 0.3634440 secs]
...

482.059: [GC 339323K->100816K(369344K), 0.0073910 secs]
482.066: [Full GC 100816K->78915K(356736K), 0.3966540 secs]
...

487.707: [GC 351450K->107636K(381632K), 0.0122460 secs]
487.719: [Full GC 107636K->80187K(359552K), 0.3931050 secs]
...
491.990: [GC 355569K->110554K(385344K), 0.0099930 secs]
492.000: [Full GC 110554K->76109K(356160K), 0.4659980 secs]

These have not given me any problems so far, but I would like to know if there is any potential issue being missed here? Like in first GC set above the output is -

38.534: [GC 262945K->41161K(300032K), 0.0332940 secs]
38.567: [Full GC 41161K->32005K(303616K), 0.1773490 secs]

Here after minor collection, the total occupancy is only at 41161/ 300032 = 27%. Then why should it be followed by a FullGC? I am of the opinion that this indicates shortage of tenured generation because after a minor GC, some objects still got promoted to tenured generation. Which is why an immediate Full GC follows minor GC and then reduced it from 41161K to 32005K which must have been a tenured generation collection. Is my understanding correct? If yes, then why is the default value of XX:NewRatio=2, not kicking in and making tenured generation twice the new generation (-XX:NewSize=254M ) at start up itself?

However my application also uses a lot JSPs, so even permanent generation will have a bearing on GC performance and can trigger a full GC. How do I know if that is the case based on GC output above? I am of the opinion that I have still not hit this issue.

In third GC set given above, FullGC has caused even total heap to come down from 366528K to 326016K. Does this indicate anything?

I also notice that with change in GC options the verbose GC output also changed. In earlier case with default collector, I used to get the following line:

34.214: [Full GC 34.214: [Tenured: 13108K->8014K(60544K), 0.0517130 secs] 13971K->8014K(65088K), [Perm : 8191K->8191K(8192K)], 0.0517880 secs]

With new options, the FullGC does not give me the break-up of different generations:
213.932: [Full GC 266866K->73362K(338240K), 0.3870610 secs]

How do I know which generation reduced by how much in above case? Or is it that this line is supposed to indicate a tenured generation clean up only and there is a separate output for permgen?

I have used following to get GC output:
-J-verbosegc -XX:+PrintGCDetails -J-Xloggc:/tmp/garbage_coll.txt -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime

I do not see any explicit GC calls as well.

Any inputs will be appreciated.
Thanks

Reply viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.
sumit_only
Offline
Joined: 2003-06-10

Hi Ruchir - Another thing you asked for was whether it is a CPU intensive or whether JSP pages are big. Well some of those pages can be big for sure. But overall, I think the application is neither too much IO centric or CPU centric. Like many other apps, it is a combination of both.

3dfan
Offline
Joined: 2009-05-21

Thanks to everyone, I found here answers to my questions!!

sumit_only
Offline
Joined: 2003-06-10

3dfan

It will be great if you could also share the questions you had as that will help others.

Thanks

ruchirc
Offline
Joined: 2008-07-20

Can you please publish the capacity of the box.

like:
RAM used
Processor single or VCPU or multi CPUS
What is the prospective you are looking for?

Try this option

java -Xmx512m -Xms512m -Xmn128m -Xss128k -XX:ParallelGCThreads=4 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:SurvivorRatio=4 -XX:TargetSurvivorRatio=30 -XX:MaxTenuringThreshold=12 -XX:+AggressiveOpts

ruchirc
Offline
Joined: 2008-07-20

java -Xmx512m -Xms512m -XX:ParallelGCThreads=5 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:SurvivorRatio=4 -XX:TargetSurvivorRatio=20 -XX:MaxTenuringThreshold=10 -XX:+AggressiveOpts

You can even try this option, I am sure it will help you.

Still if you can provide the capacity of the hardware it will help me understand the request better.

Also what type of app it is, like it creates a large pool of objects or its CPU intensive or the JSP pages are big .....

Ruchir Choudhry

sumit_only
Offline
Joined: 2003-06-10

Thanks Ruchir,

I have experimented with a lot of the options for heap/ collector. I have tried using a lot of variations for Xms and Xmx. And the option chosen right now seems to be the best. That is :

-XX:NewSize=254M
-XX:+AggressiveHeap
-XX:+UseParallelGC
-Xms256M
-Xmx1024M

I did try experimenting with Xss but that did not help much and so did a change in collector option such as ConcMarkAndSweep.

Other details of the box are:

Linux RHEL WS release 3 (Taroon update 8)
RAM = 3G
Swap = 1G
Total CPUs = 4 (hyperthreaded)

The application has lots of JSP pages as well as Java classes. However output from GC did not indicate any need to tune PermGen.

In the meantime I was able to think through and find answers to a lot of questions I raised above. It is now very clear to me that the issue of FullGC is to do with violation of Young Generation Guarantee aas opposed to any other such as PermGen getting full. I have also understood how to interpret the log above and can give more details if anyone needs to know those.

In the meantime do let me know any way to ensure that Young Generation Guarantee is not violated. For that I need to ensure tenured generation is set to much more than young generation. However I am not seeing NewRatio help me at all with that.

Thanks again.