1. 程序员快看-教程，程序员编程资料站
  2. 首页
  3. JVM实战（1）
  4. 正文

31、JVM实战：日志参数

分类：JVM实战（1）    2024-03-08    阅读(189)

24.2–日志参数

1、前提

1.1、代码

/**
 * @ClassName: Test01
 * @Description JVM 日志参数测试
 * @Author feizhou
 * @Date 2022/11/14  10:23
 * @Verson 1.0
 **/
public class Test01 {
    private static final int _1MB = 1024 * 1024;

 
    public static void main(String[] args) {

        byte[] allocation1, allocation2, allocation3;

        //256KB 什么时候进入老年代决定于XX:MaxTenuringThreshold设置
        allocation1 = new byte[_1MB / 4];

        allocation2 = new byte[4 * _1MB];//4048KB
        allocation3 = new byte[4 * _1MB];    //4048KB eden共占用了 8352KB
        allocation3 = null; //断开引用，成为垃圾对象

        //再申请分配4MB内存，放不下，触发Minor GC
        allocation3 = new byte[4 * _1MB];
    }
}

1.2、JVM 调试参数

-verbose:gc //打开GC的跟踪日志
-Xms20M  //最小堆内存
-Xmx20M  //最大堆内存
-Xmn10M  //年轻代内存
-XX:SurvivorRatio=8   //eden和from,to 比例为8:1:1
-XX:MaxTenuringThreshold=1 //最大分代年龄为1
-XX:+UseSerialGC  //收集器

2、测试

2.1、-XX:+PrintGC

可以打印GC的简要信息

JVM 参数

-verbose:gc
-Xms20M
-Xmx20M
-Xmn10M
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=1
-XX:+UseSerialGC

-XX:+PrintGC

日志

[GC (Allocation Failure)  6947K->5187K(19456K), 0.0025358 secs]
[GC (Allocation Failure)  9366K->5148K(19456K), 0.0006661 secs]

1、 GC(AllocationFailure)：GC类型；

1、 GC:minor；
2、 GC(younggc)；
3、 FullGC；
4、 majorGC；
2、 6947K：是GC前堆内存使用量；
3、 5187K：是GC后堆内存使用量；
4、 19456K：是堆内存总量；
5、 0.0025358secs：是本次GC耗时；

2.2、-XX:+PrintGCDetails

打印GC的详细信息

JVM 参数

-verbose:gc
-Xms20M
-Xmx20M
-Xmn10M
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=1
-XX:+UseSerialGC

-XX:+PrintGCDetails

日志

