G1日志详解分析 GC基础算法 YGC 日志超详细

最新推荐文章于 2024-01-05 09:26:44 发布

qqrenr

最新推荐文章于 2024-01-05 09:26:44 发布

阅读量171

点赞数

文章标签： jvm java 算法

本文链接：https://blog.csdn.net/qqrenr/article/details/130860506

版权

GC基础算法

YGC 日志

2021-09-13T23:47:13.059+0800: 8306957.465: [GC pause (G1 Evacuation Pause) (young)2021-09-13T23:47:13.068+0800: 8306957.474: [SoftReference, 0
refs, 0.0000453 secs]2021-09-13T23:47:13.068+0800: 8306957.474: [WeakReference, 2 refs, 0.0000063 secs]2021-09-13T23:47:13.068+0800: 8306957.47
4: [FinalReference, 8 refs, 0.0000095 secs]2021-09-13T23:47:13.068+0800: 8306957.474: [PhantomReference, 0 refs, 1 refs, 0.0000286 secs]2021-09
-13T23:47:13.068+0800: 8306957.474: [JNI Weak Reference, 0.0000140 secs], 0.0102679 secs]
   [Parallel Time: 8.0 ms, GC Workers: 16]
      [GC Worker Start (ms): Min: 8306957465.7, Avg: 8306957465.7, Max: 8306957465.8, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.5, Avg: 0.6, Max: 2.0, Diff: 1.6, Sum: 10.1]
      [Update RS (ms): Min: 4.3, Avg: 5.9, Max: 6.2, Diff: 1.9, Sum: 94.4]
         [Processed Buffers: Min: 27, Avg: 31.4, Max: 41, Diff: 14, Sum: 502]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.9]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 1.0, Avg: 1.0, Max: 1.1, Diff: 0.1, Sum: 16.4]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
         [Termination Attempts: Min: 1, Avg: 1.2, Max: 2, Diff: 1, Sum: 20]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.0]
      [GC Worker Total (ms): Min: 7.7, Avg: 7.8, Max: 7.9, Diff: 0.2, Sum: 124.2]
      [GC Worker End (ms): Min: 8306957473.4, Avg: 8306957473.5, Max: 8306957473.5, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.4 ms]
   [Other: 1.9 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.4 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.2 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 1.0 ms]
   [Eden: 2102.0M(2102.0M)->0.0B(2102.0M) Survivors: 8192.0K->8192.0K Heap: 4054.7M(4520.0M)->1953.1M(4520.0M)]
 [Times: user=0.13 sys=0.00, real=0.01 secs]
2021-09-13T23:47:13.070+0800: 8306957.476: Total time for which application threads were stopped: 0.0147420 seconds, Stopping threads took: 0.0
001054 seconds

2021-09-13T23:47:13.059+0800: 8306957.465: [GC pause (G1 Evacuation Pause) (young) .... 0.0102679 secs]。 (G1 Evacuation Pause) (young)标志是YGC，耗时是 10.2ms。2021-09-13T23:47:13.059 是时间，+800是东八区，8306957.465 是JVM启动后的相对时间(秒)。
[Parallel Time: 8.0 ms, GC Workers: 16] 表示并行收集任务，有16 个GC线程，从新生代垃圾收集开始到最后一个任务结束（wall clock time）总共用时 8ms。STW过程。
- [GC Worker Start (ms) Min: 8306957465.7, Avg: 8306957465.7, Max: 8306957465.8, Diff: 0.1]：min指的是第一个垃圾收集线程开始工作时JVM启动后经过的时间，max指的是最后一个，diff表示min和max之间的差值。理想情况下，你希望他们几乎是同时开始，即diff趋近于0。
- [Ext Root Scanning (ms): Min: 0.5, Avg: 0.6, Max: 2.0, Diff: 1.6, Sum: 10.1]: 扫描root集合（线程栈、JNI、全局变量、系统表等等），尝试找到是否有root集合中的节点指向当前的收集集合（CSet）。Sum表示所有线程花费的total cpu time，下同。
- [Update RS (ms): Min: 4.3, Avg: 5.9, Max: 6.2, Diff: 1.9, Sum: 94.4]：处理dirty Card来更新RS，这可以确保当前分区的RSet是最新的。
  - Processed Buffers: Min: 27, Avg: 31.4, Max: 41, Diff: 14, Sum: 502]：更新不能被并行处理的日志缓冲区部分。
