JVM G1收集器日志分析

最新推荐文章于 2024-08-09 19:03:45 发布

远处的海亲吻着天

最新推荐文章于 2024-08-09 19:03:45 发布

阅读量533

点赞数

分类专栏： JVM

本文链接：https://blog.youkuaiyun.com/lm324114/article/details/105001686

版权

JVM 专栏收录该内容

11 篇文章

订阅专栏

本文分析了G1垃圾收集器的日志，重点关注Humongous对象分配、年轻代GC过程以及并发标记阶段。日志显示了Young GC的详细步骤，包括根节点扫描、更新RSet、对象复制等，揭示了JVM内存管理的内部运作。

摘要生成于 C知道，由 DeepSeek-R1 满血版支持，前往体验 >

package com.jvm.g1;

/**
 * -verbose:gc
 * -Xms10M
 * -Xmx10M
 * -XX:+UseG1GC
 * -XX:+PrintGCDetails
 * -XX:+PrintGCDateStamps
 * -XX:MaxGCPauseMillis=200m
 *
 */
public class MyTest {


    public static void main(String[] args) {
        int size = 1024 * 1024;

        byte[] myAlloc1 = new byte[ size];
        byte[] myAlloc2 = new byte[ size];
        byte[] myAlloc3 = new byte[ size];
        byte[] myAlloc4 = new byte[ size];

        System.out.println("MyTest.main");
    }
}

我们来看G1 Humongous 由于分配的数组代大小是1M大于了region的50%，因此被分配到Humongous里
(young) (initial-mark), 0.0017556 secs 进行了young gc 初始标记花费了0.0017556 secs
[Parallel Time: 1.3 ms, GC Workers: 8] GC汇总的信息，并行的时间1.3 ms，有8个gc线程同时执行
Ext Root Scanning (ms) 进行根节点扫描
Update RS 更新RSet 集合，记录那些的region 对象引用当前region的对象的集合
Processed Buffers: 记录引用变化的缓存空间
Scan RS 扫描RSet 集合所花费的时间
Object Copy 对象复制，将存活的从一个region中复制到另外一个region中；将之前的region 清空掉。
Termination ：gc线程在终至前回检查其他线程还有没有要清理的数据
GC Worker Other (ms)、GC Worker Total (ms)、GC Worker End (ms)：记录gc 统计的信息
[Clear CT: 0.1 ms] CT就是card table
[Eden: 2048.0K(6144.0K)->0.0B(2048.0K) Survivors: 0.0B->1024.0K Heap: 3581.1K(10.0M)->2584.1K(10.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs] 表示执行完young gc 之后的结果；Eden经过yong gc 之后一定是空的这里就验证之前所描述的，Survivors 从0 变成1024k ,说明有一个对象进入Survivors空间。总的堆从3581.1K(10.0M)->2584.1K(10.0M)；因为jvm 中不单单有我们生成的对象占用内存，还有其他对象。
[GC concurrent-root-region-scan-start]
[GC concurrent-root-region-scan-end, 0.0005063 secs] 全局并发标记的扫描
[GC concurrent-mark-start]
[GC concurrent-mark-end, 0.0001488 secs] 全局并发标记

/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/bin/java -verbose:gc -Xms10M -Xmx10M -XX:+UseG1GC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:MaxGCPauseMillis=200m "-javaagent:/Applications/IntelliJ IDEA.app/Contents/lib/idea_rt.jar=54417:/Applications/IntelliJ IDEA.app/Contents/bin" -Dfile.encoding=UTF-8 -classpath /Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/charsets.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/deploy.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/ext/cldrdata.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/ext/dnsns.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/ext/jaccess.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/ext/jfxrt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/ext/localedata.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/ext/nashorn.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/ext/sunec.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/ext/sunjce_provider.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/ext/sunpkcs11.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/ext/zipfs.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/javaws.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/jce.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/jfr.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/jfxswt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/jsse.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/management-agent.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/plugin.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/resources.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/jre/lib/rt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/lib/ant-javafx.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/lib/dt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/lib/javafx-mx.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/lib/jconsole.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/lib/packager.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/lib/sa-jdi.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_231.jdk/Contents/Home/lib/tools.jar:/Users/liming/jvm/target/classes:/Users/liming/repository/cglib/cglib/3.3.0/cglib-3.3.0.jar:/Users/liming/repository/org/ow2/asm/asm/7.1/asm-7.1.jar com.jvm.g1.MyTest
2020-03-20T23:03:21.777-0800: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0017556 secs]
   [Parallel Time: 1.3 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 108.7, Avg: 108.8, Max: 109.0, Diff: 0.3]
      [Ext Root Scanning (ms): Min: 0.3, Avg: 0.5, Max: 0.7, Diff: 0.4, Sum: 4.0]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
      [Object Copy (ms): Min: 0.4, Avg: 0.5, Max: 0.6, Diff: 0.3, Sum: 3.8]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.7]
         [Termination Attempts: Min: 4, Avg: 5.6, Max: 7, Diff: 3, Sum: 45]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 0.9, Avg: 1.1, Max: 1.2, Diff: 0.3, Sum: 8.8]
      [GC Worker End (ms): Min: 109.9, Avg: 109.9, Max: 109.9, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.4 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.0 ms]
   [Eden: 2048.0K(6144.0K)->0.0B(2048.0K) Survivors: 0.0B->1024.0K Heap: 3581.1K(10.0M)->2584.1K(10.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2020-03-20T23:03:21.779-0800: [GC concurrent-root-region-scan-start]
2020-03-20T23:03:21.780-0800: [GC concurrent-root-region-scan-end, 0.0005063 secs]
2020-03-20T23:03:21.780-0800: [GC concurrent-mark-start]
2020-03-20T23:03:21.780-0800: [GC concurrent-mark-end, 0.0001488 secs]
2020-03-20T23:03:21.780-0800: [GC remark 2020-03-20T23:03:21.780-0800: [Finalize Marking, 0.0002135 secs] 2020-03-20T23:03:21.780-0800: [GC ref-proc, 0.0000556 secs] 2020-03-20T23:03:21.780-0800: [Unloading, 0.0006755 secs], 0.0010836 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2020-03-20T23:03:21.781-0800: [GC pause (G1 Humongous Allocation) (young), 0.0014894 secs]
   [Parallel Time: 0.8 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 112.6, Avg: 112.9, Max: 113.3, Diff: 0.7]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 1.0]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 1.3]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.7]
         [Termination Attempts: Min: 1, Avg: 1.5, Max: 4, Diff: 3, Sum: 12]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 0.0, Avg: 0.4, Max: 0.7, Diff: 0.7, Sum: 3.1]
      [GC Worker End (ms): Min: 113.3, Avg: 113.3, Max: 113.3, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 0.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 1024.0K(2048.0K)->0.0B(1024.0K) Survivors: 1024.0K->1024.0K Heap: 3649.1K(10.0M)->3545.0K(10.0M)]
 [Times: user=0.01 sys=0.00, real=0.00 secs] 
2020-03-20T23:03:21.783-0800: [GC cleanup 4589K->4589K(10M), 0.0007612 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
MyTest.main
Heap
 garbage-first heap   total 10240K, used 4568K [0x00000007bf600000, 0x00000007bf700050, 0x00000007c0000000)
  region size 1024K, 2 young (2048K), 1 survivors (1024K)
 Metaspace       used 3095K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 339K, capacity 388K, committed 512K, reserved 1048576K

Process finished with exit code 0