search

bingoogolapple / bingoogolapple.github.io

个人主页。同时也通过 Issues 记录学习笔记
http://www.bingoogolapple.cn
86 stars 22 forks source link

GC 日志分析 - CMS - Concurrent Mark and Sweep（并发标记-清除） #185

Open bingoogolapple opened 6 years ago

bingoogolapple commented 6 years ago 
Java HotSpot(TM) 64-Bit Server VM (25.131-b11) for bsd-amd64 JRE (1.8.0_131-b11), built on Mar 15 2017 01:32:22 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
Memory: 4k page, physical 8388608k(2156824k free)

/proc/meminfo:

CommandLine flags: -XX:InitialHeapSize=2147483648 -XX:MaxHeapSize=2147483648 -XX:MaxNewSize=348966912 -XX:MaxTenuringThreshold=6 -XX:NewSize=348966912 -XX:OldPLABSize=16 -XX:OldSize=697933824 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:ThreadStackSize=256 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC

2017-07-27T10:42:50.466-0800: 1.139: [GC (Allocation Failure)
  2017-07-27T10:42:50.466-0800: 1.139: [ParNew: 272640K->34014K(306688K), 0.2036209 secs]
  272640K->261639K(2063104K),
0.2038045 secs]
[Times: user=0.18 sys=0.45, real=0.21 secs]

2017-07-27T10:42:51.471-0800: 2.144: [GC (Allocation Failure)
  2017-07-27T10:42:51.472-0800: 2.144: [ParNew: 306654K->34039K(306688K), 0.2372089 secs]
  534279K->531300K(2063104K),
0.2373221 secs]
[Times: user=0.19 sys=0.55, real=0.23 secs]

2017-07-27T10:42:52.565-0800: 3.238: [GC (Allocation Failure)
  2017-07-27T10:42:52.565-0800: 3.238: [ParNew: 306679K->34034K(306688K), 0.2274939 secs]
  803940K->800732K(2063104K),
0.2276053 secs]
[Times: user=0.20 sys=0.47, real=0.23 secs]

2017-07-27T10:42:53.570-0800: 4.243: [GC (Allocation Failure)
  2017-07-27T10:42:53.570-0800: 4.243: [ParNew: 306555K->34025K(306688K), 0.2329599 secs]
  1073252K->1068232K(2063104K),
0.2330795 secs]
[Times: user=0.36 sys=0.32, real=0.23 secs]