- [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.9]: 扫描每个新生代分区的RSet，找出有多少指向当前分区的引用来自CSet。
- [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]: code root指的是经过JIT编译后的代码里，引用了heap中的对象，引用关系保存在RSet中。为了减少扫描时间，这个阶段只扫描CSet中region的Reset来查看是否有被code root引用的关系。
- [Object Copy (ms): Min: 1.0, Avg: 1.0, Max: 1.1, Diff: 0.1, Sum: 16.4]：拷贝CSet集合里面所有分区存活对象到新分区Survivor/Old区。所有存活的对象会被复制到thread-local GC allocated buffers（GCLABS）中，GCLABS在目标region中进行分配。
- [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]：当一个垃圾收集线程完成任务时，它就会进入一个临界区，并尝试偷任务来帮助其他垃圾线程完成任务（steal outstanding tasks）。min表示该垃圾收集线程什么时候尝试terminatie，max表示该垃圾收集回收线程什么时候真正terminated，这个时间是线程之前互相同步所花费的时间。
  - [Termination Attempts: Min: 1, Avg: 1.2, Max: 2, Diff: 1, Sum: 20]：如果一个垃圾收集线程成功盗取了其他线程的任务，那么它会再次盗取更多的任务或再次尝试terminate，每次重新terminate的时候，这个数值就会增加。
- [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.0]：GC线程花费在其他工作上（上面都没计算在内的其他）的时间。
- [GC Worker Total (ms): Min: 7.7, Avg: 7.8, Max: 7.9, Diff: 0.2, Sum: 124.2]：汇总展示每个垃圾收集线程的最小、最大、平均、差值和总共时间。
- [GC Worker End (ms): Min: 8306957473.4, Avg: 8306957473.5, Max: 8306957473.5, Diff: 0.1]：汇总线程结束时间。min表示最早结束的垃圾收集线程结束时该JVM启动后的时间；max表示最晚结束的垃圾收集线程结束时该JVM启动后的时间。理想情况下，最好是同一时间结束。
[Code Root Fixup: 0.0 ms]: 用来将code root修正到正确的回收之后的对象位置所花费的时间。串行执行。
[Code Root Purge: 0.0 ms]：清理code root的数据结构。串行执行。
[Clear CT: 0.4 ms]：清理 Card Table的耗时。
[Other: 1.9 ms]: 其他事项耗时。串行执行。
- [Choose CSet: 0.0 ms]: 选择要进行回收的分区放入CSet。
- [Ref Proc: 0.4 ms]: 处理Java中的各种引用如Soft/Weak/Final/Phantom/JNI等等。
- [Ref Enq: 0.0 ms]: 遍历所有的引用，将不能回收的放入pending队列ReferenceQueues。
- [Redirty Cards: 0.2 ms]: 在回收过程中被修改的Card将会被重置为dirty。
- [Humongous Register: 0.1 ms]: JDK8u60提供了一个特性，巨型对象可以在新生代收集的时候被回收。
- [Humongous Reclaim: 0.0 ms]: 确保巨型对象可以被回收，释放该巨型对象所占的分区，重置分区类型，并将分区还到free-list列表，并且更新空闲空间大小。
- [Free CSet: 1.0 ms]: 释放CSet中的分区到空闲列表free-list。
[Eden: 2102.0M(2102.0M)->0.0B(2102.0M) Survivors: 8192.0K->8192.0K Heap: 4054.7M(4520.0M)->1953.1M(4520.0M)]: （1）表示新生代Eden被回收，使用内存从2102.0M降到0，Eden区回收前后总大小都为2102.0M；（2）Survivors 为年轻代，使用内存为 8192.0K没变化；（3）Heap总堆大小，使用内存从4054.7M降到1953.1M，总大小为 4520.0M。
[Times: user=0.13 sys=0.00, real=0.01 secs]: 整个时间，user是用户态总cpu时间（多线程并行执行算总和），sys是系统内核的总cpu时间，real是wall clock time。

