Java garbage collection探索

1.VM参数：-XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:zoro.gc.log-Xmx50m

打印出的gc  log文件格式如下：

Java HotSpot(TM) 64-Bit Server VM (25.91-b14) for bsd-amd64 JRE (1.8.0_91-b14), built on Apr  1 2016 01:03:00 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)Memory: 4k page, physical 16777216k(545200k free)/proc/meminfo:CommandLine flags: -XX:InitialHeapSize=52428800 -XX:MaxHeapSize=52428800 -XX:MaxNewSize=17477632 -XX:MaxTenuringThreshold=6 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC 0.352: [GC (Allocation Failure) 0.352: [ParNew: 13696K->1664K(15360K), 0.0022895 secs] 13696K->2016K(49536K), 0.0023681 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 0.452: [GC (Allocation Failure) 0.452: [ParNew: 15360K->1663K(15360K), 0.0065021 secs] 15712K->3224K(49536K), 0.0065489 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] 0.520: [GC (Allocation Failure) 0.520: [ParNew: 15359K->1663K(15360K), 0.0038193 secs] 16920K->3475K(49536K), 0.0038687 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 0.619: [GC (Allocation Failure) 0.619: [ParNew: 15359K->839K(15360K), 0.0015087 secs] 17171K->2745K(49536K), 0.0015489 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 0.707: [GC (Allocation Failure) 0.707: [ParNew: 14535K->730K(15360K), 0.0010941 secs] 16441K->2636K(49536K), 0.0011279 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] ......21.399: [GC (Allocation Failure) 21.399: [ParNew: 15295K->1231K(15360K), 0.0055684 secs] 25835K->12482K(49536K), 0.0056779 secs] [Times: user=0.03 sys=0.01, real=0.01 secs] 21.405: [GC (CMS Initial Mark) [1 CMS-initial-mark: 11250K(34176K)] 12716K(49536K), 0.0007712 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 21.406: [CMS-concurrent-mark-start]21.420: [CMS-concurrent-mark: 0.015/0.015 secs] [Times: user=0.08 sys=0.00, real=0.02 secs] 21.420: [CMS-concurrent-preclean-start]21.421: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 21.421: [CMS-concurrent-abortable-preclean-start]21.475: [GC (Allocation Failure) 21.475: [ParNew: 14927K->1211K(15360K), 0.0015831 secs] 26178K->12461K(49536K), 0.0016327 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 21.554: [GC (Allocation Failure) 21.554: [ParNew: 14907K->1145K(15360K), 0.0018793 secs] 26157K->12760K(49536K), 0.0019248 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 21.597: [GC (Allocation Failure) 21.597: [ParNew: 14841K->1251K(15360K), 0.0019066 secs] 26456K->13172K(49536K), 0.0019427 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 21.626: [GC (Allocation Failure) 21.626: [ParNew: 14947K->1100K(15360K), 0.0015175 secs] 26868K->13022K(49536K), 0.0015484 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 21.648: [GC (Allocation Failure) 21.649: [ParNew: 14796K->1107K(15360K), 0.0021330 secs] 26718K->13423K(49536K), 0.0021647 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 21.651: [CMS-concurrent-abortable-preclean: 0.053/0.230 secs] [Times: user=0.83 sys=0.05, real=0.23 secs] 21.651: [GC (CMS Final Remark) [YG occupancy: 1377 K (15360 K)]21.651: [Rescan (parallel) , 0.0010526 secs]21.652: [weak refs processing, 0.0000161 secs]21.652: [class unloading, 0.0026413 secs]21.655: [scrub symbol table, 0.0030150 secs]21.658: [scrub string table, 0.0002627 secs][1 CMS-remark: 12316K(34176K)] 13693K(49536K), 0.0072790 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 21.658: [CMS-concurrent-sweep-start]21.662: [CMS-concurrent-sweep: 0.004/0.004 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 21.662: [CMS-concurrent-reset-start]21.662: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 21.680: [GC (Allocation Failure) 21.680: [ParNew: 14803K->920K(15360K), 0.0009061 secs] 25397K->11515K(49536K), 0.0009342 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 21.719: [GC (Allocation Failure) 21.719: [ParNew: 14616K->1172K(15360K), 0.0014334 secs] 25211K->11766K(49536K), 0.0014667 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 21.743: [GC (Allocation Failure) 21.743: [ParNew: 14868K->1514K(15360K), 0.0015033 secs] 25462K->12425K(49536K), 0.0015372 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 21.768: [GC (Allocation Failure) 21.768: [ParNew: 15210K->1316K(15360K), 0.0013966 secs] 26121K->12430K(49536K), 0.0014302 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 21.790: [GC (Allocation Failure) 21.790: [ParNew: 15012K->1598K(15360K), 0.0015095 secs] 26126K->12931K(49536K), 0.0015461 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 21.826: [GC (Allocation Failure) 21.826: [ParNew: 15294K->1256K(15360K), 0.0020479 secs] 26627K->13010K(49536K), 0.0020835 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 21.857: [GC (Allocation Failure) 21.857: [ParNew: 14952K->1409K(15360K), 0.0026889 secs] 26706K->13163K(49536K), 0.0027711 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 21.893: [GC (Allocation Failure) 21.893: [ParNew: 15105K->1452K(15360K), 0.0027671 secs] 26859K->13793K(49536K), 0.0028146 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 21.918: [GC (Allocation Failure) 21.918: [ParNew: 15148K->1082K(15360K), 0.0013653 secs] 27489K->13616K(49536K), 0.0013982 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 21.953: [GC (Allocation Failure) 21.953: [ParNew: 14778K->1649K(15360K), 0.0027132 secs] 27312K->14470K(49536K), 0.0027591 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] ......24.581: [GC (Allocation Failure) 24.581: [ParNew: 14826K->1242K(15360K), 0.0020681 secs] 37287K->24000K(49536K), 0.0021189 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 24.584: [GC (CMS Initial Mark) [1 CMS-initial-mark: 22757K(34176K)] 24000K(49536K), 0.0006012 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 24.584: [CMS-concurrent-mark-start]24.612: [CMS-concurrent-mark: 0.026/0.027 secs] [Times: user=0.17 sys=0.00, real=0.03 secs] 24.612: [CMS-concurrent-preclean-start]24.613: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 24.613: [CMS-concurrent-abortable-preclean-start]24.660: [GC (Allocation Failure) 24.660: [ParNew: 14938K->1155K(15360K), 0.0021686 secs] 37696K->24181K(49536K), 0.0022095 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 24.696: [CMS-concurrent-abortable-preclean: 0.037/0.083 secs] [Times: user=0.40 sys=0.02, real=0.08 secs] 24.696: [GC (CMS Final Remark) [YG occupancy: 8393 K (15360 K)]24.696: [Rescan (parallel) , 0.0017982 secs]24.698: [weak refs processing, 0.0000125 secs]24.698: [class unloading, 0.0056069 secs]24.704: [scrub symbol table, 0.0065297 secs]24.710: [scrub string table, 0.0004485 secs][1 CMS-remark: 23025K(34176K)] 31418K(49536K), 0.0146826 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 24.711: [CMS-concurrent-sweep-start]24.724: [CMS-concurrent-sweep: 0.014/0.014 secs] [Times: user=0.07 sys=0.00, real=0.01 secs] 24.724: [CMS-concurrent-reset-start]24.725: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 24.737: [GC (Allocation Failure) 24.737: [ParNew: 14851K->1408K(15360K), 0.0018607 secs] 32559K->19116K(49536K), 0.0018977 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 24.796: [GC (Allocation Failure) 24.796: [ParNew: 15104K->1253K(15360K), 0.0031151 secs] 32812K->19690K(49536K), 0.0031519 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 24.919: [GC (Allocation Failure) 24.919: [ParNew: 14949K->1663K(15360K), 0.0022003 secs] 33386K->20241K(49536K), 0.0022535 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 24.997: [GC (Allocation Failure) 24.997: [ParNew: 15359K->1663K(15360K), 0.0036855 secs] 33937K->21118K(49536K), 0.0037231 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 25.075: [GC (Allocation Failure) 25.075: [ParNew: 15359K->1663K(15360K), 0.0029750 secs] 34814K->21728K(49536K), 0.0030332 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 25.125: [GC (Allocation Failure) 25.126: [ParNew: 15359K->1664K(15360K), 0.0037313 secs] 35424K->23169K(49536K), 0.0037747 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 25.163: [GC (Allocation Failure) 25.163: [ParNew: 15360K->1664K(15360K), 0.0153039 secs] 36865K->24691K(49536K), 0.0153507 secs] [Times: user=0.11 sys=0.00, real=0.01 secs] 25.212: [GC (Allocation Failure) 25.212: [ParNew: 15360K->1664K(15360K), 0.0011898 secs] 38387K->24748K(49536K), 0.0012329 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 25.248: [GC (Allocation Failure) 25.249: [ParNew: 15360K->1664K(15360K), 0.0044245 secs] 38444K->26353K(49536K), 0.0044704 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] 25.253: [GC (CMS Initial Mark) [1 CMS-initial-mark: 24689K(34176K)] 26619K(49536K), 0.0007214 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 25.254: [CMS-concurrent-mark-start]25.276: [CMS-concurrent-mark: 0.022/0.022 secs] [Times: user=0.13 sys=0.00, real=0.02 secs] 25.276: [CMS-concurrent-preclean-start]25.277: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 25.277: [CMS-concurrent-abortable-preclean-start]25.310: [GC (Allocation Failure) 25.310: [ParNew: 15360K->842K(15360K), 0.0027769 secs] 40049K->26415K(49536K), 0.0028197 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 25.400: [CMS-concurrent-abortable-preclean: 0.013/0.123 secs] [Times: user=0.51 sys=0.00, real=0.13 secs] 25.400: [GC (CMS Final Remark) [YG occupancy: 12038 K (15360 K)]25.400: [Rescan (parallel) , 0.0028580 secs]25.403: [weak refs processing, 0.0000537 secs]25.403: [class unloading, 0.0084580 secs]25.412: [scrub symbol table, 0.0062214 secs]25.418: [scrub string table, 0.0005878 secs][1 CMS-remark: 25573K(34176K)] 37612K(49536K), 0.0182877 secs] [Times: user=0.08 sys=0.01, real=0.01 secs] 25.419: [CMS-concurrent-sweep-start]25.428: [CMS-concurrent-sweep: 0.010/0.010 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 25.428: [CMS-concurrent-reset-start]25.428: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 25.793: [GC (Allocation Failure) 25.793: [ParNew: 14538K->1663K(15360K), 0.0023048 secs] 37775K->25134K(49536K), 0.0023473 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 27.263: [GC (Allocation Failure) 27.263: [ParNew: 15359K->1664K(15360K), 0.0028278 secs] 38830K->26290K(49536K), 0.0028728 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] ......28.094: [GC (Allocation Failure) 28.094: [ParNew: 15360K->1307K(15360K), 0.0019267 secs] 45753K->32276K(49536K), 0.0019651 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 28.177: [GC (Allocation Failure) 28.177: [ParNew: 15003K->1629K(15360K), 0.0021542 secs] 45972K->33110K(49536K), 0.0022047 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 28.180: [GC (CMS Initial Mark) [1 CMS-initial-mark: 31480K(34176K)] 33384K(49536K), 0.0007713 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 28.181: [CMS-concurrent-mark-start]28.218: [CMS-concurrent-mark: 0.038/0.038 secs] [Times: user=0.23 sys=0.00, real=0.03 secs] 28.218: [CMS-concurrent-preclean-start]28.220: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 28.220: [CMS-concurrent-abortable-preclean-start]28.248: [GC (Allocation Failure) 28.248: [ParNew: 15325K->892K(15360K), 0.0022764 secs] 46806K->33094K(49536K), 0.0023272 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 28.316: [CMS-concurrent-abortable-preclean: 0.020/0.096 secs] [Times: user=0.42 sys=0.02, real=0.09 secs] 28.316: [GC (CMS Final Remark) [YG occupancy: 14588 K (15360 K)]28.316: [Rescan (parallel) , 0.0019572 secs]28.318: [weak refs processing, 0.0000510 secs]28.318: [class unloading, 0.0114522 secs]28.330: [scrub symbol table, 0.0091025 secs]28.339: [scrub string table, 0.0008593 secs][1 CMS-remark: 32202K(34176K)] 46790K(49536K), 0.0236194 secs] [Times: user=0.07 sys=0.00, real=0.03 secs] 28.340: [CMS-concurrent-sweep-start]28.342: [GC (Allocation Failure) 28.342: [ParNew: 14588K->932K(15360K), 0.0011682 secs] 46742K->33086K(49536K), 0.0012164 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 28.360: [CMS-concurrent-sweep: 0.019/0.020 secs] [Times: user=0.09 sys=0.00, real=0.02 secs] 28.360: [CMS-concurrent-reset-start]28.360: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 28.425: [GC (Allocation Failure) 28.425: [ParNew: 14628K->1488K(15360K), 0.0018670 secs] 44487K->31347K(49536K), 0.0019141 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 28.491: [GC (Allocation Failure) 28.491: [ParNew: 15184K->1279K(15360K), 0.0021584 secs] 45043K->31799K(49536K), 0.0022046 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 28.574: [GC (Allocation Failure) 28.574: [ParNew: 14975K->1550K(15360K), 0.0017569 secs] 45495K->32391K(49536K), 0.0017976 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 28.619: [GC (Allocation Failure) 28.619: [ParNew: 15246K->1407K(15360K), 0.0016409 secs] 46087K->32630K(49536K), 0.0016773 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 28.674: [GC (Allocation Failure) 28.674: [ParNew: 15103K->1542K(15360K), 0.0033892 secs] 46326K->33306K(49536K), 0.0034406 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 28.678: [GC (CMS Initial Mark) [1 CMS-initial-mark: 31763K(34176K)] 33306K(49536K), 0.0018034 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 28.680: [CMS-concurrent-mark-start]28.720: [CMS-concurrent-mark: 0.040/0.040 secs] [Times: user=0.24 sys=0.00, real=0.04 secs] 28.720: [CMS-concurrent-preclean-start]28.721: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] 28.721: [CMS-concurrent-abortable-preclean-start]28.783: [GC (Allocation Failure) 28.783: [ParNew: 15238K->1663K(15360K), 0.0020080 secs] 47002K->33867K(49536K), 0.0020497 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 28.832: [CMS-concurrent-abortable-preclean: 0.040/0.110 secs] [Times: user=0.47 sys=0.01, real=0.11 secs] 28.832: [GC (CMS Final Remark) [YG occupancy: 15359 K (15360 K)]28.832: [Rescan (parallel) , 0.0015990 secs]28.834: [weak refs processing, 0.0000154 secs]28.834: [class unloading, 0.0110656 secs]28.845: [scrub symbol table, 0.0072597 secs]28.852: [scrub string table, 0.0006640 secs][1 CMS-remark: 32203K(34176K)] 47563K(49536K), 0.0207109 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 28.853: [CMS-concurrent-sweep-start]28.854: [GC (Allocation Failure) 28.854: [ParNew: 15359K->770K(15360K), 0.0019705 secs] 47559K->33654K(49536K), 0.0020038 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 28.869: [CMS-concurrent-sweep: 0.014/0.016 secs] [Times: user=0.08 sys=0.00, real=0.01 secs] 28.869: [CMS-concurrent-reset-start]28.869: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 28.909: [GC (Allocation Failure) 28.909: [ParNew: 14466K->1340K(15360K), 0.0013277 secs] 47238K->34112K(49536K), 0.0013686 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 28.910: [GC (CMS Initial Mark) [1 CMS-initial-mark: 32772K(34176K)] 34386K(49536K), 0.0007448 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 28.911: [CMS-concurrent-mark-start]28.955: [CMS-concurrent-mark: 0.043/0.044 secs] [Times: user=0.25 sys=0.00, real=0.04 secs] 28.955: [CMS-concurrent-preclean-start]28.956: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 28.956: [CMS-concurrent-abortable-preclean-start]28.966: [GC (Allocation Failure) 28.966: [ParNew (promotion failed): 15036K->14489K(15360K), 0.0084690 secs]28.974: [CMS28.974: [CMS-concurrent-abortable-preclean: 0.006/0.019 secs] [Times: user=0.06 sys=0.01, real=0.02 secs]  (concurrent mode failure): 33261K->33696K(34176K), 0.1416585 secs] 47808K->33696K(49536K), [Metaspace: 49593K->49593K(1093632K)], 0.1501961 secs] [Times: user=0.16 sys=0.01, real=0.15 secs] 29.152: [GC (Allocation Failure) 29.152: [ParNew: 13696K->13696K(15360K), 0.0000135 secs]29.152: [CMS: 33696K->34048K(34176K), 0.1245554 secs] 47392K->34048K(49536K), [Metaspace: 49645K->49645K(1093632K)], 0.1246280 secs] [Times: user=0.36 sys=0.00, real=0.12 secs] 

2.使用命令jstat -gc -t pid 1000

因为最大堆内存设定为50M，所以频繁发生gc。

1）红色框很奇怪，因为young gc的时候，两个Survivor区应该互相交换才是，但是从结果来看，似乎都在一侧；

2）绿色框表示young gc次数

3）蓝色框表示full gc次数（full gc的概念有些歧义，更加倾向于是major gc）

相关文章：

1.https://plumbr.eu/handbook/garbage-collection-algorithms-implementations

2.https://blog.codecentric.de/en/2014/01/useful-jvm-flags-part-8-gc-logging/