关于GC日志查看分析指南

截至JDK1.8 的一些垃圾收集器日志查看指南

CMS日志分析

CMS垃圾收集器分为5个阶段
1. 初始化标记 CMS Initial  Mark  （CMS的第一个STW阶段）
2. 并发标记阶段  concurrent-mark
3. 并发预清理阶段 concurrent-preclean
4. 并发可 中止的预清理阶段 concurrent-abortable-preclean
5.  重标记阶段 remark
6.并发清理 concurrent-sweep

Java HotSpot(TM) 64-Bit Server VM (25.161-b12) for windows-amd64 JRE (1.8.0_161-b12), built on Dec 19 2017 17:52:25 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16614588k(3548420k free), swap 38634684k(17499396k free)

CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:InitialHeapSize=265833408 -XX:+ManagementServer -XX:MaxHeapSize=4253334528 -XX:MaxNewSize=697933824 -XX:MaxTenuringThreshold=6 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC
1.448: [GC (Allocation Failure) 1.448: [ParNew: 69376K->5935K(78016K), 0.0035144 secs] 69376K->5935K(251456K), 0.0147394 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
3.338: [GC (Allocation Failure) 3.338: [ParNew: 75311K->5178K(78016K), 0.0138579 secs] 75311K->8677K(251456K), 0.0139528 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
3.496: [GC (Allocation Failure) 3.496: [ParNew: 74554K->5595K(78016K), 0.0022748 secs] 78053K->9094K(251456K), 0.0023622 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
3.651: [GC (Allocation Failure) 3.651: [ParNew: 74971K->6382K(78016K), 0.0044028 secs] 78470K->11342K(251456K), 0.0045022 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
ParNew：年轻代收集器69376K> 5935K 收集前后对比 78016K 整个年轻代的容量
69376K>5935K 整个堆的清空  251456K 整个堆大小
3.656: [GC (CMS Initial Mark) [1 CMS-initial-mark: 4960K(173440K)] 12861K(251456K), 0.0006111 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
//阶段1 初始化标记
//4960K (173440K) : 老年代使用（最大）
//12861K (251456K) : 整个堆使用（最大）
3.656: [CMS-concurrent-mark-start]
//阶段2 并发标记阶段
3.661: [CMS-concurrent-mark: 0.005/0.005 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
3.661: [CMS-concurrent-preclean-start]
//阶段3  CMS-concurrent-preclean 并发预清理阶段 减少下一个STW 阶段的工作量
3.662: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
3.662: [CMS-concurrent-abortable-preclean-start]
//阶段4 并发可中止的预清理阶段 减少下一个STW 阶段的工作量
3.774: [CMS-concurrent-abortable-preclean: 0.057/0.112 secs] [Times: user=0.22 sys=0.02, real=0.11 secs]
3.774: [GC (CMS Final Remark) [YG occupancy: 45734 K (45734 K)]3.774: [Rescan (parallel) , 0.0027136 secs]3.776: [weak refs processing, 0.0000327 secs]3.777: [class unloading, 0.0017875 secs]3.778: [scrub symbol table, 0.0020953 secs]3.780: [scrub string table, 0.0002717 secs][1 CMS-remark: 4960K(173440K)] 50695K(251456K), 0.0072918 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
//阶段5 CMS中第二个并且是最后一个STW的阶段 该阶段的任务是完成标记整个年老代的所有的存活对象。由于之前的预处理是并发的，它可能跟不上应用程序改变的速度，这个时候，STW是非常需要的来完成这个严酷考验的阶段。
//STW(stop the world)阶段，YG occupancy:年轻代占用及容量  45734K  45734K
//[Rescan (parallel)：STW下的存活对象标记
//weak refs processing: 弱引用处理
//class unloading: 卸载用不到的class
//scrub symbol(string) table:
//cleaning up symbol and string tables which hold class-level metadata and
//internalized string respectively
//CMS-remark: 8511K(13696K): 4960K  (173440K)
// 50695K(251456K): 阶段过后的堆占用及容量
3.781: [CMS-concurrent-sweep-start]
//阶段6 并发清理concurrent-sweep
3.783: [CMS-concurrent-sweep: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
3.783: [CMS-concurrent-reset-start]  //重置内部结构，为下次GC做准备
3.796: [CMS-concurrent-reset: 0.013/0.013 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

G1日志分析

1. 

>> 新生代收集<<
Java HotSpot(TM) 64-Bit Server VM (25.161-b12) for windows-amd64 JRE (1.8.0_161-b12), built on Dec 19 2017 17:52:25 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16614588k(3822092k free), swap 38634684k(15872368k free)
CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:InitialHeapSize=265833408 -XX:+ManagementServer -XX:MaxHeapSize=4253334528 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation


1.057: [GC pause (G1 Evacuation Pause) (young), 0.0036391 secs] //程序运行1.057ms之后 发生的一次Evacuation Pause 耗时为3.36391毫秒
   [Parallel Time: 2.3 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 1057.3, Avg: 1057.3, Max: 1057.4, Diff: 0.1]//GC worker线程的启动耗时 平均时间 最大 最小 差异
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.8, Diff: 0.8, Sum: 2.0]//每个扫描root的线程耗时  最小 平均 最大 差异 总耗时
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]//每个执行更新RS（Remembered Sets）的线程的 耗时 最小 平均 最大 差异 总耗时
         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]//每一个线程处理的Update Buffers的数量
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]//扫描每个CSet中Region的RSet的耗时
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.4]//扫描代码中root节点(局部变量的耗时)
      [Object Copy (ms): Min: 0.0, Avg: 1.6, Max: 1.9, Diff: 1.9, Sum: 12.7]//在疏散暂停期间，所有CSet中的分区必须被转移疏散，Object copy 负责将当前分区的存货对象拷贝到新的分区 此处表示所耗时间
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]//每个工作线程执行完成任务的耗时
         [Termination Attempts: Min: 1, Avg: 19.1, Max: 38, Diff: 37, Sum: 153]//每个工作线程执行的次数 最小 平均 最大 差异次数 总次数
      [GC Worker Other (ms): Min: 0.0, Avg: 0.3, Max: 2.2, Diff: 2.2, Sum: 2.4] //垃圾收集器线程在完成其他任务的时间 分析
      [GC Worker Total (ms): Min: 2.2, Avg: 2.3, Max: 2.3, Diff: 0.1, Sum: 18.0]//每个垃圾收集器线程的最小，最大，平均，差异和总共的时间花费
      [GC Worker End (ms): Min: 1059.6, Avg: 1059.6, Max: 1059.6, Diff: 0.0]//min表示最早结束的垃圾收集线程结束时该JVM启动后的时间；max表示最晚结束的垃圾收集线程结束时该JVM启动后的时间
      //新生代的GC任务
   [Code Root Fixup: 0.0 ms]//释放用于管理并行垃圾收集活动的数据结构，应该接近于0，该步骤是线性执行的；
   [Code Root Purge: 0.0 ms]//清理更多的数据结构，应该很快，耗时接近于0，也是线性执行。
   [Clear CT: 0.1 ms]//清理card table
   //扩展功能
   [Other: 1.2 ms]
      [Choose CSet: 0.0 ms] //选择要进行回收的分区放入CSet（G1选择的标准是垃圾最多的分区优先，也就是存活对象率最低的分区优先）
      [Ref Proc: 0.9 ms]//处理Java中的各种引用——soft、weak、final、phantom、JNI等等。
      [Ref Enq: 0.0 ms]//遍历所有的引用，将不能回收的放入pending列表
      [Redirty Cards: 0.1 ms]//在回收过程中被修改的card将会被重置为dirty
      [Humongous Register: 0.0 ms]//JDK8u60提供了一个特性，巨型对象可以在新生代收集的时候被回收——通过G1ReclaimDeadHumongousObjectsAtYoungGC设置，默认为true。
      [Humongous Reclaim: 0.0 ms]//做下列任务的时间：确保巨型对象可以被回收、释放该巨型对象所占的分区，重置分区类型，并将分区还到free列表，并且更新空闲空间大小。
      [Free CSet: 0.0 ms]//将要释放的分区还回到free列表
   [Eden: 24.0M(24.0M)->0.0B(31.0M) Survivors: 0.0B->3072.0K Heap: 24.6M(254.0M)->3920.0K(254.0M)]
   //Eden 当前新生代分配的空间大小为使用了24.0M分配了(24.0M) 所有的Eden分区被疏散出来了，在新生代结束后，Eden分区的使用变成了0.0B Eden分区的大小扩大至31.0M
   //Survivors 年轻代的回收 survivor的空间从0.0B 涨到了3072.0K
   //Heap 本次垃圾回收的时候 堆空间的使用量为24.6MB 最大使用量为254.0M  回收之后变成3920.0K 堆最大空间变更为254.0M
 [Times: user=0.00 sys=0.00, real=0.00 secs]
 //user 垃圾收集器在新生代垃圾收集当中小号的cpu时间。
 //sys 内核线程消耗的CPU时间
 //-real 本次垃圾收集真正消耗的时间