Concurrent Marking Cycle 日志

2021-09-13T18:33:02.188+0800: 8288106.594: [GC pause (G1 Evacuation Pause) (young) (initial-mark)2021-09-13T18:33:02.196+0800: 8288106.602: [SoftReference, 0 refs, 0.0000466 secs]2021-09-13T18:33:02.196+0800: 8288106.602: [WeakReference, 2 refs, 0.0000054 secs]2021-09-13T18:33:02.196+0800: 8288106.602: [FinalReference, 5 refs, 0.0000094 secs]2021-09-13T18:33:02.196+0800: 8288106.602: [PhantomReference, 0 refs, 4 refs, 0.0000052 secs]2021-09-13T18:33:02.196+0800: 8288106.602: [JNI Weak Reference, 0.0000190 secs], 0.0101431 secs]
   [Parallel Time: 7.9 ms, GC Workers: 16]
      [GC Worker Start (ms): Min: 8288106594.2, Avg: 8288106594.2, Max: 8288106594.3, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 1.0, Avg: 1.1, Max: 2.2, Diff: 1.2, Sum: 17.8]
      [Update RS (ms): Min: 3.8, Avg: 5.0, Max: 5.2, Diff: 1.4, Sum: 79.6]
         [Processed Buffers: Min: 24, Avg: 29.3, Max: 36, Diff: 12, Sum: 469]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 2.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 1.3, Avg: 1.4, Max: 1.4, Diff: 0.1, Sum: 22.4]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
         [Termination Attempts: Min: 1, Avg: 1.5, Max: 2, Diff: 1, Sum: 24]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.1]
      [GC Worker Total (ms): Min: 7.6, Avg: 7.7, Max: 7.8, Diff: 0.2, Sum: 123.1]
      [GC Worker End (ms): Min: 8288106601.9, Avg: 8288106601.9, Max: 8288106602.0, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.4 ms]
   [Other: 1.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.8 ms]
   [Eden: 2022.0M(2022.0M)->0.0B(2022.0M) Survivors: 6144.0K->6144.0K Heap: 4057.9M(4520.0M)->2036.0M(4520.0M)]
 [Times: user=0.12 sys=0.00, real=0.01 secs]
2021-09-13T18:33:02.198+0800: 8288106.604: [GC concurrent-root-region-scan-start]
2021-09-13T18:33:02.198+0800: 8288106.604: Total time for which application threads were stopped: 0.0151895 seconds, Stopping threads took: 0.0006094 seconds
2021-09-13T18:33:02.201+0800: 8288106.607: [GC concurrent-root-region-scan-end, 0.0032781 secs]
2021-09-13T18:33:02.201+0800: 8288106.607: [GC concurrent-mark-start]
2021-09-13T18:33:02.325+0800: 8288106.731: [GC concurrent-mark-end, 0.1235144 secs]
2021-09-13T18:33:02.329+0800: 8288106.735: [GC remark 2021-09-13T18:33:02.329+0800: 8288106.735: [Finalize Marking, 0.0002982 secs] 2021-09-13T18:33:02.329+0800: 8288106.735: [GC ref-proc2021-09-13T18:33:02.329+0800: 8288106.735: [SoftReference, 410 refs, 0.0001589 secs]2021-09-13T18:33:02.329+0800: 8288106.735: [WeakReference, 255 refs, 0.0000923 secs]2021-09-13T18:33:02.329+0800: 8288106.735: [FinalReference, 3117 refs, 0.0022884 secs]2021-09-13T18:33:02.332+0800: 8288106.738: [PhantomReference, 0 refs, 2608 refs, 0.0005133 secs]2021-09-13T18:33:02.332+0800: 8288106.738: [JNI Weak Reference, 0.0000646 secs], 0.0032672 secs] 2021-09-13T18:33:02.332+0800: 8288106.738: [Unloading, 0.0156580 secs], 0.0210749 secs]
 [Times: user=0.27 sys=0.00, real=0.02 secs]
