- 日志概览
//before
{Heap before GC invocations=36693 (full 0):
garbage-first heap total 4194304K, used 3061575K [0x00000006c0000000, 0x00000006c0204000, 0x00000007c0000000)
region size 2048K, 1228 young (2514944K), 31 survivors (63488K)
Metaspace used 96786K, capacity 99600K, committed 100696K, reserved 1138688K
class space used 11134K, capacity 11696K, committed 11904K, reserved 1048576K
//detail
2022-05-27T13:08:44.150+0800: 1808745.052: [GC pause (G1 Evacuation Pause) (young)2022-05-27T13:08:44.184+0800: 1808745.086: [SoftReference, 0 refs, 0.0000651 secs]2022-05-27T13:08:44.184+08
00: 1808745.086: [WeakReference, 1 refs, 0.0000153 secs]2022-05-27T13:08:44.184+0800: 1808745.086: [FinalReference, 3892 refs, 0.0049231 secs]2022-05-27T13:08:44.189+0800: 1808745.091: [Phan
tomReference, 2 refs, 0 refs, 0.0000273 secs]2022-05-27T13:08:44.189+0800: 1808745.091: [JNI Weak Reference, 0.0000316 secs], 0.0433542 secs]
[Parallel Time: 22.9 ms, GC Workers: 18]
[GC Worker Start (ms): Min: 1808745053.9, Avg: 1808745054.2, Max: 1808745054.6, Diff: 0.7]
[Ext Root Scanning (ms): Min: 2.5, Avg: 8.3, Max: 13.5, Diff: 10.9, Sum: 148.6]
[Update RS (ms): Min: 0.0, Avg: 0.8, Max: 2.8, Diff: 2.8, Sum: 14.4]
[Processed Buffers: Min: 0, Avg: 24.6, Max: 96, Diff: 96, Sum: 442]
[Scan RS (ms): Min: 0.1, Avg: 0.7, Max: 8.5, Diff: 8.5, Sum: 12.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 1.7, Avg: 6.9, Max: 16.3, Diff: 14.6, Sum: 123.7]
[Termination (ms): Min: 0.0, Avg: 5.6, Max: 6.7, Diff: 6.7, Sum: 100.6]
[Termination Attempts: Min: 1, Avg: 1.1, Max: 2, Diff: 1, Sum: 20]
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 1.9]
[GC Worker Total (ms): Min: 21.8, Avg: 22.3, Max: 22.6, Diff: 0.8, Sum: 401.4]
[GC Worker End (ms): Min: 1808745076.4, Avg: 1808745076.5, Max: 1808745076.6, Diff: 0.2]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.6 ms]
[Other: 19.8 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 13.8 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 1.2 ms]
[Humongous Register: 1.0 ms]
[Humongous Reclaim: 0.1 ms]
[Free CSet: 2.1 ms]
[Eden: 2394.0M(2394.0M)->0.0B(2394.0M) Survivors: 62.0M->62.0M Heap: 2989.8M(4096.0M)->594.8M(4096.0M)]
// after
Heap after GC invocations=36694 (full 0):
garbage-first heap total 4194304K, used 609046K [0x00000006c0000000, 0x00000006c0204000, 0x00000007c0000000)
region size 2048K, 31 young (63488K), 31 survivors (63488K)
Metaspace used 96786K, capacity 99600K, committed 100696K, reserved 1138688K
class space used 11134K, capacity 11696K, committed 11904K, reserved 1048576K
}
[Times: user=0.16 sys=0.07, real=0.04 secs]
可以分为三段,before, detail, after三段
- 详细分析
- 第一部分(before)
//回收次数
{Heap before GC invocations=36693 (full 0):
//堆内存使用情况
//0x00000006c0000000: 堆保留内存低地址边界, 0x00000006c0204000: commited内存的高地址边界, 0x00000007c0000000: 堆保留内存高地址边界
garbage-first heap total 4194304K, used 3061575K [0x00000006c0000000, 0x00000006c0204000, 0x00000007c0000000)
//每个region2M,一共1228的young region (占用了2514944K空间),其中31个是survivors(占用了63488K空间)。在统计
的时候,把survivors的region也算到了前面的数值里。
region size 2048K, 1228 young (2514944K), 31 survivors (63488K)
//元数据空间使用情况
Metaspace used 96786K, capacity 99600K, committed 100696K, reserved 1138688K
class space used 11134K, capacity 11696K, committed 11904K, reserved 1048576K
- 执行的详细信息(detail)
//gc的类型(young)
//(G1 Evacuation Pause) 指的是产生本次gc的原因。常见的还有 (G1 Humongous Allocation)
2022-05-27T13:08:44.150+0800: 1808745.052: [GC pause (G1 Evacuation Pause) (young)2022-05-27T13:08:44.184+0800: 1808745.086: [SoftReference, 0 refs, 0.0000651 secs]2022-05-27T13:08:44.184+08
00: 1808745.086: [WeakReference, 1 refs, 0.0000153 secs]2022-05-27T13:08:44.184+0800: 1808745.086: [FinalReference, 3892 refs, 0.0049231 secs]2022-05-27T13:08:44.189+0800: 1808745.091: [Phan
tomReference, 2 refs, 0 refs, 0.0000273 secs]2022-05-27T13:08:44.189+0800: 1808745.091: [JNI Weak Reference, 0.0000316 secs], 0.0433542 secs]
//并行执行的部分
[Parallel Time: 22.9 ms, GC Workers: 18]
//回收线程的启动时间
[GC Worker Start (ms): Min: 1808745053.9, Avg: 1808745054.2, Max: 1808745054.6, Diff: 0.7]
//外部根扫描(堆外扫描):外部根包括(JVM系统目录、VM数据结构、JNI线程句柄、硬件寄存器、全局变量、线程堆栈根)
[Ext Root Scanning (ms): Min: 2.5, Avg: 8.3, Max: 13.5, Diff: 10.9, Sum: 148.6]
//更新RSet:每个region都维护一个Rset,在有外部region引用本region内对象时,会记录外部region的card table索引。
[Update RS (ms): Min: 0.0, Avg: 0.8, Max: 2.8, Diff: 2.8, Sum: 14.4]
//已处理的缓冲:指的就是队列中那部分还没被消费完的变更记录。
[Processed Buffers: Min: 0, Avg: 24.6, Max: 96, Diff: 96, Sum: 442]
//扫描所有region的RSet,来确定自己内部的存活对象。
[Scan RS (ms): Min: 0.1, Avg: 0.7, Max: 8.5, Diff: 8.5, Sum: 12.1]
//代码根扫描:扫描的是被JIT即时编译器编译后的代码对堆的region内部对象的引用情况。
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
//对象迁移:这一步就是将存活对象迁移到新的region和survivor,也有一部分会晋升到老年代region。回收老的region。
[Object Copy (ms): Min: 1.7, Avg: 6.9, Max: 16.3, Diff: 14.6, Sum: 123.7]
//GC终止耗时:工作线程终止
[Termination (ms): Min: 0.0, Avg: 5.6, Max: 6.7, Diff: 6.7, Sum: 100.6]
[Termination Attempts: Min: 1, Avg: 1.1, Max: 2, Diff: 1, Sum: 20]
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 1.9]
[GC Worker Total (ms): Min: 21.8, Avg: 22.3, Max: 22.6, Diff: 0.8, Sum: 401.4]
[GC Worker End (ms): Min: 1808745076.4, Avg: 1808745076.5, Max: 1808745076.6, Diff: 0.2]
//串行执行的部分
//代码根修正:代码根所引用的存活对象,从一个region迁移到了另外的region,那么就需要更新他对这个对象的引用地址
[Code Root Fixup: 0.0 ms]
//代码根清理:清理代码根中不再被使用的代码
[Code Root Purge: 0.0 ms]
//清理card table:清理全局卡表中的已扫描标志
[Clear CT: 0.6 ms]
[Other: 19.8 ms]
//选择要回收的集合(只有在混合回收时,这一步才有意义,需要基于停顿时间的考量,利用启发性算法重新界定需要回收哪些region。单纯的young gc,就是所有年轻代region)
[Choose CSet: 0.0 ms]
//引用处理:针对软引用(内存不足才回收)、弱引用(发生gc就可回收)、虚引用、final引用、JNI引用
[Ref Proc: 13.8 ms]
//可以被回收的引用入队。
[Ref Enq: 0.0 ms]
//上一步的引用处理,会更新RSet信息,所以也需要同步标记全局开标中对应的card table为脏卡片
[Redirty Cards: 1.2 ms]
//巨型对象注册(统计):虽然巨型对象是存储在老年代分区的,但是G1内部也做了特殊优化手段,在young gc是也会顺带回收一些巨型对象分区。在young gc时,会基于region的RSet确定外部对自己的引用。
[Humongous Register: 1.0 ms]
//回收H-Region的耗时
[Humongous Reclaim: 0.1 ms]
//回收CSet中region的空间,并将这些region重新置为空闲。
[Free CSet: 2.1 ms]
[Eden: 2394.0M(2394.0M)->0.0B(2394.0M) Survivors: 62.0M->62.0M Heap: 2989.8M(4096.0M)->594.8M(4096.0M)]```
3. gc结束之后堆和元数据信息(after)
```powershell
Heap after GC invocations=36694 (full 0):
garbage-first heap total 4194304K, used 609046K [0x00000006c0000000, 0x00000006c0204000, 0x00000007c0000000)
region size 2048K, 31 young (63488K), 31 survivors (63488K)
Metaspace used 96786K, capacity 99600K, committed 100696K, reserved 1138688K
class space used 11134K, capacity 11696K, committed 11904K, reserved 1048576K
}```
同before