This discussion is archived
1 Reply Latest reply: Oct 14, 2009 3:16 PM by 843829 RSS

Concurrent Mark Sweep GC not abiding by GC options

843829 Newbie
Currently Being Moderated
My company's webapp has been utilizing the CMS collector for almost a year now. Recently users started complaining about white screens, which we contributed to our obsessively large heap size and the fact that the RMI timer was set for every hour (and we don't use RMI) and the perm space was resizing (which caused a Full GC...that would take up to 30 secs if the heap was almost full). So I moved the RMI timer out to 24 hours and set the CMS collector to take care of Perm space. This succeeded and we no longer have an abundance of Full GCs, they are now all concurrent.

Next problem:

The CMS collector seems to be "too smart" for it's own good, because when peak load time hits, the CMS collector starts initiating way too early (around 5 - 7 gigs of heap utilized). Therefore only around 8G of our 14G heap is being utilized, and our CPU is around 60 - 70%. This isn't really a problem, but since we allocate 14G of space to the heap I would like to utilize this space instead of CPU. So I tried -XX:CMSInitiatingOccupancyFraction=60 and -XX:+UseCMSInitiatingOccupancyOnly to try to take control of when the CMS collector is initiating collections (I started low on the occupancy fraction and plan to increase). But, what I see in the logs makes me believe that the CMS collector is totally disregarding these new parameters. The CMS collections seem to be even more random than before. Here are my GC/Heap options and below that are snippets from our GC log:

-server -Xms14336m -Xmx14336m -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+CMSPermGenSweepingEnabled -XX:CMSInitiatingOccupancyFraction=60 -XX:+UseCMSInitiatingOccupancyOnly -XX:NewSize=2560m -XX:PermSize=256m -XX:SurvivorRatio=8 -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Dsun.rmi.dgc.client.gcInterval=84000000 -Dsun.rmi.dgc.server.gcInterval=84000000