2021-09-13T18:33:02.350+0800: 8288106.756: Total time for which application threads were stopped: 0.0250577 seconds, Stopping threads took: 0.0001040 seconds
2021-09-13T18:33:02.354+0800: 8288106.760: [GC cleanup 2068M->2050M(4520M), 0.0018493 secs]
 [Times: user=0.02 sys=0.00, real=0.00 secs]
2021-09-13T18:33:02.356+0800: 8288106.762: Total time for which application threads were stopped: 0.0057045 seconds, Stopping threads took: 0.0000681 seconds
2021-09-13T18:33:02.356+0800: 8288106.762: [GC concurrent-cleanup-start]
2021-09-13T18:33:02.356+0800: 8288106.762: [GC concurrent-cleanup-end, 0.0000579 secs]

[GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0101431 secs]: 注意也有"(G1 Humongous Allocation) (young) (initial-mark)"。初始标记从GC Root可直接到达的对象。是一种新生代垃圾回收过程（与YGC相关），设置了两个TAMS（top-at-mark-start）变量，用来区分存活的对象和在并发标记阶段新分配的对象。在TAMS之前的所有对象，在当前周期内都会被视作存活的。STW。
[GC concurrent-root-region-scan-start]: 在初始标记结束后，新生代收集也完成对象复制到Survivor的工作，应用线程可以工作起来。此时，所有新复制到Survivor分区的对象，都需要被扫描并标记成根，这个过程称为根分区扫描(Root Region Scanning)，同时扫描的Suvivor分区也被称为根分区(Root Region)。只有完成该阶段后，才能开始下一次 STW YGC。
[GC concurrent-root-region-scan-end, 0.0032781 secs]: 根分区扫描结束。
[GC concurrent-mark-start]: 并发标记阶段开始，标记整个堆的存活对象，与用户线程一起并发运行。线程个数一般是 Parallel Thread的1/4，由-XX:ConcGCThreads可配置。可以被 STW YGC中断。使用位图标记所有存活的对象，因为在TAMS之前的对象是隐式存活的，所以这里只需要标记出那些在TAMS之后的。这里采用SATB算法，在垃圾收集开始的时候给堆做一个快照，在垃圾收集过程中这个快照是不变的，但实际上肯定有些对象的引用会发生变化，这时候G1使用了pre-write barrier记录这种变更，并将这个记录存放在一个SATB缓冲区中，并有线程处理。在并发标记过程中，还会记录每个分区的存活对象占整个分区的大小的比率。
[GC concurrent-mark-end, 0.1235144 secs]: 并发标记结束。
[GC remark, 0.0210749 secs]: 重新标记阶段，标记并发阶段变化的对象，绘制出当前并发周期中整个堆的最后面貌，清空剩余的SATB缓冲区，所有存活的对象都会被标记。STW。
- [Finalize Marking, 0.0002982 secs]: Finalizer对象处理。
- [GC ref-proc, 0.0001589 secs]: Soft/Weak/Final/Phantom/JNI引用处理。
- [Unloading, 0.0156580]：卸载类。
[GC cleanup 2068M->2050M(4520M), 0.0018493 secs]: 清理阶段。没有存活对象的老年代分区和巨型对象分区会被释放和清理。处理没有任何存活对象的分区的RSet。所有的老年代分区会按照自己的存活率（存活对象占整个分区大小的比例）进行排序，为后面的CSet选择过程做准备。STW。
[GC concurrent-cleanup-start]: 并发清理阶段。
[GC concurrent-cleanup-end, 0.0000579 secs]: 并发清理结束。

MixedGC 日志

