JVM调优—GC 长时间停顿问题及解决方法
2017-8-11
| 2023-6-9
0  |  0 分钟
type
status
date
slug
summary
tags
category
icon
password
标签

简介

垃圾收集器长时间停顿,表现在 Web 页面上可能是页面响应码 500 之类的服务器错误问题,如果是个支付过程可能会导致支付失败,将造成公司的直接经济损失,程序员要尽量避免或者说减少此类情况发生。

并发模式失败(concurrent mode failure)

并发模式失败日志:
165481.820: [CMS-concurrent-mark-start] 165481.847: [GC 165481.847: [ParNew: 419456K->52416K(471872K), 0.1388080 secs] 1678939K->1315679K(2044736K), 0.1389840 secs] [Times: user=0.30 sys=0.00, real=0.14 secs] 165482.711: [GC 165482.711: [ParNew: 471872K->52416K(471872K), 0.2897670 secs] 1735135K->1415603K(2044736K), 0.2901120 secs] [Times: user=0.68 sys=0.04, real=0.30 secs] 165484.160: [GC 165484.160: [ParNew: 471872K->52416K(471872K), 0.1511710 secs] 1835059K->1468617K(2044736K), 0.1514160 secs] [Times: user=0.35 sys=0.01, real=0.15 secs] 165485.025: [GC 165485.025: [ParNew: 471872K->52416K(471872K), 0.1989200 secs] 1888073K->1513178K(2044736K), 0.1991520 secs] [Times: user=0.48 sys=0.02, real=0.20 secs] 165485.499: [CMS-concurrent-mark: 2.867/3.678 secs] [Times: user=10.39 sys=0.60, real=3.68 secs] 165485.499: [CMS-concurrent-preclean-start] 165485.597: [CMS-concurrent-preclean: 0.095/0.098 secs] [Times: user=0.29 sys=0.05, real=0.10 secs] 165485.597: [CMS-concurrent-abortable-preclean-start] 165486.287: [GC 165486.287: [ParNew: 471872K->52416K(471872K), 0.4610860 secs] 1932634K->1567513K(2044736K), 0.4614320 secs] [Times: user=1.01 sys=0.05, real=0.46 secs] 165486.938: [CMS-concurrent-abortable-preclean: 0.580/1.341 secs] [Times: user=4.14 sys=0.28, real=1.34 secs] 165486.941: [GC[YG occupancy: 128659 K (471872 K)]165486.941: [Rescan (parallel) , 0.2358900 secs]165487.177: [weak refs processing, 0.0020640 secs] [1 CMS-remark: 1515097K(1572864K)] 1643757K(2044736K), 0.2381370 secs] [Times: user=0.47 sys=0.01, real=0.24 secs] 165487.181: [CMS-concurrent-sweep-start] 165488.042: [Full GC 165488.043: [CMS165488.518: [CMS-concurrent-sweep: 1.213/1.337 secs] [Times: user=3.37 sys=0.23, real=1.34 secs] (concurrent mode failure) (concurrent mode failure): 1514835K->1485873K(1572864K), 0.4853610 secs] 1986707K->1957745K(2044736K), [CMS Perm : 81695K->81695K(136412K)], 0.4856970 secs] [Times: user=0.37 sys=0.01, real=0.48 secs] 165488.532: [GC 165488.532: [ParNew: 471872K->44512K(471872K), 0.3130160 secs] 1957745K->1573798K(2044736K), 0.3133460 secs] [Times: user=0.75 sys=0.02, real=0.31 secs] 165489.568: [Full GC 165489.568: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor1602] [Unloading class sun.reflect.GeneratedMethodAccessor1597] [Unloading class sun.reflect.GeneratedMethodAccessor1592] [Unloading class sun.reflect.GeneratedMethodAccessor1594] [Unloading class sun.reflect.GeneratedMethodAccessor1598] [Unloading class sun.reflect.GeneratedMethodAccessor1555] [Unloading class sun.reflect.GeneratedMethodAccessor1599] [Unloading class sun.reflect.GeneratedMethodAccessor1600] [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor77] [Unloading class sun.reflect.GeneratedMethodAccessor1604] [Unloading class sun.reflect.GeneratedMethodAccessor1593] [Unloading class sun.reflect.GeneratedMethodAccessor1603] [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor75] [Unloading class sun.reflect.GeneratedMethodAccessor1596] [Unloading class sun.reflect.GeneratedMethodAccessor1595] [Unloading class sun.reflect.GeneratedMethodAccessor1567] [Unloading class sun.reflect.GeneratedMethodAccessor395] [Unloading class sun.reflect.GeneratedMethodAccessor1601] [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor26] : 1529286K->1392790K(1572864K), 4.5172760 secs] 1993254K->1392790K(2044736K), [CMS Perm : 81695K->81629K(136412K)], 4.5176710 secs] [Times: user=4.44 sys=0.02, real=4.52 secs] 165494.145: [GC [1 CMS-initial-mark: 1392790K(1572864K)] 1414063K(2044736K), 0.2010890 secs] [Times: user=0.20 sys=0.00, real=0.20 secs] 165494.347: [CMS-concurrent-mark-start] 165495.237: [GC 165495.237: [ParNew: 419456K->52416K(471872K), 0.2333590 secs] 1812246K->1460179K(2044736K), 0.2337080 secs] [Times: user=0.50 sys=0.01, real=0.23 secs] 165496.118: [GC 165496.118: [ParNew: 471872K->52416K(471872K), 0.1903580 secs] 1879635K->1515864K(2044736K), 0.1905860 secs] [Times: user=0.44 sys=0.03, real=0.19 secs] 165496.715: [GC 165496.715: [ParNew: 471872K->52416K(471872K), 0.2422860 secs] 1935320K->1563468K(2044736K), 0.2425610 secs] [Times: user=0.58 sys=0.02, real=0.24 secs] 165497.487: [Full GC 165497.487: [CMS165498.311: [CMS-concurrent-mark: 3.262/3.965 secs] [Times: user=11.02 sys=0.73, real=3.96 secs] (concurrent mode failure): 1511052K->1366128K(1572864K), 5.3419340 secs] 1982924K->1366128K(2044736K), [CMS Perm : 81638K->81638K(136412K)], 5.3422540 secs] [Times: user=5.28 sys=0.00, real=5.34 secs] 165503.637: [GC 165503.637: [ParNew: 419456K->52416K(471872K), 0.1635850 secs] 1785584K->1421481K(2044736K), 0.1638860 secs] [Times: user=0.39 sys=0.01, real=0.16 secs] 165503.804: [GC [1 CMS-initial-mark: 1369065K(1572864K)] 1424544K(2044736K), 0.1566690 secs] [Times: user=0.15 sys=0.00, real=0.15 secs] 165503.961: [CMS-concurrent-mark-start] 165505.133: [GC 165505.133: [ParNew: 471866K->52416K(471872K), 0.4184870 secs] 1840931K->1480980K(2044736K), 0.4188850 secs] [Times: user=0.91 sys=0.04, real=0.42 secs] 165506.175: [GC 165506.176: [ParNew: 471872K->52416K(471872K), 0.2192270 secs] 1900436K->1525506K(2044736K), 0.2194620 secs] [Times: user=0.49 sys=0.01, real=0.22 secs] 165507.094: [GC 165507.094: [ParNew: 471872K->52416K(471872K), 0.2391910 secs] 1944962K->1569157K(2044736K), 0.2394130 secs] [Times: user=0.49 sys=0.02, real=0.24 secs] 165508.178: [Full GC 165508.178: [CMS165509.030: [CMS-concurrent-mark: 4.169/5.068 secs] [Times: user=14.16 sys=1.11, real=5.07 secs] (concurrent mode failure): 1516741K->1484032K(1572864K), 8.9510320 secs] 1988613K->1484032K(2044736K), [CMS Perm : 81663K->81634K(136412K)], 8.9515060 secs] [Times: user=7.56 sys=0.15, real=8.95 secs] 165517.659: [GC 165517.659: [ParNew: 419456K->52416K(471872K), 0.1610900 secs] 1903488K->1541664K(2044736K), 0.1613260 secs] [Times: user=0.31 sys=0.00, real=0.16 secs] 165518.036: [GC [1 CMS-initial-mark: 1489248K(1572864K)] 1717780K(2044736K), 0.5143650 secs] [Times: user=0.51 sys=0.00, real=0.51 secs] 165518.552: [CMS-concurrent-mark-start] 165519.175: [GC 165519.175: [ParNew: 471872K->52416K(471872K), 0.5417870 secs] 1961120K->1606922K(2044736K), 0.5421660 secs] [Times: user=1.07 sys=0.04, real=0.54 secs] 165520.553: [Full GC 165520.553: [CMS165521.788: [CMS-concurrent-mark: 2.683/3.236 secs] [Times: user=7.05 sys=0.65, real=3.24 secs] (concurrent mode failure): 1554506K->1522781K(1572864K), 6.0295590 secs] 2026378K->1522781K(2044736K), [CMS Perm : 81634K->81634K(136412K)], 6.0298480 secs] [Times: user=5.97 sys=0.01, real=6.03 secs] 165526.774: [GC 165526.774: [ParNew: 227496K->227496K(471872K), 0.0000320 secs] 1750278K->1750278K(2044736K), 0.0001730 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] GC locker: Trying a full collection because scavenge failed 165526.774: [Full GC 165526.774: [CMS: 1522781K->1532156K(1572864K), 5.7417660 secs] 1750278K->1532156K(2044736K), [CMS Perm : 81634K->81634K(136412K)], 5.7420650 secs] [Times: user=5.67 sys=0.01, real=5.74 secs] 165532.560: [GC [1 CMS-initial-mark: 1532156K(1572864K)] 1559772K(2044736K), 0.3628570 secs] [Times: user=0.33 sys=0.02, real=0.37 secs] 165532.923: [CMS-concurrent-mark-start] 165533.668: [GC 165533.668: [ParNew: 419456K->419456K(471872K), 0.0000250 secs]165533.668: [CMS165535.512: [CMS-concurrent-mark: 2.581/2.589 secs] [Times: user=4.38 sys=0.27, real=2.59 secs] (concurrent mode failure): 1532156K->1544103K(1572864K), 7.4693280 secs] 1951612K->1544103K(2044736K), 7.4697110 secs] [Times: user=7.30 sys=0.04, real=7.47 secs] 165542.182: [GC 165542.183: [ParNew: 419456K->419456K(471872K), 0.0000450 secs]165542.183: [CMS: 1544103K->1546768K(1572864K), 4.2923010 secs] 1963559K->1546768K(2044736K), 4.2927530 secs] [Times: user=4.25 sys=0.00, real=4.29 secs] 165546.939: [GC [1 CMS-initial-mark: 1546768K(1572864K)] 1966224K(2044736K), 0.3814880 secs] [Times: user=0.37 sys=0.00, real=0.38 secs] 165547.321: [CMS-concurrent-mark-start] 165547.322: [GC 165547.323: [ParNew: 419456K->419456K(471872K), 0.0000240 secs]165547.323: [CMS165549.212: [CMS-concurrent-mark: 1.885/1.891 secs] [Times: user=1.88 sys=0.00, real=1.90 secs] (concurrent mode failure): 1546768K->1558536K(1572864K), 7.2698510 secs] 1966224K->1558536K(2044736K), 7.2701150 secs] [Times: user=7.20 sys=0.00, real=7.27 secs] 165555.162: [GC 165555.162: [ParNew: 419456K->419456K(471872K), 0.0000440 secs]165555.162: [CMS: 1558536K->1572419K(1572864K), 4.6586080 secs] 1977992K->1572419K(2044736K), 4.6590020 secs] [Times: user=4.59 sys=0.00, real=4.65 secs] 165559.919: [GC [1 CMS-initial-mark: 1572419K(1572864K)] 1693916K(2044736K), 0.3145610 secs] [Times: user=0.31 sys=0.00, real=0.32 secs] 165560.236: [CMS-concurrent-mark-start] 165560.628: [GC 165560.628: [ParNew: 419456K->419456K(471872K), 0.0000280 secs]165560.628: [CMS165562.196: [CMS-concurrent-mark: 1.954/1.961 secs] [Times: user=2.84 sys=0.19, real=1.96 secs] (concurrent mode failure): 1572419K->1572863K(1572864K), 8.8879030 secs] 1991875K->1607194K(2044736K), 8.8882080 secs] [Times: user=8.80 sys=0.00, real=8.89 secs] 165569.881: [Full GC 165569.881: [CMS: 1572863K->1572863K(1572864K), 4.8703640 secs] 1992319K->1634385K(2044736K), [CMS Perm : 81634K->81634K(136412K)], 4.8706150 secs] [Times: user=4.82 sys=0.00, real=4.88 secs] 165574.775: [GC [1 CMS-initial-mark: 1572863K(1572864K)] 1656915K(2044736K), 0.1364280 secs] [Times: user=0.14 sys=0.00, real=0.14 secs] 165574.911: [CMS-concurrent-mark-start] 165575.648: [Full GC 165575.649: [CMS165576.932: [CMS-concurrent-mark: 2.013/2.020 secs] [Times: user=3.41 sys=0.21, real=2.01 secs] (concurrent mode failure): 1572863K->1572863K(1572864K), 5.9651530 secs] 2044735K->1682474K(2044736K), [CMS Perm : 81634K->81634K(136412K)], 5.9654160 secs] [Times: user=5.91 sys=0.00, real=5.97 secs] 165582.423: [Full GC 165582.423: [CMS: 1572863K->1572864K(1572864K), 5.0236220 secs] 2044735K->1695427K(2044736K), [CMS Perm : 81634K->81634K(136412K)], 5.0239250 secs] [Times: user=4.98 sys=0.00, real=5.02 secs] 165587.448: [GC [1 CMS-initial-mark: 1572864K(1572864K)] 1697093K(2044736K), 0.1697460 secs] [Times: user=0.17 sys=0.00, real=0.17 secs] 165587.618: [CMS-concurrent-mark-start] 165588.609: [Full GC 165588.609: [CMS165589.719: [CMS-concurrent-mark: 2.093/2.100 secs] [Times: user=4.07 sys=0.63, real=2.10 secs] (concurrent mode failure): 1572864K->1572864K(1572864K), 6.7291670 secs] 2044735K->1724617K(2044736K), [CMS Perm : 81634K->81634K(136412K)], 6.7294860 secs] [Times: user=6.62 sys=0.03, real=6.73 secs] 165596.592: [Full GC 165596.592: [CMS: 1572864K->1572864K(1572864K), 4.4670560 secs] 2044735K->1735633K(2044736K), [CMS Perm : 81634K->81634K(136412K)], 4.4673550 secs] [Times: user=4.43 sys=0.00, real=4.47 secs] 165601.346: [GC [1 CMS-initial-mark: 1572864K(1572864K)] 1992320K(2044736K), 0.5660880 secs] [Times: user=0.56 sys=0.00, real=0.57 secs] 165601.913: [CMS-concurrent-mark-start] 165602.192: [Full GC 165602.192: [CMS165603.600: [CMS-concurrent-mark: 1.681/1.687 secs] [Times: user=2.27 sys=0.20, real=1.68 secs] (concurrent mode failure): 1572864K->1572863K(1572864K), 7.8641150 secs] 2044734K->1739724K(2044736K), [CMS Perm : 81634K->81634K(136412K)], 7.8643680 secs] [Times: user=7.78 sys=0.00, real=7.86 secs] 165610.597: [Full GC 165610.597: [CMS: 1572863K->1572864K(1572864K), 4.9612280 secs] 2044735K->1738303K(2044736K), [CMS Perm : 81634K->81634K(136412K)], 4.9614800 secs] [Times: user=4.92 sys=0.00, real=4.96 secs] 165615.797: [GC [1 CMS-initial-mark: 1572864K(1572864K)] 1992913K(2044736K), 0.3312260 secs] [Times: user=0.32 sys=0.00, real=0.33 secs] 165616.129: [CMS-concurrent-mark-start] 165616.507: [Full GC 165616.507: [CMS165618.227: [CMS-concurrent-mark: 2.085/2.098 secs] [Times: user=2.89 sys=0.26, real=2.10 secs] (concurrent mode failure): 1572864K->1572863K(1572864K), 8.0011150 secs] 2044735K->1733747K(2044736K), [CMS Perm : 81634K->81634K(136412K)], 8.0014230 secs] [Times: user=7.91 sys=0.00, real=8.00 secs] 165624.791: [GC [1 CMS-initial-mark: 1572863K(1572864K)] 1997838K(2044736K), 0.3768850 secs] [Times: user=0.38 sys=0.00, real=0.38 secs] 165625.168: [CMS-concurrent-mark-start] 165625.514: [Full GC 165625.514: [CMS165627.373: [CMS-concurrent-mark: 2.191/2.204 secs] [Times: user=2.95 sys=0.23, real=2.21 secs] (concurrent mode failure): 1572863K->1572863K(1572864K), 8.6134440 secs] 2044735K->1745403K(2044736K), [CMS Perm : 81634K->81634K(136412K)], 8.6138280 secs] [Times: user=8.50 sys=0.02, real=8.61 secs] 165634.940: [Full GC 165634.940: [CMS: 1572863K->1572863K(1572864K), 5.7606810 secs] 2044735K->1763133K(2044736K), [CMS Perm : 81634K->81634K(136412K)], 5.7610340 secs] [Times: user=5.70 sys=0.00, real=5.76 secs] 165640.853: [GC [1 CMS-initial-mark: 1572863K(1572864K)] 1992760K(2044736K), 0.5402960 secs] [Times: user=0.54 sys=0.00, real=0.54 secs] 165641.394: [CMS-concurrent-mark-start] 165641.711: [Full GC 165641.711: [CMS165643.146: [CMS-concurrent-mark: 1.745/1.752 secs] [Times: user=2.40 sys=0.24, real=1.75 secs] (concurrent mode failure): 1572863K->1572863K(1572864K), 7.6559090 secs] 2044735K->1806228K(2044736K), [CMS Perm : 81634K->81634K(136412K)], 7.6561430 secs] [Times: user=7.58 sys=0.00, real=7.66 secs] 165649.836: [Full GC 165649.836: [CMS: 1572863K->1572863K(1572864K), 6.5024530 secs] 2044735K->1808957K(2044736K), [CMS Perm : 81634K->81634K(136412K)], 6.5028710 secs] [Times: user=6.42 sys=0.00, real=6.50 secs] 165656.702: [GC [1 CMS-initial-mark: 1572863K(1572864K)] 1992334K(2044736K), 0.6510610 secs] [Times: user=0.65 sys=0.00, real=0.65 secs] 165657.354: [CMS-concurrent-mark-start] 165657.768: [Full GC 165657.768: [CMS165659.289: [CMS-concurrent-mark: 1.926/1.935 secs] [Times: user=2.79 sys=0.33, real=1.93 secs] (concurrent mode failure): 1572864K->1572863K(1572864K), 9.4778960 secs] 2044735K->1817502K(2044736K), [CMS Perm : 81634K->81634K(136412K)], 9.4782160 secs] [Times: user=9.15 sys=0.00, real=9.48 secs] 165668.339: [Full GC 165668.339: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor82] : 1572864K->1572863K(1572864K), 9.3393990 secs] 2044736K->1848935K(2044736K), [CMS Perm : 81634K->81631K(136412K)], 9.3398270 secs] [Times: user=9.25 sys=0.00, real=9.34 secs] 165677.949: [GC [1 CMS-initial-mark: 1572863K(1572864K)] 1993871K(2044736K), 0.6954050 secs] [Times: user=0.69 sys=0.00, real=0.70 secs] 165678.644: [CMS-concurrent-mark-start] 165679.539: [Full GC 165679.540: [CMS165681.669: [CMS-concurrent-mark: 3.012/3.025 secs] [Times: user=4.80 sys=0.64, real=3.02 secs] (concurrent mode failure): 1572863K->1572863K(1572864K), 11.9368790 secs] 2044735K->1859006K(2044736K), [CMS Perm : 81631K->81631K(136412K)], 11.9372800 secs] [Times: user=11.61 sys=0.00, real=11.94 secs] 165692.759: [Full GC 165692.759: [CMS[Unloading class sun.reflect.GeneratedConstructorAccessor240] : 1572863K->1572863K(1572864K), 11.2508310 secs] 2044735K->1874250K(2044736K), [CMS Perm : 81631K->81628K(136412K)], 11.2511750 secs] [Times: user=9.91 sys=0.00, real=11.25 secs] 165704.100: [GC [1 CMS-initial-mark: 1572863K(1572864K)] 1992415K(2044736K), 0.3157090 secs] [Times: user=0.31 sys=0.00, real=0.32 secs] 165704.416: [CMS-concurrent-mark-start] 165704.825: [Full GC 165704.825: [CMS165706.129: [CMS-concurrent-mark: 1.703/1.713 secs] [Times: user=2.54 sys=0.34, real=1.71 secs] (concurrent mode failure): 1572863K->1572863K(1572864K), 6.3984280 secs] 2044732K->1866289K(2044736K), [CMS Perm : 81628K->81628K(136412K)], 6.3986960 secs] [Times: user=6.34 sys=0.01, real=6.40 secs] 165711.728: [Full GC 165711.728: [CMS: 1572863K->1572863K(1572864K), 5.4379380 secs] 2044735K->1880349K(2044736K), [CMS Perm : 81628K->81628K(136412K)], 5.4382730 secs] [Times: user=5.39 sys=0.00, real=5.44 secs] 165717.351: [GC [1 CMS-initial-mark: 1572863K(1572864K)] 1992539K(2044736K), 0.6038490 secs] [Times: user=0.60 sys=0.00, real=0.61 secs] 165717.955: [CMS-concurrent-mark-start] 165718.302: [Full GC 165718.302: [CMS165719.904: [CMS-concurrent-mark: 1.943/1.949 secs] [Times: user=2.69 sys=0.24, real=1.95 secs] (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor25] [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor18] [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor17] [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor22] [Unloading class sun.reflect.GeneratedMethodAccessor1445] [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor24] [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor10] [Unloading class sun.reflect.GeneratedMethodAccessor441] [Unloading class sun.reflect.GeneratedMethodAccessor854] : 1572863K->1572863K(1572864K), 7.1694470 secs] 2044735K->1862162K(2044736K), [CMS Perm : 81628K->81598K(136412K)], 7.1696770 secs] [Times: user=7.09 sys=0.00, real=7.17 secs] 165726.106: [Full GC 165726.106: [CMS: 1572863K->1572862K(1572864K), 4.8448050 secs] 2044735K->1877599K(2044736K), [CMS Perm : 81598K->81598K(136412K)], 4.8451090 secs] [Times: user=4.80 sys=0.00, real=4.84 secs] 165731.084: [GC [1 CMS-initial-mark: 1572862K(1572864K)] 1992928K(2044736K), 0.3369610 secs] [Times: user=0.34 sys=0.00, real=0.33 secs] 165731.421: [CMS-concurrent-mark-start] 165731.716: [Full GC 165731.716: [CMS165733.347: [CMS-concurrent-mark: 1.919/1.925 secs] [Times: user=2.56 sys=0.20, real=1.92 secs] (concurrent mode failure): 1572862K->1572252K(1572864K), 10.0779900 secs] 2044734K->1873718K(2044736K), [CMS Perm : 81598K->81598K(136412K)], 10.0782250 secs] [Times: user=9.64 sys=0.00, real=10.08 secs] 165742.925: [Full GC 165742.925: [CMS: 1572776K->1572408K(1572864K), 6.1126860 secs] 2044648K->1887999K(2044736K), [CMS Perm : 81598K->81598K(136412K)], 6.1130120 secs] [Times: user=6.05 sys=0.00, real=6.11 secs] 165749.202: [GC [1 CMS-initial-mark: 1572408K(1572864K)] 1991990K(2044736K), 0.7009320 secs] [Times: user=0.69 sys=0.00, real=0.71 secs] 165749.903: [CMS-concurrent-mark-start] 165750.271: [Full GC 165750.271: [CMS165751.834: [CMS-concurrent-mark: 1.920/1.931 secs] [Times: user=2.65 sys=0.30, real=1.93 secs] (concurrent mode failure): 1572647K->1572863K(1572864K), 8.3700350 secs] 2044519K->1900106K(2044736K), [CMS Perm : 81598K->81598K(136412K)], 8.3703090 secs] [Times: user=8.25 sys=0.00, real=8.38 secs] 165759.574: [Full GC 165759.574: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor19] : 1572863K->1572863K(1572864K), 5.2368120 secs] 2044735K->1906019K(2044736K), [CMS Perm : 81598K->81594K(136412K)], 5.2371710 secs] [Times: user=5.17 sys=0.01, real=5.24 secs] 165764.957: [GC [1 CMS-initial-mark: 1572863K(1572864K)] 1992752K(2044736K), 0.5464550 secs] [Times: user=0.54 sys=0.00, real=0.55 secs] 165765.504: [CMS-concurrent-mark-start] 165765.849: [Full GC 165765.849: [CMS165767.557: [CMS-concurrent-mark: 2.043/2.053 secs] [Times: user=2.59 sys=0.28, real=2.05 secs] (concurrent mode failure)

两个原因:

  • 在 CMS 启动过程中,新生代提升速度过快,老年代收集速度赶不上新生代提升速度
  • 在 CMS 启动过程中,老年代碎片化严重,无法容纳新生代提升上来的大对象
发送这种情况,应用线程将会全部停止(相当于网站这段时间无法响应用户请求),进行压缩式垃圾收集(回退到 Serial Old 算法)

解决办法:

新生代提升过快问题:
  • 如果频率太快的话,说明空间不足,首先可以尝试调大新生代空间和晋升阈值。
  • 如果内存有限,可以设置 CMS 垃圾收集在老年代占比达到多少时启动来减少问题发生频率(越早启动问题发生频率越低,但是会降低吞吐量,具体得多调整几次找到平衡点),参数如下:如果没有第二个参数,会随着 JVM 动态调节 CMS 启动时间
-XX:CMSInitiatingOccupancyFraction=68 (默认是 68) -XX:+UseCMSInitiatingOccupancyOnly
老年代碎片严重问题:
  • 如果频率太快或者 Full GC 后空间释放不多的话,说明空间不足,首先可以尝试调大老年代空间
  • 如果内存不足,可以设置进行 n 次 CMS 后进行一次压缩式 Full GC,参数如下:
-XX:+UseCMSCompactAtFullCollection:允许在 Full GC 时,启用压缩式 GC -XX:CMSFullGCBeforeCompaction=n 在进行 n 次,CMS 后,进行一次压缩的 Full GC,用以减少 CMS 产生的碎片

提升失败(promotion failed)

Minor GC 过程中,Survivor Unused 可能不足以容纳 Eden 和另一个 Survivor 中的存活对象, 那么多余的将被移到老年代, 称为过早提升(Premature Promotion)。 这会导致老年代中短期存活对象的增长, 可能会引发严重的性能问题。 再进一步, 如果老年代满了, Minor GC 后会进行 Full GC, 这将导致遍历整个堆, 称为提升失败(Promotion Failure)。
提升失败日志:
2016-01-07T18:54:26.948+0800: 18782.967: [GC2016-04-07T18:54:26.948+0800: 18782.967: [ParNew (promotion failed) Desired survivor size 117833728 bytes, new threshold 10 (max 10) - age 1: 6141680 bytes, 6141680 total - age 2: 6337936 bytes, 12479616 total - age 3: 549120 bytes, 13028736 total - age 4: 87768 bytes, 13116504 total - age 5: 221384 bytes, 13337888 total - age 6: 934168 bytes, 14272056 total - age 7: 146072 bytes, 14418128 total - age 8: 626064 bytes, 15044192 total - age 9: 398000 bytes, 15442192 total - age 10: 429616 bytes, 15871808 total : 1969227K->1929200K(2071808K), 0.7452140 secs]2016-01-07T18:54:27.693+0800: 18783.713: [CMS: 1394703K->632845K(2097152K), 4.0993640 secs] 3301676K->632845K(4168960K), [CMS Perm : 77485K->77473K(159744K)], 4.8450240 secs] [Times: user=5.18 sys=0.56, real=4.84 secs] Heap after GC invocations=5847 (full 7): par new generation total 2071808K, used 0K [0x00000006e9c00000, 0x0000000776400000, 0x0000000776400000) eden space 1841664K, 0% used [0x00000006e9c00000, 0x00000006e9c00000, 0x000000075a280000) from space 230144K, 0% used [0x0000000768340000, 0x0000000768340000, 0x0000000776400000) to space 230144K, 0% used [0x000000075a280000, 0x000000075a280000, 0x0000000768340000) concurrent mark-sweep generation total 2097152K, used 632845K [0x0000000776400000, 0x00000007f6400000, 0x00000007f6400000) concurrent-mark-sweep perm gen total 159744K, used 77473K [0x00000007f6400000, 0x0000000800000000, 0x0000000800000000) }

提升失败原因:

  • Minor GC 时发现 Survivor 空间放不下,而老年代的空闲也不够
  • 新生代提升太快
  • 老年代碎片太多,放不下大对象提升(表现为老年代还有很多空间但是,出现了 promotion failed

解决方法:

  • 两条和上面 concurrent mode failure 一样
  • 另一条,是因为 Survivor Unused 不足,那么可以尝试调大 Survivor 来尝试下

在 GC 的时候其他系统活动影响

有些时候系统活动诸如内存换入换出(vmstat)、网络活动(netstat)、I/O (iostat)在 GC 过程中发生会使 GC 时间变长。
前提是你的服务器上是有 SWAP 区域(用 top、 vmstat 等命令可以看出)用于内存的换入换出,那么操作系统可能会将 JVM 中不活跃的内存页换到 SWAP 区域用以释放内存给线程使用(这也透露出内存开始不够用了)。内存换入换出是一个开销巨大的磁盘操作,比内存访问慢好几个数量级。
看一段 GC 日志:耗时 29.47 秒
{Heap before GC invocations=132 (full 0): par new generation total 2696384K, used 2696384K [0xfffffffc20010000, 0xfffffffce0010000, 0xfffffffce0010000) eden space 2247040K, 100% used [0xfffffffc20010000, 0xfffffffca9270000, 0xfffffffca9270000) from space 449344K, 100% used [0xfffffffca9270000, 0xfffffffcc4940000, 0xfffffffcc4940000) to space 449344K, 0% used [0xfffffffcc4940000, 0xfffffffcc4940000, 0xfffffffce0010000) concurrent mark-sweep generation total 9437184K, used 1860619K [0xfffffffce0010000, 0xffffffff20010000, 0xffffffff20010000) concurrent-mark-sweep perm gen total 1310720K, used 511451K [0xffffffff20010000, 0xffffffff70010000, 0xffffffff70010000) 2013-07-17T03:58:06.601-0700: 51522.120: [GC Before GC: : 2696384K->449344K(2696384K), 29.4779282 secs] 4557003K->2326821K(12133568K) ,29.4795222 secs] [Times: user=915.56 sys=6.35, real=29.48 secs]
再看看此时的 vmstat 命令中 si、so 列的数值,如果数值大说明换入换出严重,这是内存不足的表现。

解决方法:

减少线程,这样可以降低内存换入换出;增加内存;如果是 JVM 内存设置过大导致线程所用内存不足,则适当调低 -Xmx-Xms

JVM 的 bug

这种原因就根据自己使用的 JDK 版本去查一下,如果是 JVM 的 bug,升级到解决的版本一般就能解决。

总结

长时间停顿问题的排查及解决首先需要一定的信息和方法论:
  • 详细的 GC 日志
  • 借助 Linux 平台下的 iostat、vmstat、netstat、mpstat 等命令监控系统情况
  • 使用 GCHisto 这个 GC 图形用户界面工具,可以统计出 Minor GC 及 Full GC 频率及时长分布
  • 查看 GC 日志中是否出现了上述的典型内存异常问题(promotion failed, concurrent mode failure),整体来说把上述两个典型内存异常情况控制在可接受的发生频率即可,对 CMS 碎片问题来说杜绝以上问题似乎不太可能,只能靠 G1 来解决了
  • 是不是 JVM 本身的 bug 导致的
  • 如果程序没问题,参数调了几次还是不能解决,可能说明流量太大,需要加机器把压力分散到更多 JVM 上

参考资料

转载 : wenniuwuren
 
Java
  • Java
  • Jvm
  • JVM GC算法 CMS 详解服务发现比较:Consul vs Zookeeper vs Etcd vs Eureka
    目录