【原创】JVM系列07 | 虚拟机跟踪参数

java进阶架构师

发布于 2020-06-07 10:41:40

5140

发布于 2020-06-07 10:41:40

文章被收录于专栏：Java进阶架构师

点击上方“java进阶架构师”，选择右上角“置顶公众号”

20大进阶架构专题每日送达

本文是何适 JVM 修仙系列第 7 篇，文末有本系列文章汇总。

Java 虚拟机运行过程状态多变且复杂，我们要理解虚拟机的运行过程，掌握虚拟机的运行状态，才能进行问题的排查和性能调优。那么如何跟踪虚拟机运行状态呢？今天就来介绍下虚拟机跟踪参数。

跟踪 GC 日志
跟踪类加载/卸载信息
跟踪查看虚拟机参数

1. 跟踪 GC 日志

垃圾回收机制是由虚拟机控制的，但又对程序影响很大，所以需要一些垃圾回收的跟踪参数来帮助我们监控垃圾回收。

1.1 -XX:+PrintGC

最简单的 GC 参数。

设置了-XX:+PrintGC之后打印如下日志：每一行代表进行了一次 GC。以第一行为例：1552K->848K(98304K)表示 GC 前堆空间使用 1552K，GC 后堆空间使用 848K，当前可用堆空间为 98304K；0.0006871 secs表示 GC 花费的时间。

[GC (System.gc())  1552K->848K(98304K), 0.0006871 secs]
[GC (System.gc())  558K->590K(98304K), 0.0003345 secs]
[GC (System.gc())  558K->590K(98304K), 0.0003711 secs]

1.2 -XX:+PrintGCDetails

最常用的 GC 参数，可以在日志中打印 GC 详细信息。

如下日志，执行了一次 Young GC 和 Full GC，详细解释在日志中注释