2021-09-13T23:51:25.466+0800: 8307209.871: [GC pause (G1 Evacuation Pause) (mixed)2021-09-13T23:51:25.478+0800: 8307209.884: [SoftReference, 0 refs, 0.0
000320 secs]2021-09-13T23:51:25.478+0800: 8307209.884: [WeakReference, 2 refs, 0.0000051 secs]2021-09-13T23:51:25.478+0800: 8307209.884: [FinalReference
, 0 refs, 0.0000038 secs]2021-09-13T23:51:25.478+0800: 8307209.884: [PhantomReference, 0 refs, 308 refs, 0.0000215 secs]2021-09-13T23:51:25.478+0800: 8307209.884: [JNI Weak Reference, 0.0000144 secs], 0.0135325 secs]
   [Parallel Time: 12.1 ms, GC Workers: 16]
      [GC Worker Start (ms): Min: 8307209871.8, Avg: 8307209871.9, Max: 8307209872.0, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.5, Avg: 0.6, Max: 2.1, Diff: 1.7, Sum: 9.9]
      [Update RS (ms): Min: 4.2, Avg: 5.6, Max: 5.8, Diff: 1.6, Sum: 89.3]
         [Processed Buffers: Min: 24, Avg: 32.9, Max: 41, Diff: 17, Sum: 526]
      [Scan RS (ms): Min: 0.6, Avg: 0.8, Max: 0.9, Diff: 0.3, Sum: 12.5]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 4.9, Avg: 4.9, Max: 4.9, Diff: 0.0, Sum: 78.4]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
         [Termination Attempts: Min: 1, Avg: 3.8, Max: 7, Diff: 6, Sum: 60]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.5]
      [GC Worker Total (ms): Min: 11.9, Avg: 11.9, Max: 12.0, Diff: 0.2, Sum: 190.9]
      [GC Worker End (ms): Min: 8307209883.8, Avg: 8307209883.8, Max: 8307209883.9, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 1.2 ms]
      [Choose CSet: 0.1 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.2 ms]
   [Eden: 216.0M(216.0M)->0.0B(2118.0M) Survivors: 10.0M->10.0M Heap: 2194.9M(4520.0M)->1935.8M(4520.0M)]
 [Times: user=0.20 sys=0.00, real=0.01 secs]

[GC pause (G1 Evacuation Pause) (mixed), 0.0135325 secs]: mixed表示是混合垃圾收集周期。在混合垃圾收集处理的CSet不仅包括新生代的分区，还包括老年代分区（也就是并发标记阶段标记出来的那些老年代分区）。执行流程与YGC类似。

FullGC 日志

2021-09-14T01:40:39.396+0800: 8313763.802: [Full GC (Allocation Failure) 2021-09-14T01:40:39.612+0800: 8313764.018: [SoftReference, 234 refs, 0.0000716
secs]2021-09-14T01:40:39.612+0800: 8313764.018: [WeakReference, 442 refs, 0.0000489 secs]2021-09-14T01:40:39.612+0800: 8313764.018: [FinalReference, 33
refs, 0.0000065 secs]2021-09-14T01:40:39.612+0800: 8313764.018: [PhantomReference, 0 refs, 14881 refs, 0.0006235 secs]2021-09-14T01:40:39.612+0800: 8313
764.018: [JNI Weak Reference, 0.0000303 secs] 4156M->2233M(4520M), 1.2621015 secs]
   [Eden: 0.0B(226.0M)->0.0B(226.0M) Survivors: 0.0B->0.0B Heap: 4156.3M(4520.0M)->2234.0M(4520.0M)], [Metaspace: 45276K->45244K(1097728K)]
 [Times: user=1.54 sys=0.00, real=1.26 secs]
2021-09-14T01:40:40.658+0800: 8313765.064: Total time for which application threads were stopped: 1.2652421 seconds, Stopping threads took: 0.0000462 se
conds

[Full GC (Allocation Failure) 4156M->2233M(4520M), 1.2621015 secs]: 堆空间不足，Full GC是单线程，STW，代价非常高。
- [Eden: 0.0B(226.0M)->0.0B(226.0M) Survivors: 0.0B->0.0B Heap: 4156.3M(4520.0M)->2234.0M(4520.0M)], [Metaspace: 45276K->45244K(1097728K)].