This discussion is archived
1 Reply Latest reply: Sep 8, 2009 12:02 PM by 843829 RSS

Full GC Loop + How to interpret Verbose GC?

843829 Newbie
Currently Being Moderated
Can someone please explain how this verbose gc can be interpretted?
It appears like there is close to 1G free for promotion and still the Young Gen promotion is not happening. Is this normal ?
The application goes into Full GC loops and eventually has to be restarted to be performant again.


Line 88326 : 41900.684: [GC [PSYoungGen: 1866224K->43794K(1931840K)] 3502757K->1685045K(5446976K), 0.1167970 secs] [Times: user=0.12 sys=0.00, real=0.12 secs]
Line 88327 : 41906.230: [GC [PSYoungGen: 1868882K->64245K(1941056K)] 3510133K->1705697K(5456192K), 0.1538270 secs] [Times: user=0.15 sys=0.00, real=0.15 secs]
Line 88328 : 41913.490: [GC [PSYoungGen: 1903285K->15842K(1941440K)] 3544737K->1685685K(5456576K), 0.1050850 secs] [Times: user=0.10 sys=0.00, real=0.11 secs]
Line 88329 : 41919.636: [GC [PSYoungGen: 1854882K->71593K(1938112K)] 3524725K->1743162K(5453248K), 0.1610370 secs] [Times: user=0.16 sys=0.00, real=0.16 secs]
Line 88330 : 41926.003: [GC [PSYoungGen: 1906473K->44674K(1879616K)] 3578042K->1716607K(5394752K), 0.0935700 secs] [Times: user=0.11 sys=0.00, real=0.10 secs]
Line 88331 : 41931.256: [GC [PSYoungGen: 1879554K->19205K(1940032K)] 3551487K->1720689K(5455168K), 0.0924580 secs] [Times: user=0.13 sys=0.00, real=0.09 secs]
Line 88332 : 41935.287: [GC [PSYoungGen: 1857477K->41100K(1939968K)] 3558961K->1742584K(5455104K), 0.0953660 secs] [Times: user=0.14 sys=0.00, real=0.09 secs]
Line 88333 : 41938.270: [GC [PSYoungGen: 1879372K->18301K(1942016K)] 3580856K->1719871K(5457152K), 0.1102160 secs] [Times: user=0.09 sys=0.00, real=0.11 secs]
Line 88334 : 41941.788: [GC [PSYoungGen: 1863293K->79254K(1941568K)] 3564863K->1781043K(5456704K), 0.0817900 secs] [Times: user=0.24 sys=0.00, real=0.08 secs]
Line 88335 : 41946.594: [GC [PSYoungGen: 1924246K->69389K(1938112K)] 3626035K->1771986K(5453248K), 0.1661760 secs] [Times: user=0.20 sys=0.00, real=0.16 secs]
Line 88336 : 41951.120: [GC [PSYoungGen: 1902861K->38451K(1871936K)] 3605458K->1770219K(5387072K), 0.1473680 secs] [Times: user=0.18 sys=0.00, real=0.15 secs]
Line 88337 : 41958.626: [GC [PSYoungGen: 1871923K->54656K(1942400K)] 3603691K->1788149K(5457536K), 0.1552370 secs] [Times: user=0.16 sys=0.00, real=0.15 secs]
Line 88338 : 41966.122: [GC [PSYoungGen: 1893824K->76469K(1939328K)] 4634025K->2853942K(5454464K), 0.1254980 secs] [Times: user=0.22 sys=0.00, real=0.13 secs]
Line 88339 : 41967.458: [GC [PSYoungGen: 1358774K->17127K(1941760K)] 4136247K->3836163K(6037760K), 1.0412470 secs] [Times: user=0.80 sys=0.34, real=1.04 secs]
Line 88340 : 41968.499: [Full GC[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor1047]
Line 88471 : 41975.139: [GC-- [PSYoungGen: 1836416K->1836416K(1941760K)] 4982380K->4982380K(6037760K), 0.0646720 secs] [Times: user=0.06 sys=0.01, real=0.06 secs]
Line 88472 : 41975.204: [Full GC[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor1202]
Line 88543 : 41979.042: [GC-- [PSYoungGen: 1837491K->1837491K(1941760K)] 4983455K->4983455K(6037760K), 0.3140620 secs] [Times: user=0.63 sys=0.00, real=0.32 secs]
Line 88544 : 41979.356: [Full GC[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor671]
Line 88560 : 41985.093: [GC-- [PSYoungGen: 1830269K->1830269K(1941760K)] 4795149K->4795149K(6037760K), 0.3286810 secs] [Times: user=0.63 sys=0.00, real=0.33 secs]
Line 88561 : 41985.422: [Full GC [PSYoungGen: 1830269K->1831614K(1941760K)] [PSOldGen: 2964879K->2964879K(4096000K)] 4795149K->4796494K(6037760K) [PSPermGen: 123099K->123099K(126656K)], 3.1776690 secs] [Times: user=3.17 sys=0.01, real=3.18 secs]
Line 88562 : 41988.810: [GC-- [PSYoungGen: 1836416K->1836416K(1941760K)] 4901950K->4901950K(6037760K), 0.2989710 secs] [Times: user=0.63 sys=0.00, real=0.30 secs]
Line 88563 : 41989.109: [Full GC [PSYoungGen: 1836416K->1837766K(1941760K)] [PSOldGen: 3065534K->3065534K(4096000K)] 4901950K->4903301K(6037760K) [PSPermGen: 123099K->123099K(126528K)], 3.1866390 secs] [Times: user=3.17 sys=0.00, real=3.19 secs]
Line 88564 : 41992.341: [GC-- [PSYoungGen: 1837766K->1837766K(1941760K)] 4903301K->4903301K(6037760K), 0.3023900 secs] [Times: user=0.63 sys=0.00, real=0.30 secs]
Line 88565 : 41992.643: [Full GC [PSYoungGen: 1837766K->1837766K(1941760K)] [PSOldGen: 3065534K->3065534K(4096000K)] 4903301K->4903301K(6037760K) [PSPermGen: 123099K->123099K(125952K)], 3.1959920 secs] [Times: user=3.17 sys=0.01, real=3.20 secs]
Line 88566 : 41995.849: [GC-- [PSYoungGen: 1837766K->1837766K(1941760K)] 4903301K->4903309K(6037760K), 0.3198970 secs] [Times: user=0.63 sys=0.00, real=0.32 secs]
Line 88567 : 41996.169: [Full GC [PSYoungGen: 1837766K->1813137K(1941760K)] [PSOldGen: 3065542K->3062041K(4096000K)] 4903309K->4875179K(6037760K) [PSPermGen: 123099K->123099K(125888K)], 5.4472620 secs] [Times: user=5.44 sys=0.00, real=5.45 secs]
Line 88568 : 42001.746: [GC-- [PSYoungGen: 1836416K->1836416K(1941760K)] 4898457K->4898457K(6037760K), 0.2801550 secs] [Times: user=0.65 sys=0.00, real=0.28 secs]
Line 88569 : 42002.026: [Full GC [PSYoungGen: 1836416K->1837744K(1941760K)] [PSOldGen: 3062041K->3062041K(4096000K)] 4898457K->4899786K(6037760K) [PSPermGen: 123099K->123099K(125824K)], 3.2083830 secs] [Times: user=3.20 sys=0.01, real=3.21 secs]
Line 88570 : 42005.266: [GC-- [PSYoungGen: 1837744K->1837744K(1941760K)] 4899786K->4899786K(6037760K), 0.2898370 secs] [Times: user=0.59 sys=0.00, real=0.29 secs]
Line 88571 : 42005.556: [Full GC [PSYoungGen: 1837744K->1837744K(1941760K)] [PSOldGen: 3062041K->3062041K(4096000K)] 4899786K->4899786K(6037760K) [PSPermGen: 123099K->123099K(125312K)], 3.2037720 secs] [Times: user=3.20 sys=0.01, real=3.20 secs]
Line 88572 : 42008.805: [GC-- [PSYoungGen: 1837744K->1837744K(1941760K)] 4899786K->4899794K(6037760K), 0.3347480 secs] [Times: user=0.59 sys=0.00, real=0.33 secs]
Line 88573 : 42009.140: [Full GC [PSYoungGen: 1837744K->1837744K(1941760K)] [PSOldGen: 3062049K->3062049K(4096000K)] 4899794K->4899794K(6037760K) [PSPermGen: 123099K->123099K(125312K)], 3.1690990 secs] [Times: user=3.16 sys=0.00, real=3.17 secs]
Line 88574 : 42012.319: [GC-- [PSYoungGen: 1837744K->1837744K(1941760K)] 4899794K->4899794K(6037760K), 0.3056590 secs] [Times: user=0.62 sys=0.00, real=0.31 secs]
Line 88575 : 42012.625: [Full GC [PSYoungGen: 1837744K->1813115K(1941760K)] [PSOldGen: 3062049K->3060814K(4096000K)] 4899794K->4873929K(6037760K) [PSPermGen: 123099K->123099K(124800K)], 4.9230010 secs] [Times: user=4.92 sys=0.01, real=4.92 secs]
Line 88576 : 42017.661: [GC-- [PSYoungGen: 1836416K->1836416K(1941760K)] 4897230K->4897230K(6037760K), 0.2799600 secs] [Times: user=0.66 sys=0.00, real=0.28 secs]

The following JVM options were used
-Xms512M -XX:MaxPermSize=260M -Xmx6000M