Garbage Collection - Log Analysis

25646.328 :[GC 325407K->83000K(776768K), 0.2300771 secs]
25646.328 : [GC 325816K->83372K(776768K), 0.2454258 secs]
25646.328 : [Full GC 267628K->83769K(776768K), 1.8479984 secs]


25646.328 –time since JVM started

325407K->83000K :combined size of live objects before and after garbage collection
After minor collections the count includes objects that aren't necessarily alive but can't be reclaimed, either because they are directly alive, or because they are within or referenced from the tenured generation.

(776768K) -> is the total available space, not counting the space in the permanent generation, which is the total heap minus one of the survivor spaces

0.2300771 secs –time taken

Here we see two minor collections and one major one.

Good Link:http://java.ociweb.com/mark/other-presentations/JavaGC.pdf


Sample GC logs:
25646.328: [GC [PSYoungGen: 53934K->1783K(55744K)] 139043K->86893K(521792K), 0.0091130 secs] [Times: user=0.02 sys=0.01, real=0.01 secs]
25650.658: [GC [PSYoungGen: 55735K->2232K(54208K)] 140845K->91675K(520256K), 0.0140890 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
[2009-11-03 10:02:23.092] fs-watcher Processing 'DELETED' event for file 'xxx.jar'. ? Application Undeployed
[2009-11-03 10:02:24.495] fs-watcher Undeployment of ‘xxx' version '0' completed.
[2009-11-03 10:02:48.592] fs-watcher Processing 'CREATED' event for file 'xxx.jar'.
[2009-11-03 10:02:52.915] fs-watcher Deployment of 'xxx' version '0' completed.
25705.888: [Full GC (System) [PSYoungGen: 416K->0K(53632K)] [PSOldGen: 122447K->122819K(466048K)] 122863K->122819K(519680K) [PSPermGen: 56927K->56927K(58496K)], 0.4994360 secs] [Times: user=0.50 sys=0.00, real=0.49 secs]
Total time for which application threads were stopped: 0.5127720 seconds

Approx 2.20 mins later after the redeployment the memory in OldGen starts piling up

33705.323: [Full GC (System) [PSYoungGen: 3584K->0K(51328K)]
[PSOldGen: 162686K->166028K(466048K)]
166270K->166028K(517376K)
[PSPermGen: 61486K->61486K(61824K)], 0.6978710 secs]
[Times: user=0.70 sys=0.00, real=0.70 secs]

33766.045: [Full GC (System)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor305]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor306]
[PSYoungGen: 3424K->0K(51456K)] [PSOldGen: 175451K->178649K(466048K)] 178875K->178649K(517504K) [PSPermGen: 61487K->61487K(61824K)], 0.7389690 secs] [Times: user=0.73 sys=0.01, real=0.74 secs]
36459.779: [Full GC [PSYoungGen: 41152K->0K(57664K)] [PSOldGen: 554317K->557726K(699072K)] 595469K->557726K(756736K) [PSPermGen: 61442K->61442K(61824K)], 1.6296560 secs] [Times: user=1.62 sys=0.00, real=1.63 secs]
Total time for which application threads were stopped: 1.6310400 seconds
Total time for which application threads were stopped: 0.0011620 seconds

After approx 3hrs 40mins after the redeployment, application starts doing Full GC every 2 secs virtually unable to collect anything. The GC pause times are 2secs. So application is not
running at this point.

38208.203: [Full GC [PSYoungGen: 42047K->40198K(53952K)]
[PSOldGen: 699068K->699068K(699072K)]
741115K->739266K(753024K)
[PSPermGen: 61376K->61376K(61568K)], 2.1202220 secs]

[Times: user=2.16 sys=0.00, real=2.13 secs]
Total time for which application threads were stopped: 2.1220930 seconds
38210.406: [Full GC [PSYoungGen: 42048K->38287K(53952K)] [PSOldGen: 699068K->699072K(699072K)] 741116K->737359K(753024K) [PSPermGen: 61376K->61369K(61568K)], 2.2874650 secs] [Times: user=2.28 sys=0.00, real=2.28 secs]
Total time for which application threads were stopped: 2.2889430 seconds
38213.678: [Full GC [PSYoungGen: 42043K->40523K(53952K)] [PSOldGen: 699072K->699072K(699072K)] 741115K->739595K(753024K) [PSPermGen: 61369K->61369K(61568K)], 2.1083830 secs] [Times: user=2.11 sys=0.01, real=2.11 secs]
756 MB -Xmx

Ref :http://java.sun.com/docs/hotspot/gc1.4.2/

Each blue box represents a collector that is used to collect a generation. The young generation is collected by the blue boxes in the yellow region and the tenured generation is collected by the blue boxes in the gray region.

"Serial" is a stop-the-world, copying collector which uses a single GC thread.

"ParNew" is a stop-the-world, copying collector which uses multiple GC threads. It differs from "Parallel Scavenge" in that it has enhancements that make it usable with CMS. For example, "ParNew" does the synchronization needed so that it can run during the concurrent phases of CMS.

"Parallel Scavenge" is a stop-the-world, copying collector which uses multiple GC threads.

"Serial Old" is a stop-the-world, mark-sweep-compact collector that uses a single GC thread.

"CMS" is a mostly concurrent, low-pause collector.

"Parallel Old" is a compacting collector that uses multiple GC threads.

Using the -XX flags for our collectors for jdk6,

UseSerialGC is "Serial" + "Serial Old"

UseParNewGC is "ParNew" + "Serial Old"

UseConcMarkSweepGC is "ParNew" + "CMS" + "Serial Old". "CMS" is used most of the time to collect the tenured generation. "Serial Old" is used when a concurrent mode failure occurs.

UseParallelGC is "Parallel Scavenge" + "Serial Old"

UseParallelOldGC is "Parallel Scavenge" + "Parallel Old"

Ref : http://blogs.sun.com/jonthecollector/entry/our_collectors



These 2 references clears most of teh doubts pertaining to jvm internals and gc tuning.

http://blogs.sun.com/jonthecollector/entry/our_collectors

http://www.nbl.fi/~nbl97/java/tuning/jvm_internals.pdf