各gc的行为（包括各种gc在哪个节点花费的时间最多）及适用场景，应先理解这些前提，分析gc日志才会事半功倍，核心参数解析参见java垃圾回收及gc全面解析（全面覆盖cms、g1、zgc、openj9）
开启gc日志选项：-XX:+PrintGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC
完整启动命令行参数（这里不一定是都是人工设置的，有些是JVM自动计算的）类似如下：
Java HotSpot(TM) 64-Bit Server VM (25.191-b12) for linux-amd64 JRE (1.8.0_191-b12), built on Oct 6 2018 05:43:09 by "java_re" with gcc 7.3.0 Memory: 4k page, physical 16170380k(7585644k free), swap 16383996k(16383932k free) CommandLine flags: -XX:-CMSClassUnloadingEnabled -XX:CMSInitiatingOccupancyFraction=70 -XX:+CMSParallelRemarkEnabled -XX:-ClassUnloading -XX:+DisableExplicitGC -XX:-ExplicitGCInvokesConcurrentAndUnloadsClasses -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=../logs/taaop-service/heapdump_20191218164613.dmp -XX:InitialHeapSize=6442450944 -XX:MaxHeapSize=12884901888 -XX:MaxNewSize=174485504 -XX:NewSize=174485504 -XX:OldPLABSize=16 -XX:OldSize=348971008 -XX:+PrintClassHistogram -XX:+PrintGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:SurvivorRatio=8 -XX:ThreadStackSize=512 -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC
本机的所有初始化参数可使用java -XX:+PrintFlagsInitial命令查看。
下面解释每个gc的日志详情，因为涉及到不同的gc选项不同，以及不同gc的不同支持选项（会按需说明），日志输出差异上比较大，LZ尽可能完整的说明并持续补充各种情况。
cms
2019-12-18T16:46:14.954+0800: 0.913【这里的时间代表进程移动以来的延时，下同】: Total time for which application threads were stopped: 0.0001816 seconds【应用线程停止的时间，STW的时间】, Stopping threads took: 0.0000322 seconds【停止线程花费的时间，一般来说不应该超过10%，否则就要细化分析，可以加上-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1命令行选项】【加上-XX:+PrintGCApplicationStoppedTime会该日志，如果加上-XX:+PrintGCApplicationConcurrentTime则会在其之前显示并行运行时间，类似于“Application time: 0.1325032 seconds”】
{Heap before GC invocations=0【gc次数】 (full 0)【full gc次数】:【GC前堆的使用情况】
par new generation total 153344K, used 136320K [0x00000004c0000000, 0x00000004ca660000, 0x00000004ca660000)
eden space 136320K, 100% used [0x00000004c0000000, 0x00000004c8520000, 0x00000004c8520000)
from space 17024K, 0% used [0x00000004c8520000, 0x00000004c8520000, 0x00000004c95c0000)
to space 17024K, 0% used [0x00000004c95c0000, 0x00000004c95c0000, 0x00000004ca660000)
concurrent mark-sweep generation total 6121088K, used 0K [0x00000004ca660000, 0x0000000640000000, 0x00000007c0000000)
Metaspace used 7256K, capacity 7490K, committed 7552K, reserved 1056768K
class space used 803K, capacity 879K, committed 896K, reserved 1048576K
2019-12-18T16:46:15.107+0800: 1.067: [GC (Allocation Failure) 2019-12-18T16:46:15.107+0800: 1.067: [ParNew
Desired survivor size 8716288 bytes, new threshold 15 (max 15)
- age 1: 3092032 bytes, 3092032 total
: 136320K->3050K(153344K), 0.0382914 secs] 136320K->3050K(6274432K), 0.0383715 secs] [Times: user=0.06 sys=0.00, real=0.04 secs]
Heap after GC invocations=1 (full 0):【GC后堆的使用情况】
par new generation total 153344K, used 3050K [0x00000004c0000000, 0x00000004ca660000, 0x00000004ca660000)
eden space 136320K, 0% used [0x00000004c0000000, 0x00000004c0000000, 0x00000004c8520000)
from space 17024K, 17% used [0x00000004c95c0000, 0x00000004c98ba818, 0x00000004ca660000)
to space 17024K, 0% used [0x00000004c8520000, 0x00000004c8520000, 0x00000004c95c0000)
concurrent mark-sweep generation total 6121088K, used 0K [0x00000004ca660000, 0x0000000640000000, 0x00000007c0000000)
Metaspace used 7256K, capacity 7490K, committed 7552K, reserved 1056768K
class space used 803K, capacity 879K, committed 896K, reserved 1048576K
}
2019-12-18T16:46:16.469+0800: 2.428: Total time for which application threads were stopped: 0.0003590 seconds, Stopping threads took: 0.0000623 seconds
{Heap before GC invocations=4 (full 0):
par new generation total 153344K, used 144364K [0x00000004c0000000, 0x00000004ca660000, 0x00000004ca660000)
eden space 136320K, 100% used [0x00000004c0000000, 0x00000004c8520000, 0x00000004c8520000)
from space 17024K, 47% used [0x00000004c8520000, 0x00000004c8cfb360, 0x00000004c95c0000)
to space 17024K, 0% used [0x00000004c95c0000, 0x00000004c95c0000, 0x00000004ca660000)
concurrent mark-sweep generation total 6121088K, used 0K [0x00000004ca660000, 0x0000000640000000, 0x00000007c0000000)
Metaspace used 19151K, capacity 19444K, committed 19712K, reserved 1067008K
class space used 2330K, capacity 2436K, committed 2560K, reserved 1048576K
2019-12-18T16:46:16.656+0800: 2.616: [GC (Allocation Failure)【说明eden区域没有足够空间分配对象了，需要ygc。也是ygc的主要原因，也是minor gc的主要原因。如果是CMS，则+XX:+ScavengeBeforeRemark也会导致该gc事件发生】 2019-12-18T16:46:16.656+0800: 2.616: [ParNew
Desired survivor size 8716288 bytes, new threshold 15 (max 15)
- age 1: 691728 bytes, 691728 total
- age 2: 847072 bytes, 1538800 total
- age 3: 1074560 bytes, 2613360 total
- age 4: 476048 bytes, 3089408 total
- age 5: 2668976 bytes, 5758384 total
: 144364K->7279K(153344K), 0.0780433 secs] 144364K->7279K(6274432K), 0.0781149 secs] [Times: user=0.08 sys=0.00, real=0.08 secs]
Heap after GC invocations=5 (full 0):
par new generation total 153344K, used 7279K [0x00000004c0000000, 0x00000004ca660000, 0x00000004ca660000)
eden space 136320K, 0% used [0x00000004c0000000, 0x00000004c0000000, 0x00000004c8520000)
from space 17024K, 42% used [0x00000004c95c0000, 0x00000004c9cdbff8, 0x00000004ca660000)
to space 17024K, 0% used [0x00000004c8520000, 0x00000004c8520000, 0x00000004c95c0000)
concurrent mark-sweep generation total 6121088K, used 0K [0x00000004ca660000, 0x0000000640000000, 0x00000007c0000000)
Metaspace used 19151K, capacity 19444K, committed 19712K, reserved 1067008K
class space used 2330K, capacity 2436K, committed 2560K, reserved 1048576K
}
2019-12-18T22:06:39.141+0800: 19225.101: [GC【标记gc，用于区分full和minor，没有full即为minor，此处即是】 (Allocation Failure)【发生了新生代内存分配失败，此时一定会伴随gc】 2019-12-18T22:06:39.141+0800: 19225.101: [ParNew Desired survivor size 8716288 bytes, new threshold 15 (max 15)【开启了-XX:+PrintTenuringDistribution后，此处会打印survivor区每个年龄的对象分布，以及预期使用的survivor区大小，eden区为5到6倍。需要注意的是，如果是parallel gc的话，不会打印每个年龄表，因此它不和其他gc一样使用年龄表，这是需要注意的，https://blogs.oracle.com/poonam/throughput-collector-and-printtenuringdistribution-option】 - age 1: 220800 bytes, 220800 total - age 2: 33272 bytes, 254072 total - age 3: 42496 bytes, 296568 total - age 4: 114144 bytes, 410712 total - age 5: 115968 bytes, 526680 total - age 6: 21112 bytes, 547792 total - age 7: 24976 bytes, 572768 total - age 8: 23608 bytes, 596376 total - age 9: 25072 bytes, 621448 total - age 10: 24688 bytes, 646136 total - age 11: 24760 bytes, 670896 total - age 12: 26200 bytes, 697096 total - age 13: 28360 bytes, 725456 total - age 14: 30448 bytes, 755904 total - age 15: 30512 bytes, 786416 total : 138653K【gc前新生代占用大小】->1698K【gc后新生代占用大小】(153344K)【新生代容量】, 0.0503081 secs] 994798K【gc前堆占用大小】->858486K【gc后堆占用大小】(6274432K)【堆容量大小】, 0.0504493 secs] [Times: user=0.07 sys=0.00, real=0.05 secs]
2019-12-19T08:23:54.612+0800: 56260.572: [GC (CMS Initial Mark) [1 CMS-initial-mark【标识 CMS收集器的分代收集开始，在所有状态可能变化的线性停止后结束】: 4284915K【触发CMS的已占用大小】(6121088K)【分代堆容量大小】] 4290798K(6274432K), 0.0285558 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 2019-12-19T08:23:54.641+0800: 56260.600: Total time for which application threads were stopped: 0.0291464 seconds, Stopping threads took: 0.0000984 seconds 2019-12-19T08:23:54.641+0800: 56260.600: [CMS-concurrent-mark-start]【并发标记开始，上一阶段停止的线程恢复执行】 2019-12-19T08:23:55.089+0800: 56261.049: [CMS-concurrent-mark: 0.448【并发标记花费的cpu时间】/0.448 secs【并发标记花费的延时】] [Times: user=0.48 sys=0.01, real=0.44 secs] 2019-12-19T08:23:55.090+0800: 56261.049: [CMS-concurrent-preclean-start]【预清理开始，这个阶段也是并发的】 2019-12-19T08:23:55.099+0800: 56261.059: [CMS-concurrent-preclean: 0.010/0.010 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 【并发预清理花费的时间】 2019-12-19T08:23:55.099+0800: 56261.059: [CMS-concurrent-abortable-preclean-start]【如果在preclean后，eden区占用仍大于CMSScheduleRemarkEdenSizeThreshold，则会开始本动作。然后继续执行上一预清理动作，直到eden区占用CMSScheduleRemarkEdenPenetration，否则就进入Remark阶段，如下】 CMS: abort preclean due to time 2019-12-19T08:24:00.158+0800: 56266.117: [CMS-concurrent-abortable-preclean: 1.155/5.058 secs] [Times: user=1.44 sys=0.12, real=5.06 secs] 2019-12-19T08:24:00.158+0800: 56266.118: [GC (CMS Final Remark) [YG occupancy: 61860 K (153344 K)]2019-12-19T08:24:00.158+0800: 56266.118: [Rescan (parallel) , 0.0367584 secs]2019-12-19T08:24:00.195+0800: 56266.155: [weak refs processing, 0.0018081 secs][1 CMS-remark: 4284915K(6121088K)] 4346776K(6274432K), 0.0390171 secs] [Times: user=0.08 sys=0.00, real=0.04 secs]
CML最后标记，STW步骤，这个步骤重新扫描CMS堆栈中剩下尚未处理的、更新过的对象，然后从根开始重新标记并处理引用的对象。本例中，重新扫描花了0.0367584秒，弱引用处理花了0.0018081秒。 2019-12-19T08:24:00.197+0800: 56266.157: Total time for which application threads were stopped: 0.0396563 seconds, Stopping threads took: 0.0000906 seconds 2019-12-19T08:24:00.198+0800: 56266.158: [CMS-concurrent-sweep-start] 【开始清理已经消亡或未标记过的对象，清理过程是并发的】 2019-12-19T08:24:00.205+0800: 56266.164: Total time for which application threads were stopped: 0.0023561 seconds, Stopping threads took: 0.0000992 seconds {Heap before GC invocations=18371 (full 5): par new generation total 153344K, used 139552K [0x00000004c0000000, 0x00000004ca660000, 0x00000004ca660000) eden space 136320K, 100% used [0x00000004c0000000, 0x00000004c8520000, 0x00000004c8520000) from space 17024K, 18% used [0x00000004c95c0000, 0x00000004c98e8048, 0x00000004ca660000) to space 17024K, 0% used [0x00000004c8520000, 0x00000004c8520000, 0x00000004c95c0000) concurrent mark-sweep generation total 6121088K, used 1143835K [0x00000004ca660000, 0x0000000640000000, 0x00000007c0000000) Metaspace used 99739K, capacity 105514K, committed 105728K, reserved 1142784K class space used 11277K, capacity 12218K, committed 12288K, reserved 1048576K 2019-12-19T08:24:01.641+0800: 56267.601: [GC (Allocation Failure) 2019-12-19T08:24:01.641+0800: 56267.601: [ParNew Desired survivor size 8716288 bytes, new threshold 15 (max 15) - age 1: 3690000 bytes, 3690000 total - age 2: 74312 bytes, 3764312 total - age 3: 284600 bytes, 4048912 total - age 4: 1350344 bytes, 5399256 total - age 5: 16784 bytes, 5416040 total - age 6: 17656 bytes, 5433696 total - age 7: 16368 bytes, 5450064 total - age 8: 25440 bytes, 5475504 total - age 9: 26560 bytes, 5502064 total - age 10: 14248 bytes, 5516312 total - age 11: 12360 bytes, 5528672 total - age 12: 13328 bytes, 5542000 total - age 13: 14752 bytes, 5556752 total - age 14: 13736 bytes, 5570488 total - age 15: 13120 bytes, 5583608 total : 139552K->7104K(153344K), 0.0395339 secs] 1283387K->1150953K(6274432K), 0.0396813 secs] [Times: user=0.08 sys=0.00, real=0.04 secs] Heap after GC invocations=18372 (full 5): par new generation total 153344K, used 7104K [0x00000004c0000000, 0x00000004ca660000, 0x00000004ca660000) eden space 136320K, 0% used [0x00000004c0000000, 0x00000004c0000000, 0x00000004c8520000) from space 17024K, 41% used [0x00000004c8520000, 0x00000004c8c10140, 0x00000004c95c0000) to space 17024K, 0% used [0x00000004c95c0000, 0x00000004c95c0000, 0x00000004ca660000) concurrent mark-sweep generation total 6121088K, used 1143848K [0x00000004ca660000, 0x0000000640000000, 0x00000007c0000000) Metaspace used 99739K, capacity 105514K, committed 105728K, reserved 1142784K class space used 11277K, capacity 12218K, committed 12288K, reserved 1048576K } 2019-12-19T08:24:01.681+0800: 56267.641: Total time for which application threads were stopped: 0.0403409 seconds, Stopping threads took: 0.0000727 seconds 2019-12-19T08:24:02.016+0800: 56267.975: Total time for which application threads were stopped: 0.0005714 seconds, Stopping threads took: 0.0000796 seconds 2019-12-19T08:24:03.312+0800: 56269.271: [CMS-concurrent-sweep: 3.078/3.114 secs] [Times: user=3.74 sys=0.52, real=3.12 secs] 【清理花费的时间】 2019-12-19T08:24:03.312+0800: 56269.272: [CMS-concurrent-reset-start]【标记开始重置】 2019-12-19T08:24:03.335+0800: 56269.295: [CMS-concurrent-reset: 0.023/0.023 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 【重置时间，CMS数据结构被重新初始化以备下一次GC。到这里也是一个完整的正常CMS运行周期】
有时候日志中会出现大量连续的Total time for which application threads were stopped，它不一定都是gc的原因（没有gc也可以生成这些日志，默认情况下jvm每秒触发一次safepoint处理所有队列中非紧急的操作，可通过选项GuaranteedSafepointInterval修改间隔，参考https://dzone.com/articles/logging-stop-world-pauses-jvm），通过加上jvm选项-XX:-UseBiasedLocking可减少这些日志的输出。加上选项-XX:+PrintSafepointStatistics可以进一步分析原因（进一步分析就得到jvm的源码层面了）。
参考：https://blogs.oracle.com/poonam/understanding-cms-gc-logs，https://blogs.oracle.com/jonthecollector/the-unspoken-application-times，https://blog.gceasy.io/2016/12/22/total-time-for-which-application-threads-were-stopped/，https://stackoverflow.com/questions/6870180/why-are-there-multiple-total-time-for-which-application-threads-were-stopped-l，https://dzone.com/articles/logging-stop-world-pauses-jvm
parallel gc
2019-12-21T16:24:26.097+0800: 23.831: Total time for which application threads were stopped: 0.0001024 seconds, Stopping threads took: 0.0000360 seconds
{Heap before GC invocations=1 (full 0):
PSYoungGen total 74752K, used 64512K [0x000000076cf00000, 0x0000000772200000, 0x00000007c0000000)【PSYoungGen全称parallel mark-copy stop-the-world garbage collector，表示用于minor收集的gc，PS即Parallel Scavenge的缩写】
eden space 64512K, 100% used [0x000000076cf00000,0x0000000770e00000,0x0000000770e00000)
from space 10240K, 0% used [0x0000000771800000,0x0000000771800000,0x0000000772200000)
to space 10240K, 0% used [0x0000000770e00000,0x0000000770e00000,0x0000000771800000)
ParOldGen total 171008K, used 0K [0x00000006c6c00000, 0x00000006d1300000, 0x000000076cf00000)【ParOldGen全称parallel mark-sweep-compact stop-the-world garbage collector】
object space 171008K, 0% used [0x00000006c6c00000,0x00000006c6c00000,0x00000006d1300000)
Metaspace used 6223K, capacity 6518K, committed 6656K, reserved 1056768K
class space used 660K, capacity 751K, committed 768K, reserved 1048576K
2019-12-21T16:24:28.266+0800: 26.000: [GC (Allocation Failure)
Desired survivor size 10485760 bytes, new threshold 7 (max 15)
[PSYoungGen: 64512K->3331K(74752K)] 64512K->3339K(245760K), 2.6035723 secs] [Times: user=5.24 sys=0.05, real=2.61 secs]
Heap after GC invocations=1 (full 0):
PSYoungGen total 74752K, used 3331K [0x000000076cf00000, 0x0000000776100000, 0x00000007c0000000)
eden space 64512K, 0% used [0x000000076cf00000,0x000000076cf00000,0x0000000770e00000)
from space 10240K, 32% used [0x0000000770e00000,0x0000000771140c18,0x0000000771800000)
to space 10240K, 0% used [0x0000000775700000,0x0000000775700000,0x0000000776100000)
ParOldGen total 171008K, used 8K [0x00000006c6c00000, 0x00000006d1300000, 0x000000076cf00000)
object space 171008K, 0% used [0x00000006c6c00000,0x00000006c6c02000,0x00000006d1300000)
Metaspace used 6223K, capacity 6518K, committed 6656K, reserved 1056768K
class space used 660K, capacity 751K, committed 768K, reserved 1048576K
}
eden space 515584K, 0% used [0x0000000580100000,0x0000000580100000,0x000000059f880000)
from space 85504K, 7% used [0x00000005a4c00000,0x00000005a5291258,0x00000005a9f80000)
to space 85504K, 0% used [0x000000059f880000,0x000000059f880000,0x00000005a4c00000)
ParOldGen total 1373696K, used 104K [0x0000000080200000, 0x00000000d3f80000, 0x0000000580100000)
object space 1373696K, 0% used [0x0000000080200000,0x000000008021a028,0x00000000d3f80000)
Metaspace used 20852K, capacity 21056K, committed 21296K, reserved 1069056K
class space used 2548K, capacity 2631K, committed 2688K, reserved 1048576K
}
{Heap before GC invocations=3 (full 1):
PSYoungGen total 601088K, used 6724K [0x0000000580100000, 0x00000005a9f80000, 0x0000000800000000)
eden space 515584K, 0% used [0x0000000580100000,0x0000000580100000,0x000000059f880000)
from space 85504K, 7% used [0x00000005a4c00000,0x00000005a5291258,0x00000005a9f80000)
to space 85504K, 0% used [0x000000059f880000,0x000000059f880000,0x00000005a4c00000)
ParOldGen total 1373696K, used 104K [0x0000000080200000, 0x00000000d3f80000, 0x0000000580100000)
object space 1373696K, 0% used [0x0000000080200000,0x000000008021a028,0x00000000d3f80000)
Metaspace used 20852K, capacity 21056K, committed 21296K, reserved 1069056K
class space used 2548K, capacity 2631K, committed 2688K, reserved 1048576K
2019-12-22T09:05:37.379-0500: 3.061: [Full GC (Metadata GC Threshold) [PSYoungGen: 6724K->0K(601088K)] [ParOldGen: 104K->6193K(849920K)] 6828K->6193K(1451008K), [Metaspace: 20852K->20852K(106
9056K)], 0.0388523 secs] [Times: user=0.63 sys=0.03, real=0.04 secs]
Heap after GC invocations=3 (full 1):
PSYoungGen total 601088K, used 0K [0x0000000580100000, 0x00000005a9f80000, 0x0000000800000000)
eden space 515584K, 0% used [0x0000000580100000,0x0000000580100000,0x000000059f880000)
from space 85504K, 0% used [0x00000005a4c00000,0x00000005a4c00000,0x00000005a9f80000)
to space 85504K, 0% used [0x000000059f880000,0x000000059f880000,0x00000005a4c00000)
ParOldGen total 849920K, used 6193K [0x0000000080200000, 0x00000000b4000000, 0x0000000580100000)
object space 849920K, 0% used [0x0000000080200000,0x000000008080c650,0x00000000b4000000)
Metaspace used 20852K, capacity 21056K, committed 21296K, reserved 1069056K
class space used 2548K, capacity 2631K, committed 2688K, reserved 1048576K
}
2019-12-22T09:05:37.847-0500: 3.529: Total time for which application threads were stopped: 0.0004606 seconds, Stopping threads took: 0.0000387 seconds
{Heap before GC invocations=4 (full 1):
PSYoungGen total 601088K, used 515584K [0x0000000580100000, 0x00000005a9f80000, 0x0000000800000000)
eden space 515584K, 100% used [0x0000000580100000,0x000000059f880000,0x000000059f880000)
from space 85504K, 0% used [0x00000005a4c00000,0x00000005a4c00000,0x00000005a9f80000)
to space 85504K, 0% used [0x000000059f880000,0x000000059f880000,0x00000005a4c00000)
ParOldGen total 849920K, used 6193K [0x0000000080200000, 0x00000000b4000000, 0x0000000580100000)
object space 849920K, 0% used [0x0000000080200000,0x000000008080c650,0x00000000b4000000)
Metaspace used 25929K, capacity 26264K, committed 26624K, reserved 1073152K
class space used 3194K, capacity 3300K, committed 3328K, reserved 1048576K
2019-12-22T09:05:38.244-0500: 3.925: [GC (Allocation Failure) 【parallel gc最多的就是这个事件，简单粗暴】
Desired survivor size 87556096 bytes, new threshold 7 (max 15)【Parallel gc不像其他gc一样，输出明细，只有汇总，见上文】
[PSYoungGen: 515584K->2900K(601088K)] 521777K->9101K(1451008K), 0.0055775 secs] [Times: user=0.06 sys=0.01, real=0.00 secs]
Heap after GC invocations=4 (full 1):
PSYoungGen total 601088K, used 2900K [0x0000000580100000, 0x00000005b4f80000, 0x0000000800000000)
eden space 515584K, 0% used [0x0000000580100000,0x0000000580100000,0x000000059f880000)
from space 85504K, 3% used [0x000000059f880000,0x000000059fb55040,0x00000005a4c00000)
to space 85504K, 0% used [0x00000005afc00000,0x00000005afc00000,0x00000005b4f80000)
ParOldGen total 849920K, used 6201K [0x0000000080200000, 0x00000000b4000000, 0x0000000580100000)
object space 849920K, 0% used [0x0000000080200000,0x000000008080e650,0x00000000b4000000)
Metaspace used 25929K, capacity 26264K, committed 26624K, reserved 1073152K
class space used 3194K, capacity 3300K, committed 3328K, reserved 1048576K
}
2019-12-22T14:43:06.958-0500: 281.079: Total time for which application threads were stopped: 1.0715114 seconds, Stopping threads took: 0.0000473 seconds
{Heap before GC invocations=203 (full 53):
PSYoungGen total 306688K, used 279552K [0x00000000eab00000, 0x0000000100000000, 0x0000000100000000)
eden space 279552K, 100% used [0x00000000eab00000,0x00000000fbc00000,0x00000000fbc00000)
from space 27136K, 0% used [0x00000000fe580000,0x00000000fe580000,0x0000000100000000)
to space 34816K, 0% used [0x00000000fbc00000,0x00000000fbc00000,0x00000000fde00000)
ParOldGen total 699392K, used 699239K [0x00000000c0000000, 0x00000000eab00000, 0x00000000eab00000)
object space 699392K, 99% used [0x00000000c0000000,0x00000000eaad9fe8,0x00000000eab00000)
Metaspace used 130334K, capacity 133715K, committed 133888K, reserved 1169408K
class space used 14209K, capacity 14837K, committed 14848K, reserved 1048576K
2019-12-22T14:43:06.959-0500: 281.080: [Full GC (Ergonomics【本次full gc的原因，ergonomics代表JVM内部诊断信息认为这个时候gc是合理的，主要是平衡吞吐量和暂停时间】) [PSYoungGen: 279552K->279552K(306688K)【在full gc中，PSYoungGen应该降低为0，否则说明内存太小不足以满足当前负载】] [ParOldGen: 699239K->699239K(699392K)] 978791K->978791K(1006080K), [Metaspace: 130334K->130334K(1169408K)], 1.0543736 secs] [Times: user=7.76 sys=0.00, real=1.06 secs]
Heap after GC invocations=203 (full 53):
PSYoungGen total 306688K, used 279552K [0x00000000eab00000, 0x0000000100000000, 0x0000000100000000)
eden space 279552K, 100% used [0x00000000eab00000,0x00000000fbc00000,0x00000000fbc00000)
from space 27136K, 0% used [0x00000000fe580000,0x00000000fe580000,0x0000000100000000)
to space 34816K, 0% used [0x00000000fbc00000,0x00000000fbc00000,0x00000000fde00000)
ParOldGen total 699392K, used 699239K [0x00000000c0000000, 0x00000000eab00000, 0x00000000eab00000)
object space 699392K, 99% used [0x00000000c0000000,0x00000000eaad9cb0,0x00000000eab00000)
Metaspace used 130334K, capacity 133715K, committed 133888K, reserved 1169408K
class space used 14209K, capacity 14837K, committed 14848K, reserved 1048576K
}
参考：http://www.herongyang.com/Java-8-GC/Serial-Collector-GC-Log-Message-Format.html，http://www.herongyang.com/Java-8-GC/Parallel-Collector-GC-Log-Message-Format.html，parallel gc和serial gc的日志格式差不多。https://plumbr.io/handbook/garbage-collection-algorithms-implementations/parallel-gc。
g1
2019-12-21T16:39:10.793+0800: 212.243: Total time for which application threads were stopped: 0.0007076 seconds, Stopping threads took: 0.0001682 seconds
{Heap before GC invocations=56 (full 0):
garbage-first heap total 256000K, used 220990K [0x00000006c6c00000, 0x00000006c6d007d0, 0x00000007c0000000)
region size 1024K, 140 young (143360K), 9 survivors (9216K)
Metaspace used 69879K, capacity 71544K, committed 71808K, reserved 1112064K
class space used 8438K, capacity 8748K, committed 8832K, reserved 1048576K
2019-12-21T16:39:10.875+0800: 212.325: [GC pause (G1 Evacuation Pause) (young)【标记疏散阶段开始，所有被疏散的区域都是新生代，包括Eden和Survivor这一步也可能是新生代和老年代混合，此时显示为mixed】
Desired survivor size 9437184 bytes, new threshold 15 (max 15)
- age 1: 1454248 bytes, 1454248 total
- age 2: 497112 bytes, 1951360 total
- age 3: 388880 bytes, 2340240 total
- age 4: 589192 bytes, 2929432 total
- age 5: 426184 bytes, 3355616 total
- age 6: 362328 bytes, 3717944 total
- age 7: 453504 bytes, 4171448 total
- age 8: 434256 bytes, 4605704 total
- age 9: 640800 bytes, 5246504 total
- age 10: 769760 bytes, 6016264 total
- age 11: 456480 bytes, 6472744 total
- age 12: 1182512 bytes, 7655256 total
, 0.0153785 secs]
[Parallel Time: 13.3 ms, GC Workers: 8]【所有线程加起来花费的总时间】
[GC Worker Start (ms): Min: 212324.9, Avg: 212325.0, Max: 212325.1, Diff: 0.2]【gc开始时间】
[Ext Root Scanning (ms): Min: 1.7, Avg: 2.3, Max: 5.0, Diff: 3.3, Sum: 18.8]【每个工作线程扫描gc root（全局静态、寄存器、线程栈、VM数据结构）花费的时间】
[Update RS (ms): Min: 0.6, Avg: 2.9, Max: 3.8, Diff: 3.2, Sum: 23.0]【更新Remembered Sets花费的时间】
[Processed Buffers: Min: 3, Avg: 8.6, Max: 20, Diff: 17, Sum: 69]【每个线程处理的Update Buffers数量】
[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.6]【每个工作线程扫描Remembered Sets的时间】
[Code Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 1.5]
[Object Copy (ms): Min: 7.0, Avg: 7.3, Max: 7.6, Diff: 0.6, Sum: 58.5]【拷贝存活对象到其他region的时间，通常是大头】
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]【工作线程用于结束本次gc任务前的收尾工作时间，主要是检查其他线程的工作队列是否还有存活对象要处理】
[Termination Attempts: Min: 2, Avg: 9.4, Max: 14, Diff: 12, Sum: 75]【工作线程试图结束的次数】
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.0]【花费在其他工作上的时间】
[GC Worker Total (ms): Min: 12.8, Avg: 12.9, Max: 13.1, Diff: 0.3, Sum: 103.5]【gc花费时间】
[GC Worker End (ms): Min: 212337.9, Avg: 212338.0, Max: 212338.1, Diff: 0.2]【gc结束时间】
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.5 ms]【清除Card Table花费的时间，这一步只能串行】
[Other: 1.6 ms]【花费在其他任务上的时间】
[Choose CSet: 0.0 ms]【为Collection Set选择分块】
[Ref Proc: 0.5 ms]【处理引用对象的时间】
[Ref Enq: 0.0 ms]【将引用对象放入队列的时间】
[Redirty Cards: 0.3 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.4 ms]【释放cset的时间】
[Eden: 131.0M【gc前已用大小】(131.0M)【gc前容量】->0.0B【gc后已用大小】(131.0M)【gc后eden容量，此时并非reserved大小，只不过下一次gc前会到或超过这个大小】 Survivors: 9216.0K【gc前大小】->9216.0K【gc后大小】 Heap: 215.8M【gc前堆占用】(250.0M)【gc前堆容量】->84.3M【gc后堆占用】(250.0M)【gc后堆容量】]
Heap after GC invocations=57 (full 0):
garbage-first heap total 256000K, used 86334K [0x00000006c6c00000, 0x00000006c6d007d0, 0x00000007c0000000)
region size 1024K, 9 young (9216K), 9 survivors (9216K)
Metaspace used 69879K, capacity 71544K, committed 71808K, reserved 1112064K
class space used 8438K, capacity 8748K, committed 8832K, reserved 1048576K
}
[Times: user=0.11 sys=0.00, real=0.01 secs]
2019-12-21T16:34:37.318+0800: 9.279: [GC concurrent-root-region-scan-start]【标识 开始并发扫描根区域集合(它们只是从survivor直接可达)】
2019-12-21T16:34:37.318+0800: 9.279: Total time for which application threads were stopped: 0.0183506 seconds, Stopping threads took: 0.0001925 seconds
2019-12-21T16:34:37.320+0800: 9.281: Total time for which application threads were stopped: 0.0002391 seconds, Stopping threads took: 0.0000778 seconds
2019-12-21T16:34:37.326+0800: 9.288: [GC concurrent-root-region-scan-end, 0.0085344 secs]【标识该阶段结束，及时间花费】
2019-12-21T16:34:37.326+0800: 9.288: [GC concurrent-mark-start]【并发标记开始】
2019-12-21T16:34:37.329+0800: 9.290: [GC concurrent-mark-end, 0.0025205 secs]【标识并发标记结束，及花费时间】
2019-12-21T16:34:37.329+0800: 9.291: [GC remark 2019-12-21T16:34:37.329+0800: 9.291: [Finalize Marking, 0.0069730 secs] 2019-12-21T16:34:37.336+0800: 9.298: [GC ref-proc, 0.0003443 secs] 2019-12-21T16:34:37.337+0800: 9.298: [Unloading, 0.0104921 secs], 0.0207689 secs]
[Times: user=0.11 sys=0.02, real=0.02 secs]
2019-12-21T16:34:37.350+0800: 9.311: Total time for which application threads were stopped: 0.0212366 seconds, Stopping threads took: 0.0001984 seconds
2019-12-21T16:34:37.351+0800: 9.312: [GC cleanup 10M->10M(3986M), 0.0119817 secs]【清理阶段是一个STW操作，它编译所有分块的标记信息，计算每个分块的存活数据信息，重置用于标记的数据结构，根据gc的效率排序分块。在本例中，堆大小为3986M，计算存活对象后，可使占用堆从10M降低到10M】
[Times: user=0.07 sys=0.01, real=0.01 secs]
2019-12-21T16:34:47.567+0800: 19.528: [GC pause (Metadata GC Threshold) (young) (initial-mark)【从JDK8开始，永久代(PermGen)的概念被废弃掉了，取而代之的是一个称为Metaspace的存储空间。Metaspace使用的是本地内存，而不是堆内存，也就是说在默认情况下Metaspace的大小只与本地内存大小有关。该值越大触发Metaspace GC的时机就越晚。随着GC的到来，虚拟机会根据实际情况调控Metaspace的大小，可能增加上限也可能降低。在默认情况下，这个值大小根据不同的平台在12M到20M浮动，如果不够也会发生full gc。详见-XX:Metaspacesize】
Desired survivor size 156762112 bytes, new threshold 15 (max 15)
- age 1: 684960 bytes, 684960 total
- age 2: 1602368 bytes, 2287328 total
- age 3: 641568 bytes, 2928896 total
- age 4: 3958136 bytes, 6887032 total
, 0.0906360 secs]
[Parallel Time: 73.6 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 19530.2, Avg: 19531.0, Max: 19533.3, Diff: 3.0]
[Ext Root Scanning (ms): Min: 5.0, Avg: 5.9, Max: 7.1, Diff: 2.0, Sum: 47.1]
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
......
......
# 这部分信息通过-XX:+UnlockDiagnosticVMOptions +G1PrintRegionLivenessInfo选项输出。包含了并发标记的Cleanup阶段每个子区域存活的数据
2019-12-22T09:12:49.654-0500: 2.719: [GC cleanup ### PHASE Post-Marking @ 2.720 ### HEAP reserved: 0x0000000082000000-0x0000000800000000 region-size: 4194304 ### ### type address-range used prev-live next-live gc-eff remset code-roots ### (bytes) (bytes) (bytes) (bytes/ms) (bytes) (bytes) ### FREE 0x0000000082000000-0x0000000082400000 0 0 0 0.0 6408 16 ### FREE 0x0000000082400000-0x0000000082800000 0 0 0 0.0 6408 16 ### FREE 0x0000000082800000-0x0000000082c00000 0 0 0 0.0 6408 16 ### FREE 0x0000000082c00000-0x0000000083000000 0 0 0 0.0 6408 16 ### FREE 0x0000000083000000-0x0000000083400000 0 0 0 0.0 6408 16 ### FREE 0x0000000083400000-0x0000000083800000 0 0 0 0.0 6408 16 ### FREE 0x0000000083800000-0x0000000083c00000 0 0 0 0.0 6408 16 ### FREE 0x0000000083c00000-0x0000000084000000 0 0 0 0.0 6408 16 ### FREE 0x0000000084000000-0x0000000084400000 0 0 0 0.0 6408 16 ### FREE 0x0000000084400000-0x0000000084800000 0 0 0 0.0 6408 16 ### FREE 0x00000000d0400000-0x00000000d0800000 0 0 0 0.0 6408 16 ### SURV 0x00000000d0800000-0x00000000d0c00000 1047200 1047200 1047200 0.0 6408 16 ### SURV 0x00000000d0c00000-0x00000000d1000000 4194304 4194304 4194304 0.0 7544 1152 ### SURV 0x00000000d1000000-0x00000000d1400000 4194304 4194304 4194304 0.0 27824 21432 ### FREE 0x00000000d1400000-0x00000000d1800000 0 0 0 0.0 6408 16 ### FREE 0x0000000084800000-0x0000000084c00000 0 0 0 0.0 6408 16 ### FREE 0x0000000084c00000-0x0000000085000000 0 0 0 0.0 6408 16 ### FREE 0x0000000085000000-0x0000000085400000 0 0 0 0.0 6408 16 ### FREE 0x0000000085400000-0x0000000085800000 0 0 0 0.0 6408 16 ### FREE 0x0000000085800000-0x0000000085c00000 0 0 0 0.0 6408 16 ### FREE 0x0000000085c00000-0x0000000086000000 0 0 0 0.0 6408 16 ### FREE 0x00000000ff000000-0x00000000ff400000 0 0 0 0.0 6408 16 ### EDEN 0x00000000ff400000-0x00000000ff800000 4194304 4194304 4194304 0.0 6408 16 ### EDEN 0x00000000ff800000-0x00000000ffc00000 4194304 4194304 4194304 0.0 6408 16 ### ### SUMMARY capacity: 2012.00 MB used: 17.00 MB / 0.84 % prev-live: 17.00 MB / 0.84 % next-live: 17.00 MB / 0.84 % remset: 5.47 MB code-roots: 0.03 MB ### PHASE Post-Sorting @ 2.724 ### HEAP reserved: 0x0000000082000000-0x0000000800000000 region-size: 4194304 ### ### type address-range used prev-live next-live gc-eff remset code-roots ### (bytes) (bytes) (bytes) (bytes/ms) (bytes) (bytes) ### ### SUMMARY capacity: 0.00 MB used: 0.00 MB / 0.00 % prev-live: 0.00 MB / 0.00 % next-live: 0.00 MB / 0.00 % remset: 2.37 MB code-roots: 0.00 MB 16M->16M(2012M), 0.0055096 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
这部分信息通过-XX:+G1PrintHeapRegions输出。记录了区域提交、分配和回收的事件。
G1HR ALLOC(Eden) 0x00000000ff000000 G1HR ALLOC(Eden) 0x00000000fec00000 G1HR ALLOC(Eden) 0x00000000fe800000 G1HR ALLOC(Eden) 0x00000000fe400000 ...... ...... 2019-12-22T09:12:52.100-0500: 5.165: [GC pause (G1 Evacuation Pause) (young) G1HR #StartGC 5 Desired survivor size 79691776 bytes, new threshold 15 (max 15) - age 1: 3609072 bytes, 3609072 total - age 2: 361824 bytes, 3970896 total - age 3: 3155952 bytes, 7126848 total G1HR CSET 0x00000000b4800000 G1HR CSET 0x00000000b7800000 G1HR CSET 0x00000000b7c00000 G1HR CSET 0x00000000b8000000 G1HR CSET 0x00000000b8400000 G1HR CSET 0x00000000d0c00000 G1HR CSET 0x00000000d1000000 G1HR ALLOC(Survivor) 0x00000000b4400000 G1HR ALLOC(Survivor) 0x00000000b4000000 G1HR ALLOC(Survivor) 0x00000000b3c00000 G1HR ALLOC(Survivor) 0x00000000b3800000 G1HR ALLOC(Survivor) 0x00000000b3400000 G1HR RETIRE 0x00000000b3400000 0x00000000b351bf50 G1HR #EndGC 5
[0.006s][info][gc,heap] Heap region size: 4M [0.016s][info][gc ] Using G1 [0.016s][info][gc,heap,coops] Heap address: 0x0000000082000000, size: 30688 MB, Compressed Oops mode: Zero based, Oop shift amount: 3 [0.017s][info][gc,cds ] Mark closed archive regions in map: [0x00000007ffc00000, 0x00000007ffc79ff8] [0.017s][info][gc,cds ] Mark open archive regions in map: [0x00000007ffb00000, 0x00000007ffb47ff8] [0.035s][info][gc ] Periodic GC disabled [0.956s][info][gc,start ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) [0.958s][info][gc,task ] GC(0) Using 33 workers of 33 for evacuation [0.972s][info][gc,phases ] GC(0) Pre Evacuate Collection Set: 0.1ms [0.973s][info][gc,phases ] GC(0) Evacuate Collection Set: 12.8ms [0.973s][info][gc,phases ] GC(0) Post Evacuate Collection Set: 0.9ms [0.973s][info][gc,phases ] GC(0) Other: 2.3ms [0.973s][info][gc,heap ] GC(0) Eden regions: 25->0(23) [0.973s][info][gc,heap ] GC(0) Survivor regions: 0->2(4) [0.973s][info][gc,heap ] GC(0) Old regions: 0->0 [0.973s][info][gc,heap ] GC(0) Archive regions: 2->2 [0.973s][info][gc,heap ] GC(0) Humongous regions: 0->0 [0.973s][info][gc,metaspace ] GC(0) Metaspace: 4338K->4338K(1056768K) [0.973s][info][gc ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 103M->9M(2020M) 16.274ms [0.973s][info][gc,cpu ] GC(0) User=0.11s Sys=0.08s Real=0.02s
[24.640s][info][gc,start ] GC(26) Pause Full (Metadata GC Threshold) [24.644s][info][gc,phases,start] GC(26) Phase 1: Mark live objects [24.684s][info][gc,phases ] GC(26) Phase 1: Mark live objects 40.366ms [24.684s][info][gc,phases,start] GC(26) Phase 2: Prepare for compaction [24.689s][info][gc,phases ] GC(26) Phase 2: Prepare for compaction 5.087ms [24.689s][info][gc,phases,start] GC(26) Phase 3: Adjust pointers [24.706s][info][gc,phases ] GC(26) Phase 3: Adjust pointers 16.945ms [24.706s][info][gc,phases,start] GC(26) Phase 4: Compact heap [24.712s][info][gc,phases ] GC(26) Phase 4: Compact heap 6.199ms [24.727s][info][gc,heap ] GC(26) Eden regions: 153->0(66) [24.727s][info][gc,heap ] GC(26) Survivor regions: 4->0(7) [24.727s][info][gc,heap ] GC(26) Old regions: 38->37 [24.727s][info][gc,heap ] GC(26) Archive regions: 2->2 [24.727s][info][gc,heap ] GC(26) Humongous regions: 0->0 [24.727s][info][gc,metaspace ] GC(26) Metaspace: 96236K->96236K(1136640K) [24.727s][info][gc ] GC(26) Pause Full (Metadata GC Threshold) 706M->98M(520M) 86.244ms [24.727s][info][gc,cpu ] GC(26) User=0.84s Sys=0.12s Real=0.08s
值得注意的是，在g1堆中，堆区域是可以回收的（和zgc一样），而不是和parallel gc/cms一样只增不减。
注1：并非所有的gc事件笔者都在实际环境见过，可能有些很特殊，出现纯属偶然，且难以模拟。
zgc
[0.006s][info][gc,init] Initializing The Z Garbage Collector [0.006s][info][gc,init] Version: 13.0.1+9 (release) [0.006s][info][gc,init] NUMA Support: Enabled [0.006s][info][gc,init] NUMA Nodes: 2 [0.006s][info][gc,init] CPUs: 48 total, 48 available [0.007s][info][gc,init] Memory: 128660M [0.007s][info][gc,init] Large Page Support: Disabled [0.007s][info][gc,init] Workers: 29 parallel, 6 concurrent [0.009s][info][gc,init] Address Space: 0x0000040000000000 - 0x0000140000000000 (16T) [0.009s][info][gc,init] Heap backed by file: /memfd:java_heap [0.009s][info][gc,init] Min Capacity: 8M [0.009s][info][gc,init] Initial Capacity: 2012M [0.009s][info][gc,init] Max Capacity: 30718M [0.009s][info][gc,init] Max Reserve: 90M [0.009s][info][gc,init] Pre-touch: Disabled [0.009s][info][gc,init] Available space on backing filesystem: N/A [0.329s][info][gc,init] Uncommit: Enabled, Delay: 60s [0.339s][info][gc,init] Runtime Workers: 29 parallel [0.340s][info][gc ] Using The Z Garbage Collector [2.284s][info][gc,start] GC(0) Garbage Collection (Metadata GC Threshold) [2.287s][info][gc,phases] GC(0) Pause Mark Start 2.212ms [2.304s][info][gc,phases] GC(0) Concurrent Mark 16.890ms [2.305s][info][gc,phases] GC(0) Pause Mark End 1.118ms [2.306s][info][gc,phases] GC(0) Concurrent Process Non-Strong References 0.297ms [2.306s][info][gc,phases] GC(0) Concurrent Reset Relocation Set 0.001ms [2.314s][info][gc,phases] GC(0) Concurrent Select Relocation Set 7.947ms [2.315s][info][gc,phases] GC(0) Pause Relocate Start 0.740ms [2.322s][info][gc,phases] GC(0) Concurrent Relocate 7.529ms [2.322s][info][gc,load ] GC(0) Load: 0.25/0.18/0.24 [2.322s][info][gc,mmu ] GC(0) MMU: 2ms/0.0%, 5ms/55.8%, 10ms/77.9%, 20ms/86.3%, 50ms/91.9%, 100ms/95.9% [2.322s][info][gc,marking] GC(0) Mark: 4 stripe(s), 5 proactive flush(es), 2 terminate flush(es), 1 completion(s), 0 continuation(s) [2.322s][info][gc,reloc ] GC(0) Relocation: Successful, 9M relocated [2.322s][info][gc,nmethod] GC(0) NMethods: 2303 registered, 0 unregistered [2.322s][info][gc,metaspace] GC(0) Metaspace: 20M used, 20M capacity, 21M committed, 22M reserved [2.322s][info][gc,ref ] GC(0) Soft: 3101 encountered, 0 discovered, 0 enqueued [2.322s][info][gc,ref ] GC(0) Weak: 1074 encountered, 383 discovered, 143 enqueued [2.322s][info][gc,ref ] GC(0) Final: 2 encountered, 1 discovered, 1 enqueued [2.322s][info][gc,ref ] GC(0) Phantom: 1631 encountered, 1602 discovered, 1353 enqueued [2.322s][info][gc,heap ] GC(0) Min Capacity: 8M(0%) [2.322s][info][gc,heap ] GC(0) Max Capacity: 30718M(100%) [2.322s][info][gc,heap ] GC(0) Soft Max Capacity: 30718M(100%) [2.322s][info][gc,heap ] GC(0) Mark Start Mark End Relocate Start Relocate End High Low [2.322s][info][gc,heap ] GC(0) Capacity: 2012M (7%) 2012M (7%) 2012M (7%) 2012M (7%) 2012M (7%) 2012M (7%) [2.322s][info][gc,heap ] GC(0) Reserve: 90M (0%) 90M (0%) 90M (0%) 90M (0%) 90M (0%) 90M (0%) [2.323s][info][gc,heap ] GC(0) Free: 30174M (98%) 30170M (98%) 30198M (98%) 30558M (99%) 30558M (99%) 30140M (98%) [2.323s][info][gc,heap ] GC(0) Used: 454M (1%) 458M (1%) 430M (1%) 70M (0%) 488M (2%) 70M (0%) [2.323s][info][gc,heap ] GC(0) Live: - 11M (0%) 11M (0%) 11M (0%) - - [2.323s][info][gc,heap ] GC(0) Allocated: - 4M (0%) 8M (0%) 68M (0%) - - [2.323s][info][gc,heap ] GC(0) Garbage: - 442M (1%) 410M (1%) 50M (0%) - - [2.323s][info][gc,heap ] GC(0) Reclaimed: - - 32M (0%) 392M (1%) - - [2.323s][info][gc ] GC(0) Garbage Collection (Metadata GC Threshold) 454M(1%)->70M(0%)
[10.373s][info][gc,stats ] === Garbage Collection Statistics ======================================================================================================================= [10.373s][info][gc,stats ] Last 10s Last 10m Last 10h Total [10.373s][info][gc,stats ] Avg / Max Avg / Max Avg / Max Avg / Max [10.373s][info][gc,stats ] Collector: Garbage Collection Cycle 41.276 / 44.664 41.276 / 44.664 41.276 / 44.664 41.276 / 44.664 ms [10.373s][info][gc,stats ] Contention: Mark Segment Reset Contention 0 / 3 0 / 3 0 / 3 0 / 3 ops/s [10.373s][info][gc,stats ] Contention: Mark SeqNum Reset Contention 0 / 0 0 / 0 0 / 0 0 / 0 ops/s [10.373s][info][gc,stats ] Contention: Relocation Contention 3 / 18 3 / 18 3 / 18 3 / 18 ops/s [10.373s][info][gc,stats ] Critical: Allocation Stall 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 ms [10.373s][info][gc,stats ] Critical: Allocation Stall 0 / 0 0 / 0 0 / 0 0 / 0 ops/s [10.373s][info][gc,stats ] Critical: GC Locker Stall 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 ms [10.373s][info][gc,stats ] Critical: GC Locker Stall 0 / 0 0 / 0 0 / 0 0 / 0 ops/s [10.373s][info][gc,stats ] Memory: Allocation Rate 362 / 542 362 / 542 362 / 542 362 / 542 MB/s [10.373s][info][gc,stats ] Memory: Heap Used After Mark 601 / 744 601 / 744 601 / 744 601 / 744 MB [10.373s][info][gc,stats ] Memory: Heap Used After Relocation 87 / 104 87 / 104 87 / 104 87 / 104 MB [10.373s][info][gc,stats ] Memory: Heap Used Before Mark 592 / 730 592 / 730 592 / 730 592 / 730 MB [10.373s][info][gc,stats ] Memory: Heap Used Before Relocation 563 / 696 563 / 696 563 / 696 563 / 696 MB [10.373s][info][gc,stats ] Memory: Out Of Memory 0 / 0 0 / 0 0 / 0 0 / 0 ops/s [10.373s][info][gc,stats ] Memory: Page Cache Flush 0 / 0 0 / 0 0 / 0 0 / 0 MB/s [10.373s][info][gc,stats ] Memory: Page Cache Hit L1 41 / 225 41 / 225 41 / 225 41 / 225 ops/s [10.373s][info][gc,stats ] Memory: Page Cache Hit L2 13 / 123 13 / 123 13 / 123 13 / 123 ops/s [10.373s][info][gc,stats ] Memory: Page Cache Hit L3 99 / 257 99 / 257 99 / 257 99 / 257 ops/s [10.373s][info][gc,stats ] Memory: Page Cache Miss 28 / 271 28 / 271 28 / 271 28 / 271 ops/s [10.373s][info][gc,stats ] Memory: Uncommit 0 / 0 0 / 0 0 / 0 0 / 0 MB/s [10.373s][info][gc,stats ] Memory: Undo Object Allocation Failed 0 / 0 0 / 0 0 / 0 0 / 0 ops/s [10.373s][info][gc,stats ] Memory: Undo Object Allocation Succeeded 3 / 18 3 / 18 3 / 18 3 / 18 ops/s [10.373s][info][gc,stats ] Memory: Undo Page Allocation 0 / 0 0 / 0 0 / 0 0 / 0 ops/s [10.373s][info][gc,stats ] Phase: Concurrent Mark 21.774 / 26.659 21.774 / 26.659 21.774 / 26.659 21.774 / 26.659 ms [10.373s][info][gc,stats ] Phase: Concurrent Mark Continue 1.244 / 1.244 1.244 / 1.244 1.244 / 1.244 1.244 / 1.244 ms [10.373s][info][gc,stats ] Phase: Concurrent Process Non-Strong References 0.448 / 0.600 0.448 / 0.600 0.448 / 0.600 0.448 / 0.600 ms [10.373s][info][gc,stats ] Phase: Concurrent Relocate 8.138 / 8.747 8.138 / 8.747 8.138 / 8.747 8.138 / 8.747 ms [10.373s][info][gc,stats ] Phase: Concurrent Reset Relocation Set 0.023 / 0.046 0.023 / 0.046 0.023 / 0.046 0.023 / 0.046 ms [10.373s][info][gc,stats ] Phase: Concurrent Select Relocation Set 5.241 / 7.947 5.241 / 7.947 5.241 / 7.947 5.241 / 7.947 ms [10.373s][info][gc,stats ] Phase: Pause Mark End 0.766 / 1.118 0.766 / 1.118 0.766 / 1.118 0.766 / 1.118 ms [10.373s][info][gc,stats ] Phase: Pause Mark Start 1.673 / 2.212 1.673 / 2.212 1.673 / 2.212 1.673 / 2.212 ms [10.373s][info][gc,stats ] Phase: Pause Relocate Start 0.963 / 1.187 0.963 / 1.187 0.963 / 1.187 0.963 / 1.187 ms [10.373s][info][gc,stats ] Subphase: Concurrent Classes Unload 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 ms [10.373s][info][gc,stats ] Subphase: Concurrent Mark 14.144 / 25.977 14.144 / 25.977 14.144 / 25.977 14.144 / 25.977 ms [10.373s][info][gc,stats ] Subphase: Concurrent Mark Idle 1.060 / 1.095 1.060 / 1.095 1.060 / 1.095 1.060 / 1.095 ms [10.373s][info][gc,stats ] Subphase: Concurrent Mark Try Flush 0.047 / 0.161 0.047 / 0.161 0.047 / 0.161 0.047 / 0.161 ms [10.373s][info][gc,stats ] Subphase: Concurrent Mark Try Terminate 0.873 / 1.097 0.873 / 1.097 0.873 / 1.097 0.873 / 1.097 ms [10.373s][info][gc,stats ] Subphase: Concurrent References Enqueue 0.004 / 0.004 0.004 / 0.004 0.004 / 0.004 0.004 / 0.004 ms [10.373s][info][gc,stats ] Subphase: Concurrent References Process 0.149 / 0.187 0.149 / 0.187 0.149 / 0.187 0.149 / 0.187 ms [10.373s][info][gc,stats ] Subphase: Concurrent Roots 0.139 / 0.470 0.139 / 0.470 0.139 / 0.470 0.139 / 0.470 ms [10.373s][info][gc,stats ] Subphase: Concurrent Roots ClassLoaderDataGraph 0.134 / 0.469 0.134 / 0.469 0.134 / 0.469 0.134 / 0.469 ms [10.373s][info][gc,stats ] Subphase: Concurrent Roots JNIHandles 0.004 / 0.008 0.004 / 0.008 0.004 / 0.008 0.004 / 0.008 ms [10.373s][info][gc,stats ] Subphase: Concurrent Roots Setup 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 ms [10.373s][info][gc,stats ] Subphase: Concurrent Roots Teardown 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 ms [10.373s][info][gc,stats ] Subphase: Concurrent Weak Roots 0.251 / 0.384 0.251 / 0.384 0.251 / 0.384 0.251 / 0.384 ms [10.373s][info][gc,stats ] Subphase: Concurrent Weak Roots JNIWeakHandles 0.000 / 0.001 0.000 / 0.001 0.000 / 0.001 0.000 / 0.001 ms [10.373s][info][gc,stats ] Subphase: Concurrent Weak Roots ResolvedMethodTable 0.023 / 0.031 0.023 / 0.031 0.023 / 0.031 0.023 / 0.031 ms [10.373s][info][gc,stats ] Subphase: Concurrent Weak Roots StringTable 0.219 / 0.329 0.219 / 0.329 0.219 / 0.329 0.219 / 0.329 ms [10.373s][info][gc,stats ] Subphase: Concurrent Weak Roots VMWeakHandles 0.012 / 0.024 0.012 / 0.024 0.012 / 0.024 0.012 / 0.024 ms [10.373s][info][gc,stats ] Subphase: Pause Mark Try Complete 0.403 / 1.029 0.403 / 1.029 0.403 / 1.029 0.403 / 1.029 ms [10.373s][info][gc,stats ] Subphase: Pause Roots 0.373 / 1.269 0.373 / 1.269 0.373 / 1.269 0.373 / 1.269 ms [10.373s][info][gc,stats ] Subphase: Pause Roots CodeCache 0.347 / 1.087 0.347 / 1.087 0.347 / 1.087 0.347 / 1.087 ms [10.373s][info][gc,stats ] Subphase: Pause Roots JVMTIExport 0.002 / 0.006 0.002 / 0.006 0.002 / 0.006 0.002 / 0.006 ms [10.373s][info][gc,stats ] Subphase: Pause Roots JVMTIWeakExport 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 ms [10.373s][info][gc,stats ] Subphase: Pause Roots Management 0.012 / 0.036 0.012 / 0.036 0.012 / 0.036 0.012 / 0.036 ms [10.373s][info][gc,stats ] Subphase: Pause Roots ObjectSynchronizer 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 ms [10.373s][info][gc,stats ] Subphase: Pause Roots Setup 0.001 / 0.002 0.001 / 0.002 0.001 / 0.002 0.001 / 0.002 ms [10.374s][info][gc,stats ] Subphase: Pause Roots SystemDictionary 0.037 / 0.074 0.037 / 0.074 0.037 / 0.074 0.037 / 0.074 ms [10.374s][info][gc,stats ] Subphase: Pause Roots Teardown 0.005 / 0.005 0.005 / 0.005 0.005 / 0.005 0.005 / 0.005 ms [10.374s][info][gc,stats ] Subphase: Pause Roots Threads 0.127 / 1.266 0.127 / 1.266 0.127 / 1.266 0.127 / 1.266 ms [10.374s][info][gc,stats ] Subphase: Pause Roots Universe 0.007 / 0.013 0.007 / 0.013 0.007 / 0.013 0.007 / 0.013 ms [10.374s][info][gc,stats ] Subphase: Pause Weak Roots 0.000 / 0.008 0.000 / 0.008 0.000 / 0.008 0.000 / 0.008 ms [10.374s][info][gc,stats ] Subphase: Pause Weak Roots JFRWeak 0.000 / 0.001 0.000 / 0.001 0.000 / 0.001 0.000 / 0.001 ms [10.374s][info][gc,stats ] Subphase: Pause Weak Roots JVMTIWeakExport 0.003 / 0.006 0.003 / 0.006 0.003 / 0.006 0.003 / 0.006 ms [10.374s][info][gc,stats ] Subphase: Pause Weak Roots Setup 0.000 / 0.001 0.000 / 0.001 0.000 / 0.001 0.000 / 0.001 ms [10.374s][info][gc,stats ] Subphase: Pause Weak Roots Teardown 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 0.000 / 0.000 ms [10.374s][info][gc,stats ] System: Java Threads 17 / 18 17 / 18 17 / 18 17 / 18 threads [10.374s][info][gc,stats ] =========================================================================================================================================================
[60.384s][info][gc,heap ] Capacity: 4310M(14%)->4252M(14%), Uncommitted: 58M [74.617s][info][gc,heap ] Capacity: 4252M(14%)->3042M(10%), Uncommitted: 1210M [86.866s][info][gc,heap ] Capacity: 3042M(10%)->1820M(6%), Uncommitted: 1222M
openj9
openj9日志默认为xml格式。下文scavenge用于新生代（nursery）收集。global用于老年代（tenure）收集。如下：
<concurrent-kickoff id="1083" timestamp="2019-12-22T09:06:49.766">
<kickoff reason="threshold reached" targetBytes="5041305" thresholdFreeBytes="698831" remainingFree="637904" tenureFreeBytes="1409808" nurseryFreeBytes="637904" />
</concurrent-kickoff>
<exclusive-start id="2" timestamp="2019-12-21T16:43:57.805" intervalms="188.860">【标记STW开始】
<response-info timems="0.031"【标识gc线程为了开始STW，等待其它线程停止花费的时间】 idlems="0.031"【从等待第一个到最后线程停止等待得时间】 threads="0"【需要等待释放VM资源的线程数】 lastid="00007FAB8811A900"【最后一个应答的线程】 lastname="main"【lastid对应的线程名】 />
</exclusive-start>
<af-start【af全称Allocation failure，标记本gc是由分配失败触发】 id="3" threadId="00007FAB8811B2F8" totalBytesRequested="824"【标记是申请多少内存失败触发的gc】 timestamp="2019-12-21T16:43:57.805" intervalms="188.993"【上一次af-start以来经过的时间】 type="nursery" />
<cycle-start id="4" type="scavenge" contextid="0" timestamp="2019-12-21T16:43:57.805" intervalms="189.047"【上一次本类型的gc开始后经过的时间，所以它是包括上一次gc的时间+经过的延时+本次启动时间】 />【标记一次gc周期开始】
<gc-start id="5" type="scavenge"【gc类型，新生代（nursery）收集；还有一个值为global，为标记-清理回收】 contextid="4" timestamp="2019-12-21T16:43:57.805"【标记gc开始时间，其它节点的属性同】>【标记一次完整的gc增量，每个gc增量至少有一个gc操作】
<mem-info id="6" free="6133264"【堆空闲容量】 total="8388608"【堆容量】 percent="73">
<mem type="nursery" free="0" total="2097152" percent="0">【新生代大小，在openj9中，allocate和suvivor大小是动态的，目标是最小化gc次数】
<mem type="allocate" free="0" total="1048576" percent="0" />【eden区】
<mem type="survivor" free="0" total="1048576" percent="0" />【survivor区】
</mem>
<mem type="tenure" free="6133264" total="6291456" percent="97">
<mem type="soa" free="5818896" total="5977088" percent="97" />【small object area，小对象区域】
<mem type="loa" free="314368" total="314368" percent="100" />【大对象区域，大对象的边界由jvm选项-Xloainitial0.05、-Xloaminimum0、-Xloamaximum0.5三个参数控制】
</mem>
<remembered-set count="1581" />
</mem-info>
</gc-start>
<allocation-stats totalBytes="1203080" >
<allocated-bytes non-tlh="158192" tlh="1044888" />
<largest-consumer threadName="main" threadId="00007FAB8811A900" bytes="1115440" />
</allocation-stats>
<gc-op id="1111" type="rs-scan" timems="1.036" contextid="1085" timestamp="2019-12-22T09:06:49.794">
<scan objectsFound="116" bytesTraced="24056" workStackOverflowCount="0" />
</gc-op>
<gc-op id="1112" type="card-cleaning" timems="0.433" contextid="1085" timestamp="2019-12-22T09:06:49.794">
<card-cleaning cardsCleaned="1" bytesTraced="13496" workStackOverflowCount="0" />
</gc-op>
<gc-op id="7" type="scavenge"【其值视gc的阶段及gc策略不同而不同，见手册Garbage collection operation一节】 timems="1.831" contextid="4" timestamp="2019-12-21T16:43:57.807">【每次gc增量至少有一个gc操作，这个节点就是】
【这一部分也依赖于gc-op的type取值，不同的gc类型，内容不同】
<scavenger-info tenureage="2"【对象被移动到老年代的当前年龄】 tenuremask="fffc" tiltratio="50"【新生代用于分配而非survivor的比例】 /> <memory-copied type="nursery"【除了它，还有tenure】 objects="5087" bytes="334904" bytesdiscarded="57112" />【本次gc拷贝到老年代或flipped to新生代的对象数量】
<memory-copied type="tenure" objects="426" bytes="101408" bytesdiscarded="64" />
<copy-failed type="nursery" objects="2" bytes="3146016" /> <finalization candidates="40"【候选数量，但不一定真正可执行】 enqueued="32"【可被finalization的数量】 />【标记本次gc时包含finalizer且等待jvm调用的对象数】 <ownableSynchronizers candidates="3" cleared="0" />
<references type="soft"【SoftReference类的实例】 candidates="125" cleared="0" enqueued="0" dynamicThreshold="32" maxThreshold="32" />【包含关于java引用对象的信息】 <references type="weak"【WeakReference实例】 candidates="248" cleared="204" enqueued="202" /> <references type="phantom"【PhantomReference实例】 candidates="7" cleared="1" enqueued="1" />
<heap-resize type="expand" space="tenure" amount="1114112" count="1" timems="0.050" reason="continue current collection" />
</gc-op>
<heap-resize id="1100" type="expand" space="nursery" amount="4587520" count="1" timems="0.061" reason="excessive time being spent scavenging" timestamp="2019-12-22T09:06:49.787" />
<gc-end id="8" type="scavenge" contextid="4" durationms="2.029"【gc延时，gc有可能多线程，故延时可能会小于用户态+内核态时间】 usertimems="4.999"【用户态gc时间】 systemtimems="0.000"【内核态gc时间】 timestamp="2019-12-21T16:43:57.807"【gc结束时间】 activeThreads="4"【本次gc活跃的gc线程数，它小于等于声明的gc线程数】>【标记gc增量结束】
<mem-info id="9" free="6789800" total="8388608" percent="80">
<mem type="nursery" free="656536" total="2097152" percent="31">
<mem type="allocate" free="656536" total="1048576" percent="62" />
<mem type="survivor" free="0" total="1048576" percent="0" />
</mem>
<mem type="tenure" free="6133264" total="6291456" percent="97">
<mem type="soa" free="5818896" total="5977088" percent="97" />
<mem type="loa" free="314368" total="314368" percent="100" />
</mem>
<pending-finalizers system="32"【队列中的对象数】 default="0" reference="203" classloader="0"【可被异步卸载的类加载器数量】 />【标记队列中finalizable对象的当前状态】
<remembered-set count="1581" />
</mem-info>
</gc-end>
<cycle-end id="10" type="scavenge" contextid="4" timestamp="2019-12-21T16:43:57.807" />【标记一次gc周期结束】
<allocation-satisfied id="11" threadId="00007FAB8811A900"【触发gc的线程】 bytesRequested="824" />【当因为af导致的gc完成后，会生成本节点。如果gc完成后仍然内存不够，则会触发global类型的gc】
<af-end id="12" timestamp="2019-12-21T16:43:57.807" threadId="00007FAB8811B2F8" success="true" from="nursery"/>
<exclusive-end id="13" timestamp="2019-12-21T16:43:57.807" durationms="2.412" />
<exclusive-start id="1107" timestamp="2019-12-22T09:06:49.793" intervalms="14.826">
<response-info timems="0.054" idlems="0.054" threads="0" lastid="00007F238C21C800" lastname="main" />
</exclusive-start>
<concurrent-collection-start id="1108" timestamp="2019-12-22T09:06:49.793" intervalms="220.916" >
<concurrent-trace-info reason="card cleaning threshold reached" tracedByMutators="2379680" tracedByHelpers="2975760" cardsCleaned="72" workStackOverflowCount="0" />
</concurrent-collection-start>
<gc-start id="1109" type="global" contextid="1085" timestamp="2019-12-22T09:06:49.793">
<mem-info id="1110" free="745728" total="28377088" percent="2">
<mem type="nursery" free="0" total="13893632" percent="0">
<mem type="allocate" free="0" total="6946816" percent="0" />
<mem type="survivor" free="0" total="6946816" percent="0" />
</mem>
<mem type="tenure" free="745728" total="14483456" percent="5">
<mem type="soa" free="21760" total="13759488" percent="0" />
<mem type="loa" free="723968" total="723968" percent="100" />
</mem>
<remembered-set count="185" />
</mem-info>
</gc-start>
<allocation-stats totalBytes="3120384" >
<allocated-bytes non-tlh="32" tlh="3120352" />
<largest-consumer threadName="main" threadId="00007F238C21C800" bytes="3120384" />
</allocation-stats>
<gc-op id="1111" type="rs-scan" timems="1.036" contextid="1085" timestamp="2019-12-22T09:06:49.794">
<scan objectsFound="116" bytesTraced="24056" workStackOverflowCount="0" />
</gc-op>
<gc-op id="1112" type="card-cleaning" timems="0.433" contextid="1085" timestamp="2019-12-22T09:06:49.794">
<card-cleaning cardsCleaned="1" bytesTraced="13496" workStackOverflowCount="0" />
</gc-op>
<gc-op id="1113" type="mark" timems="2.954" contextid="1085" timestamp="2019-12-22T09:06:49.797">
<trace-info objectcount="236623" scancount="236621" scanbytes="9669752" />
<finalization candidates="87" enqueued="0" />
<ownableSynchronizers candidates="18" cleared="0" />
<references type="soft" candidates="3076" cleared="0" enqueued="0" dynamicThreshold="9" maxThreshold="32" />
<references type="weak" candidates="1502" cleared="2" enqueued="1" />
<references type="phantom" candidates="224" cleared="0" enqueued="0" />
<stringconstants candidates="6474" cleared="2" />
</gc-op>
<gc-op id="1114" type="sweep" timems="1.037" contextid="1085" timestamp="2019-12-22T09:06:49.798" />
<heap-resize id="1115" type="expand" space="tenure" amount="5046272" count="1" timems="0.487" reason="insufficient free space following gc" timestamp="2019-12-22T09:06:49.799" />
<gc-end id="1116" type="global" contextid="1085" durationms="6.175" usertimems="42.413" systemtimems="15.963" timestamp="2019-12-22T09:06:49.799" activeThreads="13">
<mem-info id="1117" free="5989312" total="33423360" percent="17">
<mem type="nursery" free="108656" total="13893632" percent="0">
<mem type="allocate" free="108656" total="6946816" percent="1" />
<mem type="survivor" free="0" total="6946816" percent="0" />
</mem>
<mem type="tenure" free="5880656" total="19529728" percent="30" micro-fragmented="124096" macro-fragmented="0">
<mem type="soa" free="4904784" total="18553856" percent="26" />
<mem type="loa" free="975872" total="975872" percent="100" />
</mem>
<pending-finalizers system="0" default="0" reference="1" classloader="0" />
<remembered-set count="184" />
</mem-info>
</gc-end>
<cycle-end id="1118" type="global" contextid="1085" timestamp="2019-12-22T09:06:49.799" />
<concurrent-collection-end id="1119" timestamp="2019-12-22T09:06:49.799" />
<exclusive-end id="1120" timestamp="2019-12-22T09:06:49.799" durationms="6.314" />
<concurrent-kickoff id="1177" timestamp="2019-12-22T09:06:49.895"> <kickoff reason="threshold reached" targetBytes="10080968" thresholdFreeBytes="1397187" remainingFree="1313792" tenureFreeBytes="4070296" nurseryFreeBytes="1313792" /> </concurrent-kickoff>
<gc-op id="2572" type="scavenge" timems="4.303" contextid="2569" timestamp="2019-12-22T09:07:00.032"> <scavenger-info tenureage="14" tenuremask="4000" tiltratio="89" />【可见allocator和survivor的比例是动态的】 <memory-copied type="nursery" objects="21293" bytes="1599544" bytesdiscarded="257752" /> <finalization candidates="5" enqueued="0" /> <ownableSynchronizers candidates="81" cleared="0" /> <references type="soft" candidates="1391" cleared="0" enqueued="0" dynamicThreshold="9" maxThreshold="32" /> <references type="weak" candidates="900" cleared="400" enqueued="369" /> <references type="phantom" candidates="93" cleared="93" enqueued="93" /> </gc-op>
<heap-resize id="4799" type="expand" space="tenure" amount="7798784" count="1" timems="1.061" reason="insufficient free space following gc" timestamp="2019-12-22T14:19:43.409" /> <heap-resize id="4931" type="contract" space="nursery" amount="524288" count="1" timems="0.137" reason="insufficient time being spent scavenging" timestamp="2019-12-22T14:23:11.961" />
