What could be the reason for continuous Full GC's during application startup

Question

What could be the reason for continuous Full GC's during application (webapplication deployed on tomcat) startup?

JDK 1.6

Memory settings
-Xms1024M -Xmx1024M -XX:PermSize=200M -XX:MaxPermSize=512M -XX:+UseParallelOldGC

jmap output is below

Heap Configuration:
   MinHeapFreeRatio = 40   
   MaxHeapFreeRatio = 70  
   MaxHeapSize      = 1073741824 (1024.0MB)  
   NewSize          = 2686976 (2.5625MB)  
   MaxNewSize       = 17592186044415 MB  
   OldSize          = 5439488 (5.1875MB)  
   NewRatio         = 2  
   SurvivorRatio    = 8  
   PermSize         = 209715200 (200.0MB)  
   MaxPermSize      = 536870912 (512.0MB)  

0.194: [GC [PSYoungGen: 10489K->720K(305856K)] 10489K->720K(1004928K), 0.0061190 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]    
0.200: [Full GC (System) [PSYoungGen: 720K->0K(305856K)] [ParOldGen: 0K->594K(699072K)] 720K->594K(1004928K) [PSPermGen: 6645K->6641K(204800K)], 0.0516540 secs] [Times: user=0.10 sys=0.00, real=0.06 secs]    
6.184: [GC [PSYoungGen: 262208K->14797K(305856K)] 262802K->15392K(1004928K), 0.0354510 secs] [Times: user=0.18 sys=0.04, real=0.03 secs]    
9.549: [GC [PSYoungGen: 277005K->43625K(305856K)] 277600K->60736K(1004928K), 0.0781960 secs] [Times: user=0.56 sys=0.07, real=0.08 secs]  
11.768: [GC [PSYoungGen: 305833K->43645K(305856K)] 322944K->67436K(1004928K), 0.0584750 secs] [Times: user=0.40 sys=0.05, real=0.06 secs]  
15.037: [GC [PSYoungGen: 305853K->43619K(305856K)] 329644K->72932K(1004928K), 0.0688340 secs] [Times: user=0.42 sys=0.01, real=0.07 secs]  
19.372: [GC [PSYoungGen: 273171K->43621K(305856K)] 302483K->76957K(1004928K), 0.0573890 secs] [Times: user=0.41 sys=0.01, real=0.06 secs]  
19.430: [Full GC (System) [PSYoungGen: 43621K->0K(305856K)] [ParOldGen: 33336K->54668K(699072K)] 76957K->54668K(1004928K) [PSPermGen: 36356K->36296K(204800K)], 0.4569500 secs] [Times: user=1.77 sys=0.02, real=0.46 secs]  
19.924: [GC [PSYoungGen: 4280K->128K(305856K)] 58949K->54796K(1004928K), 0.0041070 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]  
19.928: [Full GC (System) [PSYoungGen: 128K->0K(305856K)] [ParOldGen: 54668K->54532K(699072K)] 54796K->54532K(1004928K) [PSPermGen: 36300K->36300K(204800K)], 0.3531480 secs] [Times: user=1.19 sys=0.10, real=0.35 secs]  
20.284: [GC [PSYoungGen: 4280K->64K(305856K)] 58813K->54596K(1004928K), 0.0040580 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]  
20.288: [Full GC (System) [PSYoungGen: 64K->0K(305856K)] [ParOldGen: 54532K->54532K(699072K)] 54596K->54532K(1004928K) [PSPermGen: 36300K->36300K(204800K)], 0.2360580 secs] [Times: user=1.01 sys=0.01, real=0.24 secs]  
20.525: [GC [PSYoungGen: 4280K->96K(305856K)] 58813K->54628K(1004928K), 0.0030960 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]  
20.528: [Full GC (System) [PSYoungGen: 96K->0K(305856K)] [ParOldGen: 54532K->54533K(699072K)] 54628K->54533K(1004928K) [PSPermGen: 36300K->36300K(204800K)], 0.2311320 secs] [Times: user=0.88 sys=0.00, real=0.23 secs]  
20.760: [GC [PSYoungGen: 4280K->96K(305856K)] 58814K->54629K(1004928K), 0.0034940 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]  
20.764: [Full GC (System) [PSYoungGen: 96K->0K(305856K)] [ParOldGen: 54533K->54533K(699072K)] 54629K->54533K(1004928K) [PSPermGen: 36300K->36300K(204800K)], 0.2381600 secs] [Times: user=0.85 sys=0.01, real=0.24 secs]  
21.201: [GC [PSYoungGen: 5160K->354K(305856K)] 59694K->54888K(1004928K), 0.0019950 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]  
21.204: [Full GC (System) [PSYoungGen: 354K->0K(305856K)] [ParOldGen: 54533K->54792K(699072K)] 54888K->54792K(1004928K) [PSPermGen: 36300K->36300K(204800K)], 0.2358570 secs] [Times: user=0.98 sys=0.01, real=0.24 secs]  
21.442: [GC [PSYoungGen: 4280K->64K(305856K)] 59073K->54856K(1004928K), 0.0022190 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]  
21.444: [Full GC (System) [PSYoungGen: 64K->0K(305856K)] [ParOldGen: 54792K->54792K(699072K)] 54856K->54792K(1004928K) [PSPermGen: 36300K->36300K(204800K)], 0.2475970 secs] [Times: user=0.95 sys=0.00, real=0.24 secs]  
21.773: [GC [PSYoungGen: 11200K->741K(305856K)] 65993K->55534K(1004928K), 0.0030230 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]  
21.776: [Full GC (System) [PSYoungGen: 741K->0K(305856K)] [ParOldGen: 54792K->54376K(699072K)] 55534K->54376K(1004928K) [PSPermGen: 36538K->36537K(204800K)], 0.2550630 secs] [Times: user=1.05 sys=0.00, real=0.25 secs]  
22.033: [GC [PSYoungGen: 4280K->96K(305856K)] 58657K->54472K(1004928K), 0.0032130 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]  
22.036: [Full GC (System) [PSYoungGen: 96K->0K(305856K)] [ParOldGen: 54376K->54376K(699072K)] 54472K->54376K(1004928K) [PSPermGen: 36537K->36537K(204800K)], 0.2507170 secs] [Times: user=1.01 sys=0.01, real=0.25 secs]  
22.289: [GC [PSYoungGen: 4280K->96K(305856K)] 58657K->54472K(1004928K), 0.0038060 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]  
22.293: [Full GC (System) [PSYoungGen: 96K->0K(305856K)] [ParOldGen: 54376K->54376K(699072K)] 54472K->54376K(1004928K) [PSPermGen: 36537K->36537K(204800K)], 0.2640250 secs] [Times: user=1.07 sys=0.02, real=0.27 secs]  
22.560: [GC [PSYoungGen: 4280K->128K(305856K)] 58657K->54504K(1004928K), 0.0036890 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]  
22.564: [Full GC (System) [PSYoungGen: 128K->0K(305856K)] [ParOldGen: 54376K->54377K(699072K)] 54504K->54377K(1004928K) [PSPermGen: 36537K->36536K(204800K)], 0.2585560 secs] [Times: user=1.08 sys=0.01, real=0.25 secs]  
22.823: [GC [PSYoungGen: 4533K->96K(305856K)] 58910K->54473K(1004928K), 0.0020840 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]  
22.825: [Full GC (System) [PSYoungGen: 96K->0K(305856K)] [ParOldGen: 54377K->54377K(699072K)] 54473K->54377K(1004928K) [PSPermGen: 36536K->36536K(204800K)], 0.2505380 secs] [Times: user=0.99 sys=0.01, real=0.25 secs]  
23.077: [GC [PSYoungGen: 4530K->32K(305856K)] 58908K->54409K(1004928K), 0.0016220 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]  
23.079: [Full GC (System) [PSYoungGen: 32K->0K(305856K)] [ParOldGen: 54377K->54378K(699072K)] 54409K->54378K(1004928K) [PSPermGen: 36536K->36536K(204800K)], 0.2320970 secs] [Times: user=0.95 sys=0.00, real=0.23 secs]  
24.424: [GC [PSYoungGen: 87133K->800K(305856K)] 141512K->55179K(1004928K), 0.0038230 secs] [Times: user=0.01 sys=0.01, real=0.01 secs]  
24.428: [Full GC (System) [PSYoungGen: 800K->0K(305856K)] [ParOldGen: 54378K->54950K(699072K)] 55179K->54950K(1004928K) [PSPermGen: 37714K->37712K(204800K)], 0.4105190 secs] [Times: user=1.25 sys=0.17, real=0.41 secs]   
24.866: [GC [PSYoungGen: 4280K->256K(305856K)] 59231K->55206K(1004928K), 0.0041370 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]   
24.870: [Full GC (System) [PSYoungGen: 256K->0K(305856K)] [ParOldGen: 54950K->54789K(699072K)] 55206K->54789K(1004928K) [PSPermGen: 37720K->37719K(204800K)], 0.4160520 secs] [Times: user=1.12 sys=0.19, real=0.42 secs]  
29.041: [GC [PSYoungGen: 262208K->12901K(275136K)] 316997K->67691K(974208K), 0.0170890 secs] [Times: user=0.11 sys=0.00, real=0.02 secs]  

Answer 1

I finally found the problem, it looks like some library is calling System.gc (I still could not figure out which library and why).. I have added DisableExplicitGC option and the problem is gone.

Answer 2

It looks like your system is allocating a lot of objects at start up and maintaining references too them. If you look at the Young GC collections, e.g. [PSYoungGen: 87133K->800K(305856K)] it shows most of the objects are removed (the size of the live heap goes from 87M to 800K). However, the following Full GC suggests that they are not garbage and are being promoted into the old generation. The Full GC logs, e.g. [ParOldGen: 54950K->54789K(699072K)] show that the live heap does not reduce very much (about 0.2%). This means that most of the objects in the live old heap are still strongly referenced. I think there is one of 2 problems with your system. 1. you have a memory leak and are hanging onto objects that you don't need. 2. Your system needs a lot of memory.

If it is a memory leak, you could use a profiler to look at the types of objects being created and where they are created from to try and analyse the problem.