1 Reply Latest reply: Aug 27, 2009 4:14 AM by 843798 RSS

    Full GC loop

    843798
      Our application went into Full GC loop, we did have verbose GC turned on. Can someone please explain how this can be interpretted.
      It appears like there is close to 1G free for promotion and still the Young Gen promotion is not working.

      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
        • 1. Re: Full GC loop
          843798
          Hy,

          I'll have a stab at this :)

          up until "Line 88338", there's no sign of anything wrong with memory allocation in the JVM ... but
          ...
          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]


          than on "Line 88339" a few things to notice : GC kicks in only 1sec. after previous one and only "300084K" OldGen got freed up as opposed to 1800000K befor. Eden is not the probem here; possibly survivor space ... but need more info on application

          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]

          Unloading classes can point to PermSpace depletion, but your GC logging is not verbose enough to see permspace collections all the time..
          After this, even if PermSpace got freed up enough, it seems your application doesn't recover at all ... probably only a restart works(around) ?

          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]
          ....

          If you really need 6GB for this app, and you have the resources, try moving Xms and Xmx closer together; rescale (initial + max) PermSize as well .. and than report back. Is it background app or user interactive. I presume you're using jdk1.5 ?
          e.g. "-verbose:gc -XX:+PrintGCDetails -Xms4000m -Xmx6000m -XX:MaxPermSize=500m" possibly try adding "-XX:SurvivorRatio=8" or so, this could releive collector a bit of promoting too much to OldGen ...

          grtz,
          gert