点击上方“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,详细解释在日志中注释
代码语言:javascript复制// 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 前后的堆内存信息。
代码语言:javascript复制{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 而产生的停顿时间
代码语言:javascript复制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
代码语言:javascript复制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();
}
}
控制台输出:
代码语言:javascript复制[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:打印所有系统参数的值。