Erratic(?) CMS behaviour every 5d
Srinivas Ramakrishna
ysr1729 at gmail.com
Fri Sep 28 08:46:37 PDT 2012
Do you have class unloading enabled? Also, could you check if the perm gen
size is slowly increasing? (I might have time to check your detailed GC
logs later today.)
PS: have you checked to see if a more recent version of the JVM behaves
better?
-- ramki
On Thu, Sep 27, 2012 at 2:45 PM, Bernd Eckenfels <
bernd.eckenfels at googlemail.com> 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
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20120928/22bfe1ee/attachment-0001.html
More information about the hotspot-gc-use
mailing list