2017-07-27T10:42:53.804-0800: 4.477: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1034206K(1756416K)] 1071749K(2063104K), 0.0108366 secs] [Times: user=0.01 sys=0.01, real=0.01 secs]
2017-07-27T10:42:53.815-0800: 4.488: [CMS-concurrent-mark-start]
2017-07-27T10:42:53.838-0800: 4.511: [CMS-concurrent-mark: 0.024/0.024 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
2017-07-27T10:42:53.838-0800: 4.511: [CMS-concurrent-preclean-start]
2017-07-27T10:42:53.842-0800: 4.515: [CMS-concurrent-preclean: 0.004/0.004 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2017-07-27T10:42:53.842-0800: 4.515: [CMS-concurrent-abortable-preclean-start]
2017-07-27T10:42:54.666-0800: 5.339: [GC (Allocation Failure) 2017-07-27T10:42:54.666-0800: 5.339: [ParNew2017-07-27T10:42:54.719-0800: 5.391: [CMS-concurrent-abortable-preclean: 0.048/0.876 secs] [Times: user=0.23 sys=0.04, real=0.87 secs]
: 306665K->34002K(306688K), 0.2280353 secs] 1340872K->1338040K(2063104K), 0.2281577 secs] [Times: user=0.25 sys=0.41, real=0.23 secs]
2017-07-27T10:42:54.894-0800: 5.567: [GC (CMS Final Remark) [YG occupancy: 36612 K (306688 K)]2017-07-27T10:42:54.894-0800: 5.567: [Rescan (parallel) , 0.0024003 secs]2017-07-27T10:42:54.897-0800: 5.570: [weak refs processing, 0.0000369 secs]2017-07-27T10:42:54.897-0800: 5.570: [class unloading, 0.0004609 secs]2017-07-27T10:42:54.897-0800: 5.570: [scrub symbol table, 0.0006534 secs]2017-07-27T10:42:54.898-0800: 5.571: [scrub string table, 0.0001607 secs][1 CMS-remark: 1304037K(1756416K)] 1340650K(2063104K), 0.0038603 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
2017-07-27T10:42:54.898-0800: 5.571: [CMS-concurrent-sweep-start]
2017-07-27T10:42:54.905-0800: 5.578: [CMS-concurrent-sweep: 0.006/0.006 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2017-07-27T10:42:54.905-0800: 5.578: [CMS-concurrent-reset-start]
2017-07-27T10:42:54.915-0800: 5.588: [CMS-concurrent-reset: 0.010/0.010 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

2017-07-27T10:42:55.668-0800: 6.341: [GC (Allocation Failure)
  2017-07-27T10:42:55.668-0800: 6.341: [ParNew: 306642K->34008K(306688K), 0.2533204 secs]
  1610647K->1603624K(2063104K),
0.2534524 secs]
[Times: user=0.66 sys=0.19, real=0.26 secs]

2017-07-27T10:42:55.935-0800: 6.608: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1569615K(1756416K)] 1655496K(2063104K), 0.0039640 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2017-07-27T10:42:55.942-0800: 6.614: [CMS-concurrent-mark-start]
2017-07-27T10:42:55.961-0800: 6.634: [CMS-concurrent-mark: 0.019/0.019 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
2017-07-27T10:42:55.961-0800: 6.634: [CMS-concurrent-preclean-start]
2017-07-27T10:42:55.968-0800: 6.640: [CMS-concurrent-preclean: 0.007/0.007 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
2017-07-27T10:42:55.968-0800: 6.640: [CMS-concurrent-abortable-preclean-start]
2017-07-27T10:42:56.290-0800: 6.963: [CMS-concurrent-abortable-preclean: 0.016/0.323 secs] [Times: user=0.03 sys=0.00, real=0.33 secs]
2017-07-27T10:42:56.291-0800: 6.963: [GC (CMS Final Remark) [YG occupancy: 199103 K (306688 K)]2017-07-27T10:42:56.291-0800: 6.963: [Rescan (parallel) , 0.0027865 secs]2017-07-27T10:42:56.293-0800: 6.966: [weak refs processing, 0.0000397 secs]2017-07-27T10:42:56.294-0800: 6.966: [class unloading, 0.0004163 secs]2017-07-27T10:42:56.294-0800: 6.967: [scrub symbol table, 0.0006806 secs]2017-07-27T10:42:56.295-0800: 6.967: [scrub string table, 0.0001862 secs][1 CMS-remark: 1569615K(1756416K)] 1768718K(2063104K), 0.0043575 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
2017-07-27T10:42:56.295-0800: 6.968: [CMS-concurrent-sweep-start]
2017-07-27T10:42:56.298-0800: 6.971: [CMS-concurrent-sweep: 0.003/0.003 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2017-07-27T10:42:56.299-0800: 6.971: [CMS-concurrent-reset-start]
2017-07-27T10:42:56.304-0800: 6.976: [CMS-concurrent-reset: 0.005/0.005 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

2017-07-27T10:42:56.770-0800: 7.443: [GC (Allocation Failure)
  2017-07-27T10:42:56.770-0800: 7.443: [ParNew: 306648K->34006K(306688K), 0.1443112 secs]
  1569033K->1568868K(2063104K),
0.1444384 secs]
[Times: user=0.24 sys=0.01, real=0.14 secs]

2017-07-27T10:42:56.915-0800: 7.588: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1534862K(1756416K)] 1569073K(2063104K), 0.0003244 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2017-07-27T10:42:56.915-0800: 7.588: [CMS-concurrent-mark-start]
2017-07-27T10:42:56.932-0800: 7.604: [CMS-concurrent-mark: 0.016/0.016 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
2017-07-27T10:42:56.932-0800: 7.604: [CMS-concurrent-preclean-start]
2017-07-27T10:42:56.935-0800: 7.608: [CMS-concurrent-preclean: 0.004/0.004 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2017-07-27T10:42:56.936-0800: 7.608: [CMS-concurrent-abortable-preclean-start]
2017-07-27T10:42:57.481-0800: 8.153: [CMS-concurrent-abortable-preclean: 0.029/0.545 secs] [Times: user=0.07 sys=0.00, real=0.55 secs]
2017-07-27T10:42:57.481-0800: 8.154: [GC (CMS Final Remark) [YG occupancy: 233077 K (306688 K)]2017-07-27T10:42:57.481-0800: 8.154: [Rescan (parallel) , 0.0025946 secs]2017-07-27T10:42:57.484-0800: 8.156: [weak refs processing, 0.0000296 secs]2017-07-27T10:42:57.484-0800: 8.156: [class unloading, 0.0004264 secs]2017-07-27T10:42:57.484-0800: 8.157: [scrub symbol table, 0.0006851 secs]2017-07-27T10:42:57.485-0800: 8.157: [scrub string table, 0.0001873 secs][1 CMS-remark: 1534862K(1756416K)] 1767940K(2063104K), 0.0040615 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
2017-07-27T10:42:57.485-0800: 8.158: [CMS-concurrent-sweep-start]
2017-07-27T10:42:57.488-0800: 8.161: [CMS-concurrent-sweep: 0.003/0.003 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2017-07-27T10:42:57.489-0800: 8.161: [CMS-concurrent-reset-start]
2017-07-27T10:42:57.494-0800: 8.167: [CMS-concurrent-reset: 0.005/0.005 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

2017-07-27T10:42:57.770-0800: 8.443: [GC (Allocation Failure)
  2017-07-27T10:42:57.770-0800: 8.443: [ParNew: 306468K->34018K(306688K), 0.1606080 secs]
  1638353K->1636691K(2063104K),
0.1607350 secs]
[Times: user=0.42 sys=0.06, real=0.16 secs]

2017-07-27T10:42:57.931-0800: 8.604: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1602672K(1756416K)] 1636896K(2063104K), 0.0009465 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2017-07-27T10:42:57.932-0800: 8.605: [CMS-concurrent-mark-start]
2017-07-27T10:42:57.949-0800: 8.621: [CMS-concurrent-mark: 0.017/0.017 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2017-07-27T10:42:57.949-0800: 8.622: [CMS-concurrent-preclean-start]
2017-07-27T10:42:57.953-0800: 8.625: [CMS-concurrent-preclean: 0.004/0.004 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2017-07-27T10:42:57.953-0800: 8.626: [CMS-concurrent-abortable-preclean-start]
2017-07-27T10:42:58.282-0800: 8.955: [CMS-concurrent-abortable-preclean: 0.018/0.329 secs] [Times: user=0.05 sys=0.00, real=0.33 secs]
2017-07-27T10:42:58.282-0800: 8.955: [GC (CMS Final Remark) [YG occupancy: 166906 K (306688 K)]2017-07-27T10:42:58.282-0800: 8.955: [Rescan (parallel) , 0.0029898 secs]2017-07-27T10:42:58.285-0800: 8.958: [weak refs processing, 0.0000310 secs]2017-07-27T10:42:58.285-0800: 8.958: [class unloading, 0.0004478 secs]2017-07-27T10:42:58.286-0800: 8.958: [scrub symbol table, 0.0007238 secs]2017-07-27T10:42:58.286-0800: 8.959: [scrub string table, 0.0002156 secs][1 CMS-remark: 1602672K(1756416K)] 1769578K(2063104K), 0.0045563 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
2017-07-27T10:42:58.287-0800: 8.959: [CMS-concurrent-sweep-start]
2017-07-27T10:42:58.291-0800: 8.963: [CMS-concurrent-sweep: 0.004/0.004 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2017-07-27T10:42:58.291-0800: 8.963: [CMS-concurrent-reset-start]
2017-07-27T10:42:58.296-0800: 8.969: [CMS-concurrent-reset: 0.005/0.005 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

2017-07-27T10:42:58.870-0800: 9.542: [GC (Allocation Failure)
  2017-07-27T10:42:58.870-0800: 9.542: [ParNew: 306658K->34008K(306688K), 0.1568333 secs]
  1702635K->1699707K(2063104K),
0.1569727 secs]
[Times: user=0.44 sys=0.05, real=0.15 secs]

2017-07-27T10:42:59.027-0800: 9.700: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1665699K(1756416K)] 1705318K(2063104K), 0.0002779 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2017-07-27T10:42:59.027-0800: 9.700: [CMS-concurrent-mark-start]
2017-07-27T10:42:59.047-0800: 9.720: [CMS-concurrent-mark: 0.020/0.020 secs] [Times: user=0.04 sys=0.00, real=0.02 secs]
2017-07-27T10:42:59.047-0800: 9.720: [CMS-concurrent-preclean-start]
2017-07-27T10:42:59.051-0800: 9.723: [CMS-concurrent-preclean: 0.004/0.004 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2017-07-27T10:42:59.051-0800: 9.724: [CMS-concurrent-abortable-preclean-start]
2017-07-27T10:42:59.157-0800: 9.830: [CMS-concurrent-abortable-preclean: 0.004/0.106 secs] [Times: user=0.01 sys=0.00, real=0.10 secs]
2017-07-27T10:42:59.157-0800: 9.830: [GC (CMS Final Remark) [YG occupancy: 102742 K (306688 K)]2017-07-27T10:42:59.157-0800: 9.830: [Rescan (parallel) , 0.0026914 secs]2017-07-27T10:42:59.160-0800: 9.833: [weak refs processing, 0.0000324 secs]2017-07-27T10:42:59.160-0800: 9.833: [class unloading, 0.0004596 secs]2017-07-27T10:42:59.161-0800: 9.833: [scrub symbol table, 0.0006945 secs]2017-07-27T10:42:59.161-0800: 9.834: [scrub string table, 0.0001893 secs][1 CMS-remark: 1665699K(1756416K)] 1768441K(2063104K), 0.0042049 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2017-07-27T10:42:59.162-0800: 9.834: [CMS-concurrent-sweep-start]
2017-07-27T10:42:59.166-0800: 9.838: [CMS-concurrent-sweep: 0.004/0.004 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2017-07-27T10:42:59.166-0800: 9.838: [CMS-concurrent-reset-start]
2017-07-27T10:42:59.176-0800: 9.848: [CMS-concurrent-reset: 0.010/0.010 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

2017-07-27T10:42:59.872-0800: 10.544: [GC (Allocation Failure) 2017-07-27T10:42:59.872-0800: 10.545: [ParNew (promotion failed): 306476K->306477K(306688K), 0.1537088 secs]2017-07-27T10:43:00.026-0800: 10.698: [CMS: 1708163K->1562328K(1756416K), 0.6213842 secs] 1746873K->1562328K(2063104K), [Metaspace: 3152K->3152K(1056768K)], 0.7752991 secs] [Times: user=0.95 sys=0.06, real=0.77 secs]

2017-07-27T10:43:00.648-0800: 11.320: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1562328K(1756416K)] 1568021K(2063104K), 0.0002750 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
2017-07-27T10:43:00.648-0800: 11.321: [CMS-concurrent-mark-start]
2017-07-27T10:43:00.683-0800: 11.356: [CMS-concurrent-mark: 0.035/0.035 secs] [Times: user=0.07 sys=0.00, real=0.04 secs]
2017-07-27T10:43:00.683-0800: 11.356: [CMS-concurrent-preclean-start]
2017-07-27T10:43:00.688-0800: 11.361: [CMS-concurrent-preclean: 0.005/0.005 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
2017-07-27T10:43:00.689-0800: 11.361: [CMS-concurrent-abortable-preclean-start]
2017-07-27T10:43:00.796-0800: 11.469: [CMS-concurrent-abortable-preclean: 0.004/0.107 secs] [Times: user=0.02 sys=0.00, real=0.11 secs]
2017-07-27T10:43:00.796-0800: 11.469: [GC (CMS Final Remark) [YG occupancy: 231200 K (306688 K)]2017-07-27T10:43:00.796-0800: 11.469: [Rescan (parallel) , 0.0039800 secs]2017-07-27T10:43:00.800-0800: 11.473: [weak refs processing, 0.0000448 secs]2017-07-27T10:43:00.800-0800: 11.473: [class unloading, 0.0005073 secs]2017-07-27T10:43:00.801-0800: 11.473: [scrub symbol table, 0.0010072 secs]2017-07-27T10:43:00.802-0800: 11.474: [scrub string table, 0.0002594 secs][1 CMS-remark: 1562328K(1756416K)] 1793528K(2063104K), 0.0059938 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2017-07-27T10:43:00.802-0800: 11.475: [CMS-concurrent-sweep-start]
2017-07-27T10:43:00.806-0800: 11.479: [CMS-concurrent-sweep: 0.004/0.004 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2017-07-27T10:43:00.806-0800: 11.479: [CMS-concurrent-reset-start]
2017-07-27T10:43:00.813-0800: 11.486: [CMS-concurrent-reset: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

2017-07-27T10:43:00.967-0800: 11.639: [GC (Allocation Failure) 2017-07-27T10:43:00.967-0800: 11.639: [ParNew: 272523K->272523K(306688K), 0.0000304 secs]2017-07-27T10:43:00.967-0800: 11.639: [CMS: 1493918K->1618668K(1756416K), 0.5884151 secs] 1766441K->1618668K(2063104K), [Metaspace: 3152K->3152K(1056768K)], 0.5886111 secs] [Times: user=0.55 sys=0.01, real=0.59 secs]

2017-07-27T10:43:01.556-0800: 12.229: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1618668K(1756416K)] 1624344K(2063104K), 0.0002740 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2017-07-27T10:43:01.557-0800: 12.230: [CMS-concurrent-mark-start]
2017-07-27T10:43:01.587-0800: 12.259: [CMS-concurrent-mark: 0.029/0.029 secs] [Times: user=0.07 sys=0.00, real=0.03 secs]
2017-07-27T10:43:01.587-0800: 12.259: [CMS-concurrent-preclean-start]
2017-07-27T10:43:01.591-0800: 12.264: [CMS-concurrent-preclean: 0.004/0.004 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2017-07-27T10:43:01.591-0800: 12.264: [CMS-concurrent-abortable-preclean-start]
2017-07-27T10:43:02.068-0800: 12.740: [GC (Allocation Failure) 2017-07-27T10:43:02.068-0800: 12.740: [ParNew2017-07-27T10:43:02.125-0800: 12.798: [CMS-concurrent-abortable-preclean: 0.021/0.534 secs] [Times: user=0.23 sys=0.00, real=0.53 secs]
 (promotion failed): 272639K->306648K(306688K), 0.0674296 secs]2017-07-27T10:43:02.135-0800: 12.808: [CMS (concurrent mode failure): 1756268K->1672499K(1756416K), 0.6006566 secs] 1891308K->1672499K(2063104K), [Metaspace: 3154K->3154K(1056768K)], 0.6682758 secs] [Times: user=0.79 sys=0.01, real=0.67 secs]

2017-07-27T10:43:03.069-0800: 13.742: [GC (Allocation Failure) 2017-07-27T10:43:03.069-0800: 13.742: [ParNew: 272640K->272640K(306688K), 0.0000406 secs]2017-07-27T10:43:03.069-0800: 13.742: [CMS: 1672499K->1726228K(1756416K), 0.5934777 secs] 1945139K->1726228K(2063104K), [Metaspace: 3163K->3163K(1056768K)], 0.5936850 secs] [Times: user=0.57 sys=0.01, real=0.60 secs]

2017-07-27T10:43:03.665-0800: 14.337: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1726228K(1756416K)] 1734205K(2063104K), 0.0004136 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2017-07-27T10:43:03.666-0800: 14.338: [CMS-concurrent-mark-start]
2017-07-27T10:43:03.706-0800: 14.379: [CMS-concurrent-mark: 0.040/0.040 secs] [Times: user=0.08 sys=0.01, real=0.04 secs]
2017-07-27T10:43:03.706-0800: 14.379: [CMS-concurrent-preclean-start]
2017-07-27T10:43:03.711-0800: 14.383: [CMS-concurrent-preclean: 0.005/0.005 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2017-07-27T10:43:03.711-0800: 14.383: [CMS-concurrent-abortable-preclean-start]
2017-07-27T10:43:03.711-0800: 14.383: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2017-07-27T10:43:03.711-0800: 14.383: [GC (CMS Final Remark) [YG occupancy: 164313 K (306688 K)]2017-07-27T10:43:03.711-0800: 14.383: [Rescan (parallel) , 0.0026526 secs]2017-07-27T10:43:03.714-0800: 14.386: [weak refs processing, 0.0000293 secs]2017-07-27T10:43:03.714-0800: 14.386: [class unloading, 0.0009635 secs]2017-07-27T10:43:03.715-0800: 14.388: [scrub symbol table, 0.0014278 secs]2017-07-27T10:43:03.717-0800: 14.389: [scrub string table, 0.0001779 secs][1 CMS-remark: 1726228K(1756416K)] 1890541K(2063104K), 0.0057687 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2017-07-27T10:43:03.717-0800: 14.389: [CMS-concurrent-sweep-start]
2017-07-27T10:43:03.721-0800: 14.393: [CMS-concurrent-sweep: 0.004/0.004 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2017-07-27T10:43:03.721-0800: 14.394: [CMS-concurrent-reset-start]
2017-07-27T10:43:03.729-0800: 14.401: [CMS-concurrent-reset: 0.007/0.007 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2017-07-27T10:43:04.169-0800: 14.841: [GC (Allocation Failure) 2017-07-27T10:43:04.169-0800: 14.841: [ParNew (promotion failed): 272640K->306644K(306688K), 0.0452558 secs]2017-07-27T10:43:04.214-0800: 14.887: [CMS: 1756147K->1756348K(1756416K), 0.5361627 secs] 1935168K->1780519K(2063104K), [Metaspace: 3163K->3163K(1056768K)], 0.5816062 secs] [Times: user=0.68 sys=0.01, real=0.59 secs]
2017-07-27T10:43:04.751-0800: 15.423: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1756348K(1756416K)] 1786069K(2063104K), 0.0003120 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2017-07-27T10:43:04.751-0800: 15.424: [CMS-concurrent-mark-start]

Heap
 par new generation   total 306688K, used 48795K [0x0000000740000000, 0x0000000754cc0000, 0x0000000754cc0000)
  eden space 272640K,  17% used [0x0000000740000000, 0x0000000742fa6f50, 0x0000000750a40000)
  from space 34048K,   0% used [0x0000000750a40000, 0x0000000750a40000, 0x0000000752b80000)
  to   space 34048K,   0% used [0x0000000752b80000, 0x0000000752b80000, 0x0000000754cc0000)
 concurrent mark-sweep generation total 1756416K, used 1756348K [0x0000000754cc0000, 0x00000007c0000000, 0x00000007c0000000)
 Metaspace       used 3178K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 354K, capacity 386K, committed 512K, reserved 1048576K
bingoogolapple commented 6 years ago

取正数第二条来分析

2017-07-27T10:42:51.471-0800: 2.144: [GC (Allocation Failure)
  2017-07-27T10:42:51.472-0800: 2.144: [ParNew: 306654K->34039K(306688K), 0.2372089 secs]
  534279K->531300K(2063104K),
0.2373221 secs]
[Times: user=0.19 sys=0.55, real=0.23 secs]
2017-07-27T10:42:51.471-0800（开始垃圾收集时的当前时间戳）: 2.144（JVM 启动后经过的时间，单位为秒）: [GC (Allocation Failure（导致 GC 的原因，这里是分配内存失败导致的）)
  2017-07-27T10:42:51.472-0800: 2.144: [ParNew（ParNewGC 年轻代内存区域名称，并行，多线程，标记-复制 Mark-Copy，STW）: 306654K（GC 前年轻代的使用量）->34039K（GC 后年轻代的使用量）(306688K（年轻代总大小）), 0.2372089（年轻代 GC 所占用的时间，包括和 ConcurrentMarkSweep 收集器的通信开销，提升存活时间达标的对象到老年代，以及垃圾收集后期的一些最终清理） secs]
  534279K（GC 前整个堆的使用量）->531300K（GC 后整个堆的使用量）(2063104K（整个堆的总大小）),
0.2373221 secs]
[Times: user=0.19 sys=0.55, real=0.23 secs]
bingoogolapple commented 6 years ago
bingoogolapple commented 6 years ago

CMS GC 日志分析

2017-07-27T10:42:55.935-0800: 6.608: [GC (CMS Initial Mark)
  [1 CMS-initial-mark: 1569615K(1756416K)]
  1655496K(2063104K),
0.0039640 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]

2017-07-27T10:42:55.942-0800: 6.614: [CMS-concurrent-mark-start]
2017-07-27T10:42:55.961-0800: 6.634: [CMS-concurrent-mark: 0.019/0.019 secs]
[Times: user=0.02 sys=0.00, real=0.02 secs]

2017-07-27T10:42:55.961-0800: 6.634: [CMS-concurrent-preclean-start]
2017-07-27T10:42:55.968-0800: 6.640: [CMS-concurrent-preclean: 0.007/0.007 secs]
[Times: user=0.02 sys=0.00, real=0.00 secs]

2017-07-27T10:42:55.968-0800: 6.640: [CMS-concurrent-abortable-preclean-start]
2017-07-27T10:42:56.290-0800: 6.963: [CMS-concurrent-abortable-preclean: 0.016/0.323 secs]
[Times: user=0.03 sys=0.00, real=0.33 secs]

2017-07-27T10:42:56.291-0800: 6.963: [GC (CMS Final Remark)
  [YG occupancy: 199103 K (306688 K)]
  2017-07-27T10:42:56.291-0800: 6.963: [Rescan (parallel) , 0.0027865 secs]
  2017-07-27T10:42:56.293-0800: 6.966: [weak refs processing, 0.0000397 secs]
  2017-07-27T10:42:56.294-0800: 6.966: [class unloading, 0.0004163 secs]
  2017-07-27T10:42:56.294-0800: 6.967: [scrub symbol table, 0.0006806 secs]
  2017-07-27T10:42:56.295-0800: 6.967: [scrub string table, 0.0001862 secs]
  [1 CMS-remark: 1569615K(1756416K)]
  1768718K(2063104K),
0.0043575 secs]
[Times: user=0.01 sys=0.00, real=0.00 secs]

2017-07-27T10:42:56.295-0800: 6.968: [CMS-concurrent-sweep-start]
2017-07-27T10:42:56.298-0800: 6.971: [CMS-concurrent-sweep: 0.003/0.003 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]

2017-07-27T10:42:56.299-0800: 6.971: [CMS-concurrent-reset-start]
2017-07-27T10:42:56.304-0800: 6.976: [CMS-concurrent-reset: 0.005/0.005 secs]
[Times: user=0.01 sys=0.00, real=0.01 secs]
bingoogolapple commented 6 years ago

阶段 1：Initial Mark（初始标记）这是第一次 STW 事件。此阶段的目标是标记老年代中所有存活的对象，包括 GC ROOR 的直接引用，以及由年轻代中存活对象所引用的对象（非常重要，因为老年代是独立进行回收的）

2017-07-27T10:42:55.935-0800: 6.608: [GC (CMS Initial Mark)
  [1 CMS-initial-mark: 1569615K(1756416K)]
  1655496K(2063104K),
0.0039640 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
2017-07-27T10:42:55.935-0800: 6.608: [GC (CMS Initial Mark)
  [1 CMS-initial-mark: 1569615K（老年代的当前使用量）(1756416K（老年代代总大小）)]
  1655496K（当前整个堆的使用量）(2063104K（整个堆的总大小）),
0.0039640 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
bingoogolapple commented 6 years ago

阶段 2：Concurrent Mark（并发标记）在此阶段，垃圾收集器遍历老年代，标记所有的存活对象，从前一阶段 Initial Mark 找到的 root 根开始算起。是与应用程序同时运行，不用暂停的阶段。请注意，并非所有老年代中存活的对象都在此阶段被标记，因为在标记过程中对象的引用关系还在发生变化

2017-07-27T10:42:55.942-0800: 6.614: [CMS-concurrent-mark-start]
2017-07-27T10:42:55.961-0800: 6.634: [CMS-concurrent-mark: 0.019/0.019 secs]
[Times: user=0.02 sys=0.00, real=0.02 secs]
2017-07-27T10:42:55.942-0800: 6.614: [CMS-concurrent-mark-start]
2017-07-27T10:42:55.961-0800: 6.634: [CMS-concurrent-mark: 0.019（运行时间）/0.019（响应时间） secs]
[Times: user=0.02 sys=0.00, real=0.02 secs]（这部分对并发阶段来说没多少意义，因为程序也在运行）
bingoogolapple commented 6 years ago

阶段 3：Concurrent Preclean（并发预清理）此阶段同样是与应用线程并行执行的，不需要停止应用线程。因为前一阶段是与程序并发进行的，可能有一些引用已经改变。如果在并发标记过程中发生了引用关系变化，JVM 会通过 Card 将发生了改变的区域标记为「脏」区，这就是所谓的卡片标记（Card Marking）。本阶段也会执行一些必要的细节处理，并为 Final Remark 阶段做一些准备工作

2017-07-27T10:42:55.961-0800: 6.634: [CMS-concurrent-preclean-start]
2017-07-27T10:42:55.968-0800: 6.640: [CMS-concurrent-preclean: 0.007/0.007 secs]
[Times: user=0.02 sys=0.00, real=0.00 secs]
2017-07-27T10:42:55.961-0800: 6.634: [CMS-concurrent-preclean-start]
2017-07-27T10:42:55.968-0800: 6.640: [CMS-concurrent-preclean: 0.007（运行时间）/0.007（响应时间） secs]
[Times: user=0.02 sys=0.00, real=0.00 secs]（这部分对并发阶段来说没多少意义，因为程序也在运行）
bingoogolapple commented 6 years ago

阶段 4：Concurrent Abortable Preclean（并发可取消的预清理）此阶段也不停止应用线程. 本阶段尝试在 STW 的 Final Remark 之前尽可能地多做一些工作。本阶段的具体时间取决于多种因素，因为它循环做同样的事情，直到满足某个退出条件（如迭代次数，有用工作量，消耗的系统时间等等）

2017-07-27T10:42:55.968-0800: 6.640: [CMS-concurrent-abortable-preclean-start]
2017-07-27T10:42:56.290-0800: 6.963: [CMS-concurrent-abortable-preclean: 0.016/0.323 secs]
[Times: user=0.03 sys=0.00, real=0.33 secs]
2017-07-27T10:42:55.968-0800: 6.640: [CMS-concurrent-abortable-preclean-start]
2017-07-27T10:42:56.290-0800: 6.963: [CMS-concurrent-abortable-preclean: 0.016（运行时间）/0.323（响应时间） secs]
[Times: user=0.03 sys=0.00, real=0.33 secs]（这部分对并发阶段来说没多少意义，因为程序也在运行）
bingoogolapple commented 6 years ago

阶段 5：Final Remark（最终标记）这是此次 GC 事件中第二次（也是最后一次）STW 阶段。本阶段的目标是完成老年代中所有存活对象的标记。因为之前的 preclean 阶段是并发的，有可能无法跟上应用程序的变化速度。所以需要 STW 暂停来处理复杂情况

2017-07-27T10:42:56.291-0800: 6.963: [GC (CMS Final Remark)
  [YG occupancy: 199103 K (306688 K)]
  2017-07-27T10:42:56.291-0800: 6.963: [Rescan (parallel) , 0.0027865 secs]
  2017-07-27T10:42:56.293-0800: 6.966: [weak refs processing, 0.0000397 secs]
  2017-07-27T10:42:56.294-0800: 6.966: [class unloading, 0.0004163 secs]
  2017-07-27T10:42:56.294-0800: 6.967: [scrub symbol table, 0.0006806 secs]
  2017-07-27T10:42:56.295-0800: 6.967: [scrub string table, 0.0001862 secs]
  [1 CMS-remark: 1569615K(1756416K)]
  1768718K(2063104K),
0.0043575 secs]
[Times: user=0.01 sys=0.00, real=0.00 secs]
2017-07-27T10:42:56.291-0800: 6.963: [GC (CMS Final Remark（最终标记阶段，标记老年代中所有存活的对象，包括在此前的并发标记过程中创建/修改的引用）)
  [YG occupancy: 199103 K（当前年轻代的使用量） (306688 K（年轻代总大小）)]
  2017-07-27T10:42:56.291-0800: 6.963: [Rescan (parallel) , 0.0027865 secs]（在程序暂停时重新进行扫描，以完成存活对象的标记。此时 Rescan 是并行执行的）
  2017-07-27T10:42:56.293-0800: 6.966: [weak refs processing, 0.0000397 secs]（第一个子阶段，处理弱引用）
  2017-07-27T10:42:56.294-0800: 6.966: [class unloading, 0.0004163 secs]（第二个子阶段，卸载不使用的类）
  2017-07-27T10:42:56.294-0800: 6.967: [scrub symbol table, 0.0006806 secs]
  2017-07-27T10:42:56.295-0800: 6.967: [scrub string table, 0.0001862 secs]（最后一个子阶段，清理持有 class 级别 metadata 的符号表，以及内部化字符串对应的 string tables）
  [1 CMS-remark: 1569615K(1756416K)]（此阶段完成后老年代的使用量和总容量）
  1768718K(2063104K),（此阶段完成后整个堆内存的使用量和总容量）
0.0043575 secs]
[Times: user=0.01 sys=0.00, real=0.00 secs]
bingoogolapple commented 6 years ago

阶段 6：Concurrent Sweep（并发清除）此阶段与应用程序并发执行，不需要 STW。目的是删除未使用的对象，并收回他们占用的空间

2017-07-27T10:42:56.295-0800: 6.968: [CMS-concurrent-sweep-start]
2017-07-27T10:42:56.298-0800: 6.971: [CMS-concurrent-sweep: 0.003/0.003 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
2017-07-27T10:42:56.295-0800: 6.968: [CMS-concurrent-sweep-start]
2017-07-27T10:42:56.298-0800: 6.971: [CMS-concurrent-sweep: 0.003（运行时间）/0.003（响应时间） secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]（这部分对并发阶段来说没多少意义，因为程序也在运行）
bingoogolapple commented 6 years ago

阶段 7：Concurrent Reset（并发重置）此阶段与应用程序并发执行，重置 CMS 算法相关的内部数据，为下一次 GC 循环做准备

2017-07-27T10:42:56.299-0800: 6.971: [CMS-concurrent-reset-start]
2017-07-27T10:42:56.304-0800: 6.976: [CMS-concurrent-reset: 0.005/0.005 secs]
[Times: user=0.01 sys=0.00, real=0.01 secs]
2017-07-27T10:42:56.299-0800: 6.971: [CMS-concurrent-reset-start]
2017-07-27T10:42:56.304-0800: 6.976: [CMS-concurrent-reset: 0.005（运行时间）/0.005（响应时间） secs]
[Times: user=0.01 sys=0.00, real=0.01 secs]（这部分对并发阶段来说没多少意义，因为程序也在运行）
bingoogolapple commented 6 years ago

CMS的GC概述