各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，參考https://blog.csdn.net/liubenlong007/article/details/78143285。詳見-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事件筆者都在實際環境見過，可能有些很特殊，出現純屬偶然，且難以模擬。
參考：https://dzone.com/articles/understanding-g1-gc-log-format，https://blogs.oracle.com/poonam/understanding-g1-gc-logs，https://www.cnblogs.com/lujiango/p/9021279.html，https://www.redhat.com/en/blog/part-1-introduction-g1-garbage-collector，https://www.redhat.com/en/blog/collecting-and-reading-g1-garbage-collector-logs-part-2
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" />
openj9捐獻給eclipse之后，目前文檔還不完善，https://www.eclipse.org/openj9/docs/，https://www.eclipse.org/openj9/docs/version0.17/
openj9每個元素的詳細含義可見https://www.ibm.com/support/knowledgecenter/SSYKE2_8.0.0/com.ibm.java.vm.80.doc/docs/mm_gc_pd_verbosegc.html。
gc日志分析工具：https://gceasy.io/gc-index.jsp#banner，也可以使用GCMV (Garbage Collection and Memory Visualizer)（eclipse插件），后者效果不如前者。只不過前者無法分析openj9日志。
gc優化官方文檔：https://docs.oracle.com/javase/8/docs/technotes/guides/vm/gctuning/toc.html、https://plumbr.io/handbook/gc-tuning-in-practice
圖形化分析還可以參考下https://www.cnblogs.com/qlqwjy/p/7929414.html。
full gc觸發的各種條件，完整參考：https://cloud.tencent.com/developer/article/1082687