[GC (Allocation Failure) [DefNew: 7111K->1023K(9216K), 0.0019243 secs] 7111K->5194K(19456K), 0.0019527 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC (Allocation Failure) [DefNew: 5203K->0K(9216K), 0.0006750 secs] 9374K->5162K(19456K), 0.0006878 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 def new generation   total 9216K, used 4242K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,  51% used [0x00000000fec00000, 0x00000000ff024888, 0x00000000ff400000)
  from space 1024K,   0% used [0x00000000ff400000, 0x00000000ff4000e8, 0x00000000ff500000)
  to   space 1024K,   0% used [0x00000000ff500000, 0x00000000ff500000, 0x00000000ff600000)
 tenured generation   total 10240K, used 5162K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
   the space 10240K,  50% used [0x00000000ff600000, 0x00000000ffb0a828, 0x00000000ffb0aa00, 0x0000000100000000)
 Metaspace       used 3482K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 380K, capacity 388K, committed 512K, reserved 1048576K

2.3、-XX:+PrintGCTimeStamps

1、 GC时，打印进程启动到现在经历的时间；
2、 可与以下参数混合使用；

1、 -XX:+PrintGC(我使用的)；
2、 -XX:+PrintGCDetails；

JVM 参数

-verbose:gc
-Xms20M
-Xmx20M
-Xmn10M
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=1
-XX:+UseSerialGC

-XX:+PrintGC
-XX:+PrintGCTimeStamps

日志

0.074: [GC (Allocation Failure) 0.074: [DefNew: 6947K->1024K(9216K), 0.0020946 secs] 6947K->5192K(19456K), 0.0021204 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

0.076: [GC (Allocation Failure) 0.076: [DefNew: 5203K->0K(9216K), 0.0008615 secs] 9372K->5171K(19456K), 0.0008747 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

表示进程启动到现在经历的时间

GC时，打印进程启动到现在经历的时间是：0.074
GC时，打印进程启动到现在经历的时间是：0.076

2.4、-XX:+PrintTenuringDistribution

打印出对象的年龄分布，让开发者知道在自己的系统中对象晋升到老年代到底经过了几次GC，然后就可以根据年龄情况调整-XX:MaxTenuringThreshold参数或者调整其他参数让对象晋升到老年代的年龄阈值尽量达到开发者自己设置的理想阈值

JVM 参数

-verbose:gc
-Xms20M
-Xmx20M
-Xmn10M
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=1
-XX:+UseSerialGC

-XX:+PrintGC
-XX:+PrintTenuringDistribution

日志

[GC (Allocation Failure) 
Desired survivor size 524288 bytes, new threshold 1 (max 1)
- age   1:    1048568 bytes,    1048568 total
 6947K->5191K(19456K), 0.0024241 secs]
[GC (Allocation Failure) 
Desired survivor size 524288 bytes, new threshold 1 (max 1)
- age   1:        800 bytes,        800 total
 9371K->5156K(19456K), 0.0007482 secs]

1、 newthreshold1：即标识新的存活周期的阈值为1；

2.5、-XX:+PrintGCApplicationStoppedTime

1、 打印GC时，应用停顿时间；
2、 可与以下参数混合使用；

1、 -XX:+PrintGC(我使用的)；
2、 -XX:+PrintGCDetails；

JVM 参数

-verbose:gc
-Xms20M
-Xmx20M
-Xmn10M
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=1
-XX:+UseSerialGC

-XX:+PrintGC
-XX:+PrintGCApplicationStoppedTime

日志

[GC (Allocation Failure)  6947K->5193K(19456K), 0.0020556 secs]
Total time for which application threads were stopped: 0.0021627 seconds, Stopping threads took: 0.0000338 seconds

[GC (Allocation Failure)  9537K->5159K(19456K), 0.0006417 secs]
Total time for which application threads were stopped: 0.0007482 seconds, Stopping threads took: 0.0000635 seconds

打印GC时，应用停顿时间是 0.0000338 seconds
打印GC时，应用停顿时间是 0.0000635 seconds

2.6、-XX:+PrintGCApplicationConcurrentTime

1、 GC时，打印应用执行时间；
2、 可与以下参数混合使用；

1、 -XX:+PrintGC(我使用的)；
2、 -XX:+PrintGCDetails；

JVM 参数

-verbose:gc
-Xms20M
-Xmx20M
-Xmn10M
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=1
-XX:+UseSerialGC

-XX:+PrintGC
-XX:+PrintGCApplicationConcurrentTime

日志

Application time: 0.0021807 seconds
[GC (Allocation Failure)  6947K->5192K(19456K), 0.0020423 secs]
Application time: 0.0002188 seconds

[GC (Allocation Failure)  9372K->5165K(19456K), 0.0007476 secs]
Application time: 0.0002772 seconds

GC时，打印应用执行时间是：0.0002188 seconds
GC时，打印应用执行时间是：0.0002772 seconds

2.7、-XX:+PrintHeapAtGC

每次一次GC之后，打印GC前后的详细堆栈信息

JVM 参数

-verbose:gc
-Xms20M
-Xmx20M
-Xmn10M
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=1
-XX:+UseSerialGC

-XX:+PrintGC
-XX:+PrintHeapAtGC

日志

{Heap before GC invocations=0 (full 0):
 def new generation   total 9216K, used 7111K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,  86% used [0x00000000fec00000, 0x00000000ff2f1de0, 0x00000000ff400000)
  from space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
  to   space 1024K,   0% used [0x00000000ff500000, 0x00000000ff500000, 0x00000000ff600000)
 tenured generation   total 10240K, used 0K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
   the space 10240K,   0% used [0x00000000ff600000, 0x00000000ff600000, 0x00000000ff600200, 0x0000000100000000)
 Metaspace       used 3462K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 377K, capacity 388K, committed 512K, reserved 1048576K
[GC (Allocation Failure)  7111K->5194K(19456K), 0.0024106 secs]
Heap after GC invocations=1 (full 0):
 def new generation   total 9216K, used 1024K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,   0% used [0x00000000fec00000, 0x00000000fec00000, 0x00000000ff400000)
  from space 1024K, 100% used [0x00000000ff500000, 0x00000000ff600000, 0x00000000ff600000)
  to   space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
 tenured generation   total 10240K, used 4170K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
   the space 10240K,  40% used [0x00000000ff600000, 0x00000000ffa12b50, 0x00000000ffa12c00, 0x0000000100000000)
 Metaspace       used 3462K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 377K, capacity 388K, committed 512K, reserved 1048576K
}
{Heap before GC invocations=1 (full 0):
 def new generation   total 9216K, used 5203K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,  51% used [0x00000000fec00000, 0x00000000ff014f50, 0x00000000ff400000)
  from space 1024K, 100% used [0x00000000ff500000, 0x00000000ff600000, 0x00000000ff600000)
  to   space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
 tenured generation   total 10240K, used 4170K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
   the space 10240K,  40% used [0x00000000ff600000, 0x00000000ffa12b50, 0x00000000ffa12c00, 0x0000000100000000)
 Metaspace       used 3462K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 377K, capacity 388K, committed 512K, reserved 1048576K
[GC (Allocation Failure)  9374K->5161K(19456K), 0.0008099 secs]
Heap after GC invocations=2 (full 0):
 def new generation   total 9216K, used 0K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,   0% used [0x00000000fec00000, 0x00000000fec00000, 0x00000000ff400000)
  from space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400100, 0x00000000ff500000)
  to   space 1024K,   0% used [0x00000000ff500000, 0x00000000ff500000, 0x00000000ff600000)
 tenured generation   total 10240K, used 5161K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
   the space 10240K,  50% used [0x00000000ff600000, 0x00000000ffb0a5f8, 0x00000000ffb0a600, 0x0000000100000000)
 Metaspace       used 3462K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 377K, capacity 388K, committed 512K, reserved 1048576K
}

Process finished with exit code 0

重点

Heap before GC ....
Heap after GC ....

2.8、-Xloggc:filename

1、 指定GClog的位置，以文件输出；
2、 与上面几个配合使用；

-Xloggc:./gc.log

JVM 参数

-verbose:gc
-Xms20M
-Xmx20M
-Xmn10M
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=1
-XX:+UseSerialGC

-XX:+PrintGCDetails
-Xloggc:./gc.log

日志

*

2.9、-XX:+PrintClassHistogram

1、 按下Ctrl+Break后，打印类的信息；
2、 打印出实例的数量以及空间大小；
3、 注意：我没找到Ctrl+Break键，所以下面的图不是我测试的数据；

JVM 参数

-verbose:gc
-Xms20M
-Xmx20M
-Xmn10M
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=1
-XX:+UseSerialGC

-XX:+PrintGC
-XX:+PrintClassHistogram

*

2.10、-XX:+PrintTLAB

查看TLAB空间的使用情况

JVM 参数

-verbose:gc
-Xms20M
-Xmx20M
-Xmn10M
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=1
-XX:+UseSerialGC

-XX:+PrintGC
-XX:+PrintTLAB

日志

TLAB: gc thread: 0x0000000014066800 [id: 27888] desired_size: 163KB slow allocs: 0  refill waste: 2616B alloc: 0.99998     7111KB refills: 1 waste 100.0% gc: 167744B slow: 0B fast: 0B
TLAB: gc thread: 0x0000000014041800 [id: 28144] desired_size: 163KB slow allocs: 0  refill waste: 2616B alloc: 0.99998     7111KB refills: 2 waste 13.9% gc: 45360B slow: 1416B fast: 0B
TLAB: gc thread: 0x0000000003b43800 [id: 16568] desired_size: 163KB slow allocs: 8  refill waste: 2712B alloc: 0.99998     7111KB refills: 13 waste  3.8% gc: 77000B slow: 4928B fast: 0B
TLAB totals: thrds: 3  refills: 16 max: 13 slow allocs: 8 max 8 waste: 11.0% gc: 290104B max: 167744B slow: 6344B max: 4928B fast: 0B max: 0B
[GC (Allocation Failure)  7111K->5219K(19456K), 0.0020531 secs]
[GC (Allocation Failure)  9315K->5210K(19456K), 0.0006678 secs]

2.11、-XX:+TraceClassLoading

1、 监控系统中每一个类的加载；
2、 在做一些跟踪调试的时候可以加上，可以看到那些类被加载进来；

JVM 参数

-verbose:gc
-Xms20M
-Xmx20M
-Xmn10M
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=1
-XX:+UseSerialGC

-XX:+PrintGC
-XX:+TraceClassLoading

日志


[Opened D:\Java\jdk1.8.0_181\jre\lib\rt.jar]
[Loaded java.lang.Object from D:\Java\jdk1.8.0_181\jre\lib\rt.jar]
[Loaded java.io.Serializable from D:\Java\jdk1.8.0_181\jre\lib\rt.jar]
[Loaded java.lang.Comparable from D:\Java\jdk1.8.0_181\jre\lib\rt.jar]
[Loaded java.lang.CharSequence from D:\Java\jdk1.8.0_181\jre\lib\rt.jar]
 
......

[Loaded java.net.DualStackPlainSocketImpl from D:\Java\jdk1.8.0_181\jre\lib\rt.jar]
[Loaded java.lang.Void from D:\Java\jdk1.8.0_181\jre\lib\rt.jar]
[Loaded java.net.Inet6Address from D:\Java\jdk1.8.0_181\jre\lib\rt.jar]
[Loaded java.net.Inet6Address$Inet6AddressHolder from D:\Java\jdk1.8.0_181\jre\lib\rt.jar]
[Loaded java.net.SocksSocketImpl$3 from D:\Java\jdk1.8.0_181\jre\lib\rt.jar]
[Loaded java.net.ProxySelector from D:\Java\jdk1.8.0_181\jre\lib\rt.jar]
[Loaded sun.net.spi.DefaultProxySelector from D:\Java\jdk1.8.0_181\jre\lib\rt.jar]
[Loaded sun.net.spi.DefaultProxySelector$1 from D:\Java\jdk1.8.0_181\jre\lib\rt.jar]
[Loaded sun.net.NetProperties from D:\Java\jdk1.8.0_181\jre\lib\rt.jar]
[Loaded sun.net.NetProperties$1 from D:\Java\jdk1.8.0_181\jre\lib\rt.jar]
[Loaded java.net.URI from D:\Java\jdk1.8.0_181\jre\lib\rt.jar]
[GC (Allocation Failure)  6947K->5191K(19456K), 0.0019703 secs]
Process finished with exit code 0

2.12、OOM 情况

2.12.1、-XX:+HeapDumpOnOutOfMemoryError

OOM时导出堆到文件

2.12.2、-XX:+HeadDumpHead

导出OOM的路径

2.12.3、-XX:OnOutOfMemoryError

1、 在OOM的时候，执行一个脚本；
-XX:OnOutOfMemoryError=D:\java\workSpace-learn\learnDemo\visualvm-learn\demo1\print.bat
2、 可以在OOM时，发送邮件，甚至是重启程序；

2.12.4、测试代码

public class Test02 {

    private static final int _1MB = 1024 * 1024;

    /**
     * JVM 参数
     * -verbose:gc //打开GC的跟踪日志
     * -Xms20M  //最小堆内存
     * -Xmx20M  //最大堆内存
     * -Xmn10M  //年轻代内存
     * -XX:SurvivorRatio=8   //eden和from,to 比例为8:1:1
     * -XX:MaxTenuringThreshold=1 //最大分代年龄为1
     * -XX:+UseSerialGC  //收集器
     * -XX:+PrintGC
     * -XX:+HeapDumpOnOutOfMemoryError
     * -XX:HeapDumpPath=./oom.dump
     * -XX:OnOutOfMemoryError=D:\java\workSpace-learn\learnDemo\visualvm-learn\demo1\print.bat
     **/
    public static void main(String[] args) {
        List<byte[]> list = new ArrayList();
        for (int i = 0; i < 25; i++) {
            list.add(new byte[_1MB]);
        }
    }
}
JVM 参数

-verbose:gc
-Xms20M
-Xmx20M
-Xmn10M
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=1
-XX:+UseSerialGC
-XX:+PrintGC
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=./oom.dump
-XX:OnOutOfMemoryError=D:\java\workSpace-learn\learnDemo\visualvm-learn\demo1\print.bat

2.12.5、结果

*
*

2.13、-XX:+PrintGCCause

打印GC回收原因

JVM 参数

-verbose:gc
-Xms20M
-Xmx20M
-Xmn10M
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=1
-XX:+UseSerialGC

-XX:+PrintGC
-XX:+PrintGCCause

日志

[GC (Allocation Failure)  6947K->5191K(19456K), 0.0020120 secs]
[GC (Allocation Failure)  9535K->5157K(19456K), 0.0007670 secs]

2.14、-XX:+PrintGCDateStamps

打印GC发生日期戳

JVM 参数

-verbose:gc
-Xms20M
-Xmx20M
-Xmn10M
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=1
-XX:+UseSerialGC

-XX:+PrintGC
-XX:+PrintGCDateStamps

日志

2022-12-01T11:19:58.514+0800: [GC (Allocation Failure)  7111K->5219K(19456K), 0.0020058 secs]
2022-12-01T11:19:58.516+0800: [GC (Allocation Failure)  9315K->5210K(19456K), 0.0007110 secs]

2.15、日志生成方式

如果不设置滚动日志通过%t.log每天生成一个jvm的GC文件但需要定时清理

2.15.1、-XX:+UseGCLogFileRotation

开启滚动生成日志

2.15.2、-XX:NumberOfGCLogFiles=5

1、 滚动GC日志文件数；
2、 默认：0不滚动；

2.15.3、-XX:GCLogFileSize=20M

每个GC日志文件分割时的大小

2.15.4、JVM 参数

-verbose:gc
-Xms20M
-Xmx20M
-Xmn10M
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=1
-XX:+UseSerialGC

-XX:+PrintGCDetails
-Xloggc:./gc-%t.log
-XX:+UseGCLogFileRotation
-XX:NumberOfGCLogFiles=5
-XX:GCLogFileSize=20M

2.12.5、结果

*

2.16、异常崩溃日志

1、 只是在针对异常崩溃如:jdkbug或者在自己程序有问题调用了调用了native的方法的时候才会有用；

1、 native的方法：比如调用了C/C++写的库文件，比如C/C++里面调用JVM；
2、 针对手动kill或者linux自动触发oomkill是是无法触发的；
3、 触发OnError或者ErrorFile的场景比较难模拟；

2.16.1、-XX:ErrorFile=./hs_err_pid.log

出现致命ERROR之后，保存日志的路径


-XX:ErrorFile=./hs_err_pid_%p.log

1、 指定当异常崩溃保存的错误日志路径；
2、 默认是在jdk目录下；

2.16.2、-XX:OnError=“;”

出现致命ERROR之后运行自定义命令 如:“sh ~/cleanup.sh”

2.16.3、JVM 参数

-verbose:gc
-Xms20M
-Xmx20M
-Xmn10M
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=1
-XX:+UseSerialGC

-XX:+PrintGC
-XX:ErrorFile=/var/log/hs_err_pid_%p.log

3、常用的参数


-verbose:gc
-XX:+PrintGCDetails	
-XX:+PrintGCCause
-XX:+PrintGCTimeStamps
-XX:+PrintTenuringDistribution
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCApplicationConcurrentTime
-XX:+PrintHeapAtGC
-Xloggc:./gc-%t.log
-XX:+UseGCLogFileRotation
-XX:NumberOfGCLogFiles=5
-XX:GCLogFileSize=20M
-XX:+PrintTLAB
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=./oom.dump
-XX:ErrorFile=/E/hs_err_pid_%p.log

3.1、测试


-Xms20M
-Xmx20M
-Xmn10M
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=1
-XX:+UseSerialGC

-verbose:gc
-XX:+PrintGCDetails	
-XX:+PrintGCCause
-XX:+PrintGCTimeStamps
-XX:+PrintTenuringDistribution
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCApplicationConcurrentTime
-XX:+PrintHeapAtGC
-Xloggc:./gc-%t.log
-XX:+UseGCLogFileRotation
-XX:NumberOfGCLogFiles=5
-XX:GCLogFileSize=20M
-XX:+PrintTLAB
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=./oom.dump
-XX:ErrorFile=/E/hs_err_pid_%p.log

*