14612.946: [GC 14612.946: [ParNew: 2348649K->262144K(2359296K), 1.9469691 secs] 4403236K->2365986K(14417920K), 1.9471168 secs] [Times: user=2.59 sys=0.67, real=1.95 secs]
14670.513: [GC [1 CMS-initial-mark: 2103842K(12058624K)] 3571096K(14417920K), 0.8550273 secs] [Times: user=0.84 sys=0.00, real=0.84 secs]
14671.369: [CMS-concurrent-mark-start]
14673.423: [CMS-concurrent-mark: 2.054/2.054 secs] [Times: user=2.11 sys=0.00, real=2.06 secs]
14673.423: [CMS-concurrent-preclean-start]
14673.480: [CMS-concurrent-preclean: 0.056/0.057 secs] [Times: user=0.06 sys=0.00, real=0.06 secs]
14673.480: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 14678.591: [CMS-concurrent-abortable-preclean: 0.873/5.111 secs] [Times: user=3.42 sys=0.00, real=5.11 secs]
14678.595: [GC[YG occupancy: 1510299 K (2359296 K)]14678.595: [Rescan (parallel) , 0.6706245 secs]14679.265: [weak refs processing, 0.3979575 secs]14679.663: [class unloading, 0.0627083 secs]14679.726: [scrub symbol & string tables, 0.0228238 secs] [1 CMS-remark: 2103842K(12058624K)] 3614141K(14417920K), 1.1672779 secs] [Times: user=1.25 sys=0.00, real=1.16 secs]
14679.766: [CMS-concurrent-sweep-start]
14681.854: [CMS-concurrent-sweep: 2.081/2.088 secs] [Times: user=2.42 sys=0.02, real=2.09 secs]
14681.854: [CMS-concurrent-reset-start]
14683.562: [CMS-concurrent-reset: 1.707/1.708 secs] [Times: user=2.17 sys=0.03, real=1.70 secs]
14733.655: [GC 14733.655: [ParNew: 2359296K->189853K(2359296K), 0.2648834 secs] 3356399K->1218795K(14417920K), 0.2650443 secs] [Times: user=0.69 sys=0.02, real=0.25 secs]
14796.124: [GC 14796.124: [ParNew: 2287005K->241717K(2359296K), 0.1866311 secs] 3315947K->1270660K(14417920K), 0.1867696 secs] [Times: user=0.58 sys=0.00, real=0.17 secs]
14832.143: [GC 14832.143: [ParNew: 2338869K->221217K(2359296K), 0.2507953 secs] 3367812K->1295246K(14417920K), 0.2509513 secs] [Times: user=0.69 sys=0.05, real=0.23 secs]
14920.700: [GC 14920.700: [ParNew: 2318369K->215328K(2359296K), 0.2415954 secs] 3392398K->1316602K(14417920K), 0.2417639 secs] [Times: user=0.64 sys=0.02, real=0.25 secs]
15628.082: [GC 15628.082: [ParNew: 2288005K->212559K(2359296K), 0.2569291 secs] 3675279K->1641319K(14417920K), 0.2570624 secs] [Times: user=0.83 sys=0.00, real=0.25 secs]
15654.030: [GC [1 CMS-initial-mark: 1428759K(12058624K)] 2782632K(14417920K), 0.8181906 secs] [Times: user=0.81 sys=0.00, real=0.81 secs]
15654.849: [CMS-concurrent-mark-start]
15656.902: [CMS-concurrent-mark: 2.042/2.053 secs] [Times: user=2.34 sys=0.05, real=2.05 secs]
15656.902: [CMS-concurrent-preclean-start]
15656.961: [CMS-concurrent-preclean: 0.058/0.059 secs] [Times: user=0.05 sys=0.00, real=0.06 secs]
15656.961: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 15662.145: [CMS-concurrent-abortable-preclean: 1.729/5.184 secs] [Times: user=5.00 sys=0.08, real=5.19 secs]
15662.149: [GC[YG occupancy: 1703619 K (2359296 K)]15662.149: [Rescan (parallel) , 0.7962586 secs]15662.945: [weak refs processing, 0.3231276 secs]15663.268: [class unloading, 0.0609900 secs]15663.329: [scrub symbol & string tables, 0.0221605 secs] [1 CMS-remark: 1428759K(12058624K)] 3132378K(14417920K), 1.2117037 secs] [Times: user=1.22 sys=0.00, real=1.20 secs]
15663.369: [CMS-concurrent-sweep-start]
15664.982: [CMS-concurrent-sweep: 1.605/1.612 secs] [Times: user=3.08 sys=0.08, real=1.61 secs]
15664.982: [CMS-concurrent-reset-start]
15666.149: [CMS-concurrent-reset: 1.167/1.167 secs] [Times: user=2.38 sys=0.41, real=1.17 secs]
15672.284: [GC 15672.285: [ParNew: 2306837K->183569K(2359296K), 0.2672160 secs] 3400818K->1316181K(14417920K), 0.2673458 secs] [Times: user=0.73 sys=0.00, real=0.27 secs]
15707.742: [GC 15707.742: [ParNew: 2280721K->257332K(2359296K), 0.2613859 secs] 3413333K->1424951K(14417920K), 0.2615385 secs] [Times: user=0.78 sys=0.02, real=0.25 secs]
15719.177: [GC [1 CMS-initial-mark: 1167619K(12058624K)] 2548257K(14417920K), 0.6210944 secs] [Times: user=0.59 sys=0.00, real=0.61 secs]
15719.798: [CMS-concurrent-mark-start]
15721.721: [CMS-concurrent-mark: 1.863/1.922 secs] [Times: user=2.14 sys=0.11, real=1.94 secs]
15721.721: [CMS-concurrent-preclean-start]
15721.773: [CMS-concurrent-preclean: 0.052/0.053 secs] [Times: user=0.05 sys=0.00, real=0.05 secs]
15721.774: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 15727.004: [CMS-concurrent-abortable-preclean: 1.061/5.231 secs] [Times: user=5.59 sys=0.06, real=5.23 secs]
15727.008: [GC[YG occupancy: 1674026 K (2359296 K)]15727.008: [Rescan (parallel) , 0.6717400 secs]15727.680: [weak refs processing, 0.2640532 secs]15727.944: [class unloading, 0.0741019 secs]15728.018: [scrub symbol & string tables, 0.0225081 secs] [1 CMS-remark: 1167619K(12058624K)] 2841645K(14417920K), 1.0410796 secs] [Times: user=1.06 sys=0.02, real=1.03 secs]
15728.049: [CMS-concurrent-sweep-start]
15729.299: [CMS-concurrent-sweep: 1.190/1.250 secs] [Times: user=2.03 sys=0.11, real=1.27 secs]
15729.299: [CMS-concurrent-reset-start]
15729.487: [CMS-concurrent-reset: 0.188/0.188 secs] [Times: user=0.33 sys=0.05, real=0.19 secs]
15733.725: [GC 15733.725: [ParNew: 2353559K->253011K(2359296K), 0.2682961 secs] 3464536K->1400388K(14417920K), 0.2685250 secs] [Times: user=0.81 sys=0.00, real=0.27 secs]
15776.393: [GC 15776.393: [ParNew: 2350163K->262144K(2359296K), 0.2995145 secs] 3497540K->1457247K(14417920K), 0.2996425 secs] [Times: user=0.89 sys=0.00, real=0.30 secs]
  • 1. Re: Concurrent Mark Sweep GC not abiding by GC options
    843829 Newbie
    Currently Being Moderated
    Check the occupancy of all the spaces (young, old, perm) by means of
    -XX:+PrintHeapAtGC.

    I don't believe I have seen this kind of behaviour, but suspect that perm gen collection
    might be obscuring the picture here.

    In any case, if you have not done so already, please use your support contacts into Sun to log a bug.
    For Sun service offerings, turn to http://www.sun.com/software/javaforbusiness/index.jsp