Erratic(?) CMS behaviour after 5d

Azeem Jiva azeem.jiva at oracle.com
Fri Sep 28 13:18:07 UTC 2012


You're seeing concurrent mode failures (see attached graph).  I'd 
recommend trying these flags:

-XX:CMSInitiatingOccupancyFraction=60 (or something smaller, experiment 
here)

It's also possible you are running out of old gen space, try increasing 
your old gen size as well.


On 09/27/2012 04:16 PM, Bernd Eckenfels wrote:
> Hello,
>
> I have talked about this before, however I had no good trace file. Now I
> have a verbose GC log.
>
> In the attached log you see a system where CMS and ParNew are running 
> more
> or less fine and stable. But then after 5d suddenly the CMS goes wild and
> shows heavy activity. I dont think it looks like the traffic/usage 
> pattern
> has changed and the old heap is pretty empty. This has been happening
> repeatedly, always after 5-6d the GC goes wild and the overall system
> performance drops.
>
> The permgen is used to 75%, so I dont think it is the issue here. Here is
> a jmap -heap output of the system at the end of that GC log timeframe:
>
> Attaching to process ID 46008, please wait...
> Debugger attached successfully.
> Server compiler detected.
> JVM version is 20.8-b03
> using parallel threads in the new generation.
> using thread-local object allocation.
> Concurrent Mark-Sweep GC
> Heap Configuration:
>      MinHeapFreeRatio = 40
>      MaxHeapFreeRatio = 70
>      MaxHeapSize      = 51539607552 (49152.0MB)
>      NewSize          = 1310720 (1.25MB)
>      MaxNewSize       = 17592186044415 MB
>      OldSize          = 5439488 (5.1875MB)
>      NewRatio         = 1
>      SurvivorRatio    = 8
>      PermSize         = 104857600 (100.0MB)
>      MaxPermSize      = 314572800 (300.0MB)
> Heap Usage:
> New Generation (Eden + 1 Survivor Space):
>      capacity = 23192862720 (22118.4375MB)
>      used     = 19142525576 (18255.734992980957MB)
>      free     = 4050337144 (3862.702507019043MB)
>      82.5362776777562% used
> Eden Space:
>      capacity = 20615921664 (19660.875MB)
>      used     = 18511946216 (17654.367652893066MB)
>      free     = 2103975448 (2006.5073471069336MB)
>      89.79441481059753% used
>   From Space:
>      capacity = 2576941056 (2457.5625MB)
>      used     = 630579360 (601.3673400878906MB)
>      free     = 1946361696 (1856.1951599121094MB)
>      24.47007309429122% used
> To Space:
>      capacity = 2576941056 (2457.5625MB)
>      used     = 0 (0.0MB)
>      free     = 2576941056 (2457.5625MB)
>      0.0% used
> concurrent mark-sweep generation:
>      capacity = 25769803776 (24576.0MB)
>      used     = 1704634416 (1625.6660614013672MB)
>      free     = 24065169360 (22950.333938598633MB)
>      6.614852137863636% used
> Perm Generation:
>      capacity = 314572800 (300.0MB)
>      used     = 238131048 (227.0994644165039MB)
>      free     = 76441752 (72.9005355834961MB)
>      75.69982147216797% used
>
>
> (note that "heap configuration" seems to be broken, I specified
> NewRatio=1, but the NewSize and MaxNewSize displayed by jmap are way off)
>
> Any Idea what can cause the GC go wild, here is an  excerpt (note that
> ParNew happens only every 300s, after 10 of those one CMS happens, etc):
>
>
> God NewGC/CMS/NewGC Cycle:
>
> 14586.770: [GC 14586.772: [ParNew: 1991511K->319572K(22649280K), 
> 0.0489290
> secs] 3229450K->1573413K(47815104K), 0.0513610 secs] [Times: user=1.29
> sys=0.01, real=0.05 secs]
> 14586.834: [GC [1 CMS-initial-mark: 1253840K(25165824K)]
> 1573413K(47815104K), 0.2554070 secs] [Times: user=0.26 sys=0.00, 
> real=0.26
> secs]
> 14587.091: [CMS-concurrent-mark-start]
> 14587.506: [CMS-concurrent-mark: 0.276/0.415 secs] [Times: user=4.29
> sys=0.06, real=0.41 secs]
> 14587.507: [CMS-concurrent-preclean-start]
> 14587.592: [CMS-concurrent-preclean: 0.085/0.085 secs] [Times: user=0.13
> sys=0.03, real=0.09 secs]
> 14587.592: [CMS-concurrent-abortable-preclean-start]
>    CMS: abort preclean due to time 14592.774:
> [CMS-concurrent-abortable-preclean: 5.180/5.182 secs] [Times: user=7.45
> sys=0.42, real=5.18 secs]
> 14592.786: [GC[YG occupancy: 860025 K (22649280 K)]14592.787: [Rescan
> (parallel) , 0.1106510 secs]14592.898: [weak refs processing, 0.0009520
> secs]14592.899: [class unloading, 0.0440260 secs]14592.943: [scrub symbol
> & string tables, 0.0386660 secs] [1 CMS-remark: 1253840K(25165824K)]
> 2113866K(47815104K), 0.2091080 secs] [Times: user=5.65 sys=0.02, 
> real=0.21
> secs]
> 14592.997: [CMS-concurrent-sweep-start]
> 14594.081: [CMS-concurrent-sweep: 1.084/1.084 secs] [Times: user=1.43
> sys=0.10, real=1.09 secs]
> 14594.081: [CMS-concurrent-reset-start]
> 14594.190: [CMS-concurrent-reset: 0.108/0.108 secs] [Times: user=0.17
> sys=0.00, real=0.11 secs]
> 15041.297: [GC 15041.299: [ParNew: 20452429K->555085K(22649280K),
> 0.3904490 secs] 21375098K->1485221K(47815104K), 0.3937640 secs] [Times:
> user=2.23 sys=0.04, real=0.39 secs]
> 15041.706: [GC 15041.707: [ParNew: 598821K->603384K(22649280K), 0.0499560
> secs] 1528957K->1542532K(47815104K), 0.0520930 secs] [Times: user=1.88
> sys=0.01, real=0.05 secs]
> 15583.968: [GC 15583.970: [ParNew: 20736120K->479921K(22649280K),
> 0.3162220 secs] 21675269K->1438894K(47815104K), 0.3195300 secs] [Times:
> user=1.66 sys=0.02, real=0.32 secs]
> 15952.644: [GC 15952.646: [ParNew: 20612657K->469661K(22649280K),
> 0.2957950 secs] 21571630K->1429526K(47815104K), 0.2989230 secs] [Times:
> user=1.73 sys=0.01, real=0.30 secs]
> 16324.194: [GC 16324.196: [ParNew: 20602397K->394671K(22649280K),
> 0.3984460 secs] 21562262K->1388556K(47815104K), 0.4017930 secs] [Times:
> user=2.08 sys=0.04, real=0.40 secs]
> 16686.481: [GC 16686.484: [ParNew: 20527410K->515765K(22649280K),
> 0.2218350 secs] 21521295K->1509652K(47815104K), 0.2252750 secs] [Times:
> user=1.90 sys=0.03, real=0.23 secs]
> 16988.880: [GC 16988.882: [ParNew: 20649063K->617925K(22649280K),
> 0.4101530 secs] 21642950K->1638935K(47815104K), 0.4135050 secs] [Times:
> user=2.38 sys=0.02, real=0.41 secs]
> 16989.316: [GC 16989.317: [ParNew: 796218K->679931K(22649280K), 0.0544170
> secs] 1817228K->1718567K(47815104K), 0.0566550 secs] [Times: user=1.92
> sys=0.04, real=0.06 secs]
> 17292.082: [GC 17292.085: [ParNew: 20812672K->520352K(22649280K),
> 0.3049860 secs] 21851308K->1566872K(47815104K), 0.3082490 secs] [Times:
> user=1.57 sys=0.02, real=0.30 secs]
> 17564.795: [GC 17564.797: [ParNew: 20653088K->473652K(22649280K),
> 0.3699550 secs] 21699608K->1572756K(47815104K), 0.3731990 secs] [Times:
> user=2.03 sys=0.05, real=0.37 secs]
> 17974.219: [GC 17974.221: [ParNew: 20606388K->423143K(22649280K),
> 0.3992190 secs] 21705492K->1572876K(47815104K), 0.4026250 secs] [Times:
> user=1.71 sys=0.03, real=0.40 secs]
> 18194.094: [GC 18194.096: [ParNew: 13619215K->538306K(22649280K),
> 0.2371980 secs] 14768948K->1688055K(47815104K), 0.2400000 secs] [Times:
> user=2.16 sys=0.03, real=0.24 secs]
>
>
> Here it becomes wild after 5d:
>
> 467312.874: [GC 467312.876: [ParNew: 20650041K->551029K(22649280K),
> 0.4254210 secs] 22325555K->2243659K(47815104K), 0.4291600 secs] [Times:
> user=2.61 sys=0.04, real=0.44 secs]
> 467519.696: [GC 467519.698: [ParNew: 20683765K->513430K(22649280K),
> 0.2666780 secs] 22376395K->2210010K(47815104K), 0.2703630 secs] [Times:
> user=2.39 sys=0.02, real=0.27 secs]
> 467523.989: [GC [1 CMS-initial-mark: 1696579K(25165824K)]
> 2728951K(47815104K), 0.7737110 secs] [Times: user=0.77 sys=0.00, 
> real=0.78
> secs]
> 467524.765: [CMS-concurrent-mark-start]
> 467525.201: [CMS-concurrent-mark: 0.420/0.436 secs] [Times: user=6.69
> sys=0.08, real=0.44 secs]
> 467525.201: [CMS-concurrent-preclean-start]
> 467525.314: [CMS-concurrent-preclean: 0.111/0.113 secs] [Times: user=0.31
> sys=0.01, real=0.11 secs]
> 467525.315: [CMS-concurrent-abortable-preclean-start]
>    CMS: abort preclean due to time 467531.001:
> [CMS-concurrent-abortable-preclean: 5.664/5.687 secs] [Times: user=10.99
> sys=0.46, real=5.69 secs]
> 467531.022: [GC[YG occupancy: 1673737 K (22649280 K)]467531.024: [Rescan
> (parallel) , 0.5323440 secs]467531.556: [weak refs processing, 0.0010300
> secs]467531.557: [class unloading, 0.0550310 secs]467531.612: [scrub
> symbol & string tables, 0.0447430 secs] [1 CMS-remark:
> 1696579K(25165824K)] 3370316K(47815104K), 0.6511260 secs] [Times:
> user=25.71 sys=0.07, real=0.65 secs]
> 467531.676: [CMS-concurrent-sweep-start]
> 467534.168: [CMS-concurrent-sweep: 2.492/2.492 secs] [Times: user=6.17
> sys=0.33, real=2.49 secs]
> 467534.168: [CMS-concurrent-reset-start]
> 467534.278: [CMS-concurrent-reset: 0.110/0.110 secs] [Times: user=0.23
> sys=0.02, real=0.11 secs]
> 467581.647: [GC [1 CMS-initial-mark: 1352729K(25165824K)]
> 7579835K(47815104K), 5.2493880 secs] [Times: user=5.24 sys=0.01, 
> real=5.25
> secs]
> 467586.898: [CMS-concurrent-mark-start]
> 467587.639: [CMS-concurrent-mark: 0.455/0.740 secs] [Times: user=7.50
> sys=0.17, real=0.74 secs]
> 467587.639: [CMS-concurrent-preclean-start]
> 467587.801: [CMS-concurrent-preclean: 0.153/0.162 secs] [Times: user=0.32
> sys=0.02, real=0.16 secs]
> 467587.802: [CMS-concurrent-abortable-preclean-start]
>    CMS: abort preclean due to time 467593.476:
> [CMS-concurrent-abortable-preclean: 5.671/5.674 secs] [Times: user=20.61
> sys=0.75, real=5.68 secs]
> 467593.497: [GC[YG occupancy: 7185297 K (22649280 K)]467593.499: [Rescan
> (parallel) , 4.9687880 secs]467598.468: [weak refs processing, 0.0000570
> secs]467598.468: [class unloading, 0.0540020 secs]467598.522: [scrub
> symbol & string tables, 0.0434850 secs] [1 CMS-remark:
> 1352729K(25165824K)] 8538026K(47815104K), 5.0845650 secs] [Times:
> user=235.75 sys=0.66, real=5.08 secs]
> 467598.584: [CMS-concurrent-sweep-start]
> 467601.429: [CMS-concurrent-sweep: 2.801/2.845 secs] [Times: user=11.65
> sys=0.42, real=2.85 secs]
> 467601.429: [CMS-concurrent-reset-start]
> 467601.539: [CMS-concurrent-reset: 0.109/0.109 secs] [Times: user=0.20
> sys=0.01, real=0.11 secs]
> 467603.561: [GC [1 CMS-initial-mark: 1352455K(25165824K)]
> 9474109K(47815104K), 7.1588640 secs] [Times: user=7.14 sys=0.01, 
> real=7.16
> secs]
> 467610.722: [CMS-concurrent-mark-start]
> 467611.120: [CMS-concurrent-mark: 0.397/0.398 secs] [Times: user=7.28
> sys=0.16, real=0.40 secs]
> 467611.120: [CMS-concurrent-preclean-start]
> 467611.224: [CMS-concurrent-preclean: 0.102/0.104 secs] [Times: user=0.58
> sys=0.03, real=0.11 secs]
> 467611.225: [CMS-concurrent-abortable-preclean-start]
>    CMS: abort preclean due to time 467617.031:
> [CMS-concurrent-abortable-preclean: 5.667/5.806 secs] [Times: user=13.49
> sys=0.50, real=5.80 secs]
> 467617.052: [GC[YG occupancy: 8991850 K (22649280 K)]467617.053: [Rescan
> (parallel) , 6.1182390 secs]467623.172: [weak refs processing, 0.0000610
> secs]467623.172: [class unloading, 0.1001680 secs]467623.272: [scrub
> symbol & string tables, 0.0434510 secs] [1 CMS-remark:
> 1352455K(25165824K)] 10344305K(47815104K), 6.2801570 secs] [Times:
> user=288.78 sys=0.80, real=6.28 secs]
> 467623.334: [CMS-concurrent-sweep-start]
> 467625.074: [CMS-concurrent-sweep: 1.706/1.740 secs] [Times: user=3.86
> sys=0.20, real=1.74 secs]
> 467625.074: [CMS-concurrent-reset-start]
> 467625.184: [CMS-concurrent-reset: 0.110/0.110 secs] [Times: user=0.27
> sys=0.01, real=0.12 secs]
> 467627.206: [GC [1 CMS-initial-mark: 1352264K(25165824K)]
> 10644634K(47815104K), 8.0760290 secs] [Times: user=8.06 sys=0.00,
> real=8.07 secs]
> 467635.284: [CMS-concurrent-mark-start]
> 467635.710: [CMS-concurrent-mark: 0.404/0.427 secs] [Times: user=6.72
> sys=0.23, real=0.42 secs]
> 467635.711: [CMS-concurrent-preclean-start]
> 467635.814: [CMS-concurrent-preclean: 0.101/0.103 secs] [Times: user=0.33
> sys=0.03, real=0.10 secs]
> 467635.814: [CMS-concurrent-abortable-preclean-start]
>    CMS: abort preclean due to time 467641.531:
> [CMS-concurrent-abortable-preclean: 5.690/5.717 secs] [Times: user=17.67
> sys=0.85, real=5.73 secs]
> 467641.552: [GC[YG occupancy: 10330198 K (22649280 K)]467641.554: [Rescan
> (parallel) , 7.7808590 secs]467649.335: [weak refs processing, 0.0001180
> secs]467649.335: [class unloading, 0.1016250 secs]467649.437: [scrub
> symbol & string tables, 0.0437740 secs] [1 CMS-remark:
> 1352264K(25165824K)] 11682462K(47815104K), 7.9447800 secs] [Times:
> user=368.46 sys=1.14, real=7.94 secs]
> 467649.499: [CMS-concurrent-sweep-start]
> 467651.175: [CMS-concurrent-sweep: 1.595/1.676 secs] [Times: user=10.23
> sys=0.41, real=1.68 secs]
> 467651.176: [CMS-concurrent-reset-start]
> 467651.285: [CMS-concurrent-reset: 0.109/0.109 secs] [Times: user=0.58
> sys=0.00, real=0.11 secs]
> 467652.306: [GC [1 CMS-initial-mark: 1352044K(25165824K)]
> 12914694K(47815104K), 10.0236240 secs] [Times: user=10.01 sys=0.01,
> real=10.02 secs]
> 467662.332: [CMS-concurrent-mark-start]
>
> You can find the GC log (1.6MB) here:
>
> https://mft.seeburger.de/portal-seefx/~public/46ed46f6-69f8-4f05-929a-5af9ab19b57f?download 
>
>
> Greetings
> Bernd

-- 
Azeem Jiva
@javawithjiva

-------------- next part --------------
A non-text attachment was scrubbed...
Name: Screenshot from 2012-09-28 08:16:35.png
Type: image/png
Size: 33938 bytes
Desc: not available
URL: <https://mail.openjdk.java.net/pipermail/hotspot-gc-dev/attachments/20120928/d830e2a7/35.png>


More information about the hotspot-gc-dev mailing list