G1 young gc日志分析

最新推荐文章于 2024-06-11 10:40:50 发布

热心网友summer

最新推荐文章于 2024-06-11 10:40:50 发布

阅读量357

点赞数 1

分类专栏： java 高性能文章标签： java 性能优化后端

本文链接：https://blog.csdn.net/weixin_41550544/article/details/125097348

版权

java 同时被 2 个专栏收录

6 篇文章 0 订阅

订阅专栏

高性能

1 篇文章 0 订阅

订阅专栏

日志概览

//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