GC相关：
打印日志相关参数：
-XX:+PrintGCDetails
-XX:PrintGCTimestamps
-XX:PrintGCDateStamps
-Xloggc:$CATALINA_HOME/logs/gc.log
-XX:+PrintHeapAtGC
-XX:+PrintTenuringDistriution：发生GC的时候，把Young区中对象的年龄打印出来
其余的参数应该能直接看懂的，就不解释了。
PS：日志中加的注释下一行会错位，请自行注意。
Parallel日志：
默认情况下，都是使用Parallel收集器
JAVA_OPTS="-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:$CATALINA_HOME/logs/gc.log"
打开gc.log文件：
#虚拟机版本、jdk版本、Linux内核等Java HotSpot(TM) 64-Bit Server VM (25.102-b14) for linux-amd64 JRE (1.8.0_102-b14), built on Jun 22 2016 18:43:17 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8) #磁盘数据每页4K，内存4G，1.7G属于空闲Memory: 4k page, physical 3880412k(1678252k free), swap 0k(0k free) #打印命令：因为Parallel是自适应的，虽然没有设置一些参数，但是根据服务器的内存、CPU等情况就行分配。CommandLine flags: -XX:InitialHeapSize=62086592 -XX:MaxHeapSize=993385472 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC #对象分配内存失败，Young区发生GC，从15M-->2M，总17M，堆从15M-->4M，总58M，GC时间0.0074512s，Young区减少13M，堆只减少了11M，所以有2M对象到了Old区 2019-07-15T10:38:52.441+0800: 0.654: [GC (Allocation Failure) [PSYoungGen: 15360K->2544K(17920K)] 15360K->4022K(58880K), 0.0074512 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 2019-07-15T10:38:52.942+0800: 1.155: [GC (Allocation Failure) [PSYoungGen: 17904K->2554K(33280K)] 19382K->7383K(74240K), 0.0171215 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 2019-07-15T10:38:53.359+0800: 1.572: [GC (Allocation Failure) [PSYoungGen: 33274K->2554K(33280K)] 38103K->11504K(74240K), 0.0143284 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 2019-07-15T10:38:53.500+0800: 1.713: [GC (Allocation Failure) [PSYoungGen: 33274K->2554K(64000K)] 42224K->14443K(104960K), 0.0129043 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 2019-07-15T10:38:53.788+0800: 2.000: [GC (Allocation Failure) [PSYoungGen: 63994K->2554K(64000K)] 75883K->23497K(104960K), 0.0179449 secs] [Times: user=0.03 sys=0.01, real=0.02 secs] 2019-07-15T10:38:54.041+0800: 2.253: [GC (Allocation Failure) [PSYoungGen: 63994K->11256K(131584K)] 84937K->33580K(172544K), 0.0177155 secs] [Times: user=0.02 sys=0.01, real=0.02 secs] 2019-07-15T10:38:54.500+0800: 2.713: [GC (Allocation Failure) [PSYoungGen: 131576K->13815K(134144K)] 153900K->43739K(175104K), 0.0276207 secs] [Times: user=0.03 sys=0.02, real=0.03 secs] #Metaspace区发生GC，Young区发生GC，从115M-->10M，总258M，堆从145M-->40M，总299M，GC时间0.02273802019-07-15T10:38:55.513+0800: 3.726: [GC (Metadata GC Threshold) [PSYoungGen: 115110K->10443K(258560K)] 145034K->40823K(299520K), 0.0227380 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] #发生Full GC，因为Metaspace内存利用达到阀值，Old区也被回收了2019-07-15T10:38:55.536+0800: 3.748: [Full GC (Metadata GC Threshold) [PSYoungGen: 10443K->0K(258560K)] [ParOldGen: 30380K->28896K(59392K)] 40823K->28896K(317952K), [Metaspace: 20720K->20720K(1069056K)], 0.0819349 secs] [Times: user=0.14 sys=0.00, real=0.09 secs] 2019-07-15T10:38:58.060+0800: 6.272: [GC (Allocation Failure) [PSYoungGen: 240640K->15826K(259584K)] 269536K->44730K(318976K), 0.0444735 secs] [Times: user=0.08 sys=0.01, real=0.04 secs] 2019-07-15T10:38:58.842+0800: 7.054: [GC (Metadata GC Threshold) [PSYoungGen: 113863K->8488K(303616K)] 142768K->37401K(363008K), 0.0197353 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 2019-07-15T10:38:58.861+0800: 7.074: [Full GC (Metadata GC Threshold) [PSYoungGen: 8488K->0K(303616K)] [ParOldGen: 28912K->15427K(55296K)] 37401K->15427K(358912K), [Metaspace: 33955K->33955K(1081344K)], 0.1084317 secs] [Times: user=0.19 sys=0.00, real=0.11 secs]
-XX:+UseCompressedClassPointers使用CCS短指针
-XX:+UseCompressedOops：压缩对象指针
-XX:+UseParallelGC：默认使用Parallel垃圾收集器，Server模式下
[Times: user=0.02 sys=0.00, real=0.01 secs] ：分别代表用户态消耗的CPU时间、内核态消耗的CPU时间、操作从开始到结束经过的墙钟事件
CPU时间和墙钟时间区别：
墙钟时间包含多种非运算的等待耗时，例如等待磁盘IO、等待线程阻塞
CPU时间不包含这些耗时，多CPU或多核，会叠加这些CPU时间
CMS日志：截取部分日志
Java HotSpot(TM) 64-Bit Server VM (25.102-b14) for linux-amd64 JRE (1.8.0_102-b14), built on Jun 22 2016 18:43:17 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)Memory: 4k page, physical 3880412k(1677240k free), swap 0k(0k free) #因为使用了CMS，所以Young区使用了ParNew，从参数可以看出来：-XX:+UseConcMarkSweepGC -XX:+UseParNewGCCommandLine flags: -XX:InitialHeapSize=62086592 -XX:MaxHeapSize=993385472 -XX:MaxNewSize=174485504 -XX:MaxTenuringThreshold=6 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC #刚开始为Young区GC 2019-07-15T10:50:17.152+0800: 0.706: [GC (Allocation Failure) 2019-07-15T10:50:17.152+0800: 0.706: [ParNew: 16384K->2048K(18432K), 0.0116281 secs] 16384K->4234K(59392K), 0.0117284 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 2019-07-15T10:50:17.705+0800: 1.259: [GC (Allocation Failure) 2019-07-15T10:50:17.705+0800: 1.260: [ParNew: 18426K->2048K(18432K), 0.0166827 secs] 20612K->7790K(59392K), 0.0167603 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 2019-07-15T10:50:17.964+0800: 1.518: [GC (Allocation Failure) 2019-07-15T10:50:17.964+0800: 1.518: [ParNew: 18432K->2048K(18432K), 0.0131088 secs] 24174K->11214K(59392K), 0.0131987 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 2019-07-15T10:50:18.087+0800: 1.641: [GC (Allocation Failure) 2019-07-15T10:50:18.087+0800: 1.641: [ParNew: 18432K->2048K(18432K), 0.0063598 secs] 27598K->12525K(59392K), 0.0064490 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 2019-07-15T10:50:18.171+0800: 1.725: [GC (Allocation Failure) 2019-07-15T10:50:18.171+0800: 1.725: [ParNew: 18432K->2047K(18432K), 0.0048486 secs] 28909K->13416K(59392K), 0.0049454 secs] [Times: user=0.00 sys=0.01, real=0.00 secs] 2019-07-15T10:50:18.253+0800: 1.807: [GC (Allocation Failure) 2019-07-15T10:50:18.253+0800: 1.807: [ParNew: 18431K->2048K(18432K), 0.0044206 secs] 29800K->14647K(59392K), 0.0044871 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 2019-07-15T10:50:18.351+0800: 1.905: [GC (Allocation Failure) 2019-07-15T10:50:18.351+0800: 1.905: [ParNew: 18432K->2048K(18432K), 0.0078141 secs] 31031K->15528K(59392K), 0.0078983 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 2019-07-15T10:50:18.438+0800: 1.992: [GC (Allocation Failure) 2019-07-15T10:50:18.438+0800: 1.992: [ParNew: 18432K->2048K(18432K), 0.0036144 secs] 31912K->15758K(59392K), 0.0036887 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 2019-07-15T10:50:18.500+0800: 2.054: [GC (Allocation Failure) 2019-07-15T10:50:18.500+0800: 2.054: [ParNew: 18432K->2047K(18432K), 0.0043671 secs] 32142K->16245K(59392K), 0.0044290 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2019-07-15T10:50:18.574+0800: 2.128: [GC (Allocation Failure) 2019-07-15T10:50:18.574+0800: 2.128: [ParNew: 18431K->2048K(18432K), 0.0075469 secs] 32629K->16612K(59392K), 0.0076214 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 2019-07-15T10:50:18.632+0800: 2.186: [GC (Allocation Failure) 2019-07-15T10:50:18.632+0800: 2.186: [ParNew: 18432K->2048K(18432K), 0.0056882 secs] 32996K->16953K(59392K), 0.0057710 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 2019-07-15T10:50:18.700+0800: 2.254: [GC (Allocation Failure) 2019-07-15T10:50:18.700+0800: 2.254: [ParNew: 18432K->2047K(18432K), 0.0039387 secs] 33337K->17367K(59392K), 0.0039998 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 2019-07-15T10:50:18.769+0800: 2.323: [GC (Allocation Failure) 2019-07-15T10:50:18.769+0800: 2.323: [ParNew: 18431K->2048K(18432K), 0.0080793 secs] 33751K->18524K(59392K), 0.0081855 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 2019-07-15T10:50:18.841+0800: 2.395: [GC (Allocation Failure) 2019-07-15T10:50:18.841+0800: 2.395: [ParNew: 18432K->2047K(18432K), 0.0042404 secs] 34908K->19147K(59392K), 0.0043270 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 2019-07-15T10:50:18.903+0800: 2.457: [GC (Allocation Failure) 2019-07-15T10:50:18.903+0800: 2.457: [ParNew: 18431K->2048K(18432K), 0.0040362 secs] 35531K->19653K(59392K), 0.0040956 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2019-07-15T10:50:18.962+0800: 2.516: [GC (Allocation Failure) 2019-07-15T10:50:18.962+0800: 2.516: [ParNew: 18432K->2039K(18432K), 0.0071315 secs] 36037K->19920K(59392K), 0.0072320 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 2019-07-15T10:50:19.035+0800: 2.589: [GC (Allocation Failure) 2019-07-15T10:50:19.035+0800: 2.589: [ParNew: 18423K->2048K(18432K), 0.0048979 secs] 36304K->20760K(59392K), 0.0049775 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 2019-07-15T10:50:19.101+0800: 2.655: [GC (Allocation Failure) 2019-07-15T10:50:19.101+0800: 2.655: [ParNew: 18432K->2048K(18432K), 0.0044687 secs] 37144K->21047K(59392K), 0.0045589 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2019-07-15T10:50:19.164+0800: 2.718: [GC (Allocation Failure) 2019-07-15T10:50:19.164+0800: 2.718: [ParNew: 18432K->2048K(18432K), 0.0079322 secs] 37431K->21701K(59392K), 0.0080210 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 2019-07-15T10:50:19.235+0800: 2.789: [GC (Allocation Failure) 2019-07-15T10:50:19.235+0800: 2.789: [ParNew: 18432K->2048K(18432K), 0.0075261 secs] 38085K->22350K(59392K), 0.0076038 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 2019-07-15T10:50:19.303+0800: 2.857: [GC (Allocation Failure) 2019-07-15T10:50:19.303+0800: 2.857: [ParNew: 18432K->2048K(18432K), 0.0072659 secs] 38734K->22980K(59392K), 0.0073609 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] #Old区发生GC，为FUll GC #CMS初始标记，Old区为20M，总的为40M，堆区为24M，总的为59M 2019-07-15T10:50:19.317+0800: 2.871: [GC (CMS Initial Mark) [1 CMS-initial-mark: 20932K(40960K)] 24947K(59392K), 0.0020892 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] #并发标记2019-07-15T10:50:19.320+0800: 2.874: [CMS-concurrent-mark-start] #并发标记时间位0.41s2019-07-15T10:50:19.361+0800: 2.915: [CMS-concurrent-mark: 0.041/0.041 secs] [Times: user=0.07 sys=0.01, real=0.04 secs] #并发预清理2019-07-15T10:50:19.361+0800: 2.915: [CMS-concurrent-preclean-start] #时间为0.001s2019-07-15T10:50:19.362+0800: 2.916: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] #可终止预清理2019-07-15T10:50:19.362+0800: 2.916: [CMS-concurrent-abortable-preclean-start] #发生Young GC2019-07-15T10:50:19.369+0800: 2.923: [GC (Allocation Failure) 2019-07-15T10:50:19.369+0800: 2.923: [ParNew: 18432K->2047K(18432K), 0.0073641 secs] 39364K->23988K(59392K), 0.0074166 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] #可终止预清理时间位0.02s 2019-07-15T10:50:19.471+0800: 3.025: [CMS-concurrent-abortable-preclean: 0.020/0.109 secs] [Times: user=0.21 sys=0.00, real=0.11 secs] #重新标记 2019-07-15T10:50:19.477+0800: 3.031: [GC (CMS Final Remark) [YG occupancy: 14850 K (18432 K)]2019-07-15T10:50:19.477+0800: 3.031: [Rescan (parallel) , 0.0088998 secs]2019-07-15T10:50:19.486+0800: 3.040: [weak refs processing, 0.0004368 secs]2019-07-15T10:50:19.486+0800: 3.040: [class unloading, 0.0036209 secs]2019-07-15T10:50:19.490+0800: 3.044: [scrub symbol table, 0.0020465 secs]2019-07-15T10:50:19.492+0800: 3.046: [scrub string table, 0.0009907 secs][1 CMS-remark: 21940K(40960K)] 36790K(59392K), 0.0165922 secs] [Times: user=0.03 sys=0.01, real=0.02 secs] 2019-07-15T10:50:19.494+0800: 3.048: [CMS-concurrent-sweep-start]#并发清除时间位0.009s 2019-07-15T10:50:19.502+0800: 3.056: [CMS-concurrent-sweep: 0.009/0.009 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 2019-07-15T10:50:19.502+0800: 3.056: [CMS-concurrent-reset-start] #并发重置时间位0.044s2019-07-15T10:50:19.547+0800: 3.101: [CMS-concurrent-reset: 0.044/0.044 secs] [Times: user=0.06 sys=0.02, real=0.04 secs]
G1日志：
#发生Young区的GC2019-07-15T13:43:43.100+0800: 3.463: [GC pause (G1 Evacuation Pause) (young), 0.0191098 secs]#并行的时间12.5 ms,GC工作线程为2，我的阿里云只是双核的，下面的Min、Max和Avg是指启动的这些工作线程的运行状况 [Parallel Time: 12.5 ms, GC Workers: 2]#GC开始的时间点 [GC Worker Start (ms): Min: 3463.2, Avg: 3464.5, Max: 3465.8, Diff: 2.6]#GC Root扫描的时间 [Ext Root Scanning (ms): Min: 0.3, Avg: 3.9, Max: 7.4, Diff: 7.1, Sum: 7.7]#更新RSet的时间 [Update RS (ms): Min: 0.0, Avg: 1.6, Max: 3.1, Diff: 3.1, Sum: 3.1] [Processed Buffers: Min: 0, Avg: 7.0, Max: 14, Diff: 14, Sum: 14]#扫描RSet的时间 [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1] [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.1] [Object Copy (ms): Min: 5.0, Avg: 5.6, Max: 6.3, Diff: 1.3, Sum: 11.2] [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.1] [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [GC Worker Total (ms): Min: 9.9, Avg: 11.2, Max: 12.5, Diff: 2.6, Sum: 22.4] [GC Worker End (ms): Min: 3475.7, Avg: 3475.7, Max: 3475.7, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.1 ms] [Other: 6.5 ms] [Choose CSet: 0.0 ms] [Ref Proc: 4.5 ms] [Ref Enq: 0.1 ms] [Redirty Cards: 0.0 ms]#就是存储大对象的Region [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.1 ms]#Eden区回收67.0M，变成135.0M，Survivors区从5120.0K->9216.0K，堆区从92M到29.9M，并且总大小翻倍 [Eden: 67.0M(67.0M)->0.0B(135.0M) Survivors: 5120.0K->9216.0K Heap: 92.0M(120.0M)->29.9M(240.0M)] [Times: user=0.03 sys=0.00, real=0.02 secs]#堆占有率达到InitiatingHeapOccupancyPercent，发生一次Mixed GC，会有global concurrent marking，时间为0.0166952s2019-07-15T13:43:44.072+0800: 4.435: [GC pause (Metadata GC Threshold) (young) (initial-mark), 0.0166952 secs] [Parallel Time: 12.5 ms, GC Workers: 2] [GC Worker Start (ms): Min: 4435.1, Avg: 4435.9, Max: 4436.8, Diff: 1.7] [Ext Root Scanning (ms): Min: 1.2, Avg: 2.1, Max: 2.9, Diff: 1.8, Sum: 4.1] [Update RS (ms): Min: 1.6, Avg: 1.7, Max: 1.7, Diff: 0.2, Sum: 3.3] [Processed Buffers: Min: 4, Avg: 7.5, Max: 11, Diff: 7, Sum: 15] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.1] [Code Root Scanning (ms): Min: 0.2, Avg: 0.2, Max: 0.3, Diff: 0.1, Sum: 0.4] [Object Copy (ms): Min: 7.5, Avg: 7.6, Max: 7.7, Diff: 0.1, Sum: 15.2] [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [GC Worker Total (ms): Min: 10.7, Avg: 11.6, Max: 12.4, Diff: 1.7, Sum: 23.1] [GC Worker End (ms): Min: 4447.5, Avg: 4447.5, Max: 4447.5, Diff: 0.0] [Code Root Fixup: 0.1 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.1 ms] [Other: 4.1 ms] [Choose CSet: 0.0 ms] [Ref Proc: 3.7 ms] [Ref Enq: 0.0 ms] [Redirty Cards: 0.0 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.1 ms] [Eden: 83.0M(135.0M)->0.0B(135.0M) Survivors: 9216.0K->9216.0K Heap: 112.9M(240.0M)->29.4M(240.0M)] [Times: user=0.03 sys=0.01, real=0.02 secs] #并发root Region扫描2019-07-15T13:43:44.090+0800: 4.453: [GC concurrent-root-region-scan-start]2019-07-15T13:43:44.104+0800: 4.467: [GC concurrent-root-region-scan-end, 0.0138623 secs] #并发标记2019-07-15T13:43:44.104+0800: 4.467: [GC concurrent-mark-start]2019-07-15T13:43:44.166+0800: 4.529: [GC concurrent-mark-end, 0.0614277 secs] #重新标记2019-07-15T13:43:44.166+0800: 4.529: [GC remark 2019-07-15T13:43:44.166+0800: 4.529: [Finalize Marking, 0.0001259 secs] 2019-07-15T13:43:44.166+0800: 4.529: [GC ref-proc, 0.0001492 secs] 2019-07-15T13:43:44.166+0800: 4.529: [Unloading, 0.0067901 secs], 0.0072554 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 2019-07-15T13:43:44.179+0800: 4.542: [GC cleanup 37M->31M(240M), 0.0005559 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] #并发清除2019-07-15T13:43:44.186+0800: 4.549: [GC concurrent-cleanup-start]2019-07-15T13:43:44.186+0800: 4.549: [GC concurrent-cleanup-end, 0.0000283 secs]
当堆占有率达到InitiatingHeapOccupancyPercent，发生一次Mixed GC，默认45%
# jinfo -flag InitiatingHeapOccupancyPercent 11833-XX:InitiatingHeapOccupancyPercent=45
GC日志可以参考下面的地址：
CMS日志格式：
G1日志格式：解释：
DefNew：default new generation
PSYoungGen：Parallel Scavenge generation
ParNew：Parallel New Generation
老年代和永久带同理，名称也是由收集器决定
Minor GC 对年轻代进行回
Major GC 是清理老年代
Full GC 是清理整个堆空间—包括年轻代和老年代