// PSYoungGen: 2064K->800K(29696K)：经过GC，新生代内存占用由2064K变为800K，当前新生代可用内存为29696K
// 2064K->808K(98304K)：经过GC，堆内存由2064K变为808K，当前堆可用内存为98304K
[GC (System.gc()) [PSYoungGen: 2064K->800K(29696K)] 2064K->808K(98304K), 0.0008407 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
// [PSYoungGen: 800K->0K(29696K)]：新生代内存占用由800K变为0K，当前新生代可用内存为29696K
// [ParOldGen: 8K->562K(68608K)]：老年代内存占用由8K变为562K，当前新生代可用内存为68608K
// 808K->562K(98304K):堆内存由808K变为562K，当前堆可用内存为98304K
// [Metaspace: 2788K->2788K(1056768K)]：元数据区内存占用由2788K变为2788K，当前堆可用内存为1056768K
[Full GC (System.gc()) [PSYoungGen: 800K->0K(29696K)] [ParOldGen: 8K->562K(68608K)] 808K->562K(98304K), [Metaspace: 2788K->2788K(1056768K)], 0.0047863 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
// 设置-XX:+PrintGCDetails参数，虚拟机退出前打印堆详细信息
Heap
//新生代
 PSYoungGen      total 29696K, used 256K [0x00000000fdf00000, 0x0000000100000000, 0x0000000100000000)
  eden space 25600K, 1% used [0x00000000fdf00000,0x00000000fdf40178,0x00000000ff800000)
  from space 4096K, 0% used [0x00000000ff800000,0x00000000ff800000,0x00000000ffc00000)
  to   space 4096K, 0% used [0x00000000ffc00000,0x00000000ffc00000,0x0000000100000000)
// 老年代
 ParOldGen       total 68608K, used 562K [0x00000000f9c00000, 0x00000000fdf00000, 0x00000000fdf00000)
  object space 68608K, 0% used [0x00000000f9c00000,0x00000000f9c8c900,0x00000000fdf00000)
// 元数据区
 Metaspace       used 2795K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 296K, capacity 386K, committed 512K, reserved 1048576K

1.3 -XX:+PrintHeapAtGC

详细的打印出 GC 前后的堆内存信息。

{Heap before GC invocations=1 (full 0):
// GC前堆内存详细信息
 PSYoungGen      total 29696K, used 1552K [0x00000000fdf00000, 0x0000000100000000, 0x0000000100000000)
  eden space 25600K, 6% used [0x00000000fdf00000,0x00000000fe084080,0x00000000ff800000)
  from space 4096K, 0% used [0x00000000ffc00000,0x00000000ffc00000,0x0000000100000000)
  to   space 4096K, 0% used [0x00000000ff800000,0x00000000ff800000,0x00000000ffc00000)
 ParOldGen       total 68608K, used 0K [0x00000000f9c00000, 0x00000000fdf00000, 0x00000000fdf00000)
  object space 68608K, 0% used [0x00000000f9c00000,0x00000000f9c00000,0x00000000fdf00000)
 Metaspace       used 2751K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 295K, capacity 386K, committed 512K, reserved 1048576K

Heap after GC invocations=1 (full 0):
// GC后堆内存详细信息
 PSYoungGen      total 29696K, used 840K [0x00000000fdf00000, 0x0000000100000000, 0x0000000100000000)
  eden space 25600K, 0% used [0x00000000fdf00000,0x00000000fdf00000,0x00000000ff800000)
  from space 4096K, 20% used [0x00000000ff800000,0x00000000ff8d2030,0x00000000ffc00000)
  to   space 4096K, 0% used [0x00000000ffc00000,0x00000000ffc00000,0x0000000100000000)
 ParOldGen       total 68608K, used 8K [0x00000000f9c00000, 0x00000000fdf00000, 0x00000000fdf00000)
  object space 68608K, 0% used [0x00000000f9c00000,0x00000000f9c02000,0x00000000fdf00000)
 Metaspace       used 2751K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 295K, capacity 386K, committed 512K, reserved 1048576K
}

1.4 -XX:+PrintGCTimeStamps

-XX:+PrintGCTimeStamps与-XX:+PrintGC/-XX:+PrintGCDetails搭配使用，输出每次 GC 发生的时间，该时间是虚拟机启动后的时间偏移量。如下日志表示 Java 程序启动后分别在 0.219 秒、0.231 秒、0.236 秒发生了三次 GC。

0.219: [GC (System.gc())  2064K->776K(98304K), 0.0008678 secs]
0.231: [GC (System.gc())  562K->594K(98304K), 0.0002789 secs]
0.236: [GC (System.gc())  562K->594K(98304K), 0.0002970 secs]
...

1.5 -XX:+PrintGCApplicationConcurrentTime

记录 Java 程序执行时间，表示应用程序在两次垃圾回收之间运行多长时间。

1.6 -XX:+PrintGCApplicationStoppedTime

记录 Java 程序因为 GC 而产生的停顿时间

Application time: 0.2863875 seconds
Total time for which application threads were stopped: 0.0225087 seconds
Application time: 0.1476791 seconds
Total time for which application threads were stopped: 0.0255697 seconds

该应用程序运行大约 0.2863875 秒，然后停止了大约 0.0225087 秒。

1.7 -Xloggc

GC 日志默认在控制台输出，不便于保存和使用，所以提供了-Xloggc 参数。-Xloggc 用于指定 GC 日志的输出形式及目录，如设置-Xloggc:log/gc.log，就会在程序当前目录下的 log 下生成 GC 日志 gc.log。

2. 跟踪类加载/卸载信息

Java 程序类以两种形式存在：

jar 包中的 class 文件，可以通过文件系统查看；
动态代理、AOP 等技术生成的动态代理类，无法通过文件系统查看。

所以不是所有类都可以通过文件系统查看的，所以提供了跟踪类加载和卸载的参数-verbose:class。

-verbose:class：跟踪类加载和卸载，等价于下面两个参数一起用-XX:+TraceClassLoading：单独跟踪类加载-XX:+TraceClassUnloading：单独跟踪类卸载

举例：执行如下使用动态的代码，设置参数-verbose:class

public class SampleClass {
    public void test(){
//        System.out.println("hello world");
    }

    public static void main(String[] args) {
        for (int i = 0; i < 99; i++) {
        }
        Enhancer enhancer = new Enhancer();
        enhancer.setSuperclass(SampleClass.class);
        enhancer.setCallback(new MethodInterceptor() {
            @Override
            public Object intercept(Object obj, Method method, Object[] args, MethodProxy proxy) throws Throwable {
                Object result = proxy.invokeSuper(obj, args);
                return result;
            }
        });
        SampleClass sample = (SampleClass) enhancer.create();
        sample.test();
    }
}

控制台输出：

[Loaded test.SampleClass$$EnhancerByCGLIB$$c8c2ea0e$$FastClassByCGLIB$$8a605109 from file:/D:/bov/workspace_trunk_20191009/ZTest/bin/]
[Loaded test.SampleClass from file:/D:/bov/workspace_trunk_20191009/ZTest/bin/]
[Loaded test.SampleClass$1 from file:/D:/bov/workspace_trunk_20191009/ZTest/bin/]
[Loaded test.SampleClass$$EnhancerByCGLIB$$c8c2ea0e from file:/D:/bov/workspace_trunk_20191009/ZTest/bin/]
...部分省略

3. 跟踪查看虚拟机参数

3.1 -XX:+PrintVMOptions

-XX:+PrintVMOptions查看 Java 程序启动时设置的参数。

程序启动时设置了 -XX:+PrintGC -XX:+PrintVMOptions，输出结果如下：

VM option '+PrintGC'
VM option '+PrintVMOptions'

3.2 -XX:+PrintCommandLineFlags

打印虚拟机的显示和隐藏参数。

程序启动时只设置了 -XX:+PrintGC -XX:+PrintCommandLineFlags，输出结果如下：

-XX:InitialHeapSize=104857600
-XX:MaxHeapSize=104857600
-XX:+PrintCommandLineFlags
-XX:+PrintGC
-XX:ThreadStackSize=128
-XX:+UseCompressedClassPointers
-XX:+UseCompressedOops
-XX:-UseLargePagesIndividualAllocation
-XX:+UseParallelGC

3.3 -XX:+PrintFlagsFinal

打印所有系统参数的值。设置-XX:+PrintFlagsFinal执行后，输出结果如下：

[Global flags]
    uintx AdaptiveSizeDecrementScaleFactor          = 4                                   {product}
    uintx AdaptiveSizeMajorGCDecayTimeScale         = 10                                  {product}
    uintx AdaptiveSizePausePolicy                   = 0                                   {product}
    uintx AdaptiveSizePolicyCollectionCostMargin    = 50                                  {product}
    uintx AdaptiveSizePolicyInitializingSteps       = 20                                  {product}
    ...
    省略了500多行详细信息
    ...

4. 总结

跟踪 GC 日志

-XX:+PrintGC：最简单的 GC 参数，每一行代表进行了一次 GC。
-XX:+PrintGCDetails：最常用的 GC 参数，可以在日志中打印 GC 详细信息。
-XX:+PrintHeapAtGC：详细的打印出 GC 前后的堆内存信息。
-XX:+PrintGCTimeStamps：输出每次 GC 发生的时间
-XX:+PrintGCApplicationConcurrentTime：记录 Java 程序执行时间，表示应用程序在两次垃圾回收之间运行多长时间
-XX:+PrintGCApplicationStoppedTime：记录 Java 程序因为 GC 而产生的停顿时间

跟踪类加载/卸载信息

-verbose:class：跟踪类加载和卸载

跟踪查看虚拟机参数

-XX:+PrintVMOptions：查看 Java 程序启动时设置的参数。
-XX:+PrintCommandLineFlags：打印虚拟机的显示和隐藏参数。
-XX:+PrintFlagsFinal：打印所有系统参数的值。

本文参与腾讯云自媒体同步曝光计划，分享自微信公众号。

原始发表：2020-06-05，如有侵权请联系 cloudcommunity@tencent.com 删除

海外加速

java

数据分析

本文分享自 java进阶架构师微信公众号，前往查看

如有侵权，请联系 cloudcommunity@tencent.com 删除。

本文参与腾讯云自媒体同步曝光计划，欢迎热爱写作的你一起参与！

海外加速

java

数据分析

登录后参与评论

0 条评论

热度