使用 Jconsle 与 GC 日志分析程序 JVM 运行状态

最近在学习 JVM，刚好论文的实验代码出现运行过慢的情况，所以想通过 Jconsle 查看代码运行中 JVM 的情况。

Jconsole中对内存为如下结构：

其中 Metaspace 是 Java 1.8 之后取消方法区（永久代）后引入的。

Jconsle 连接后，可以看到内存、线程、CPU 等概览。

堆内存

查看程序运行过程中堆内存的使用情况

堆内存图上下波动，说明进行了多次 GC ，并且基本没有内存泄漏。从详细信息中也可以看到 新生代用的是 PS Scavenge 垃圾收集器，这是一个并行的多线程的收集器，目标时控制吞吐量。老年代用的是 PS MarkSweep （Serial Old）收集器，是一个单线程，使用标记-整理算法。

从图中可以看出，老年代GC了一次，新生代 GC 了4525次。新生代 GC 频繁应该与我代码中在循环体里面创建矩阵对象有关。

以下分别是新生代 Eden 区，Survivor 区和老年代的内存状态图，也印证了 Minor GC 频繁的现象。但是 GC 所占用的时间与程序整体时间相比并不多，这个算法运行时间在10分钟左右。

GC 原理

新生代的GC使用复制算法。在GC前To survivor区保持清空,对象保存在Eden和From survivor区中，GC运行时,Eden中的幸存对象被复制到 To survivor区。针对 From survivor取中的幸存对象，会考虑对象年龄,如果年龄没达到阀值(tenuring threshold)，对象会被复制到To survivor区。如果达到阀值对象被复制到老年代。复制阶段完成后，Eden 和From survivor区中只保存死对象，可以被视为全部清空。如果在复制过程中To survivor区被填满了，剩余的对象会被复制到老年代中。最后 From和To会对换。

GC 日志

程序运行时加入 -XX:+PrintGCDetails 参数。
列出一部分GC日志如下

[Full GC (Ergonomics) [PSYoungGen: 69883K->0K(657920K)] [ParOldGen: 182607K->93569K(191488K)] 252491K->93569K(849408K), [Metaspace: 8524K->8524K(1056768K)], 0.0221501 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 

[GC (Allocation Failure) [PSYoungGen: 111648K->32K(131584K)] 212646K->101030K(323072K), 0.0005877 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC (Allocation Failure) [PSYoungGen: 131104K->32K(127488K)] 232102K->101030K(318976K), 0.0006413 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC (Allocation Failure) [PSYoungGen: 126496K->64K(122880K)] 227494K->101062K(314368K), 0.0006811 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC (Allocation Failure) [PSYoungGen: 122432K->32K(119296K)] 223430K->101038K(310784K), 0.0005787 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC (Allocation Failure) [PSYoungGen: 118304K->64K(114688K)] 219310K->101070K(306176K), 0.0006089 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
[GC (Allocation Failure) [PSYoungGen: 114240K->32K(111616K)] 215246K->101038K(303104K), 0.0007545 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 

Heap
 PSYoungGen      total 111616K, used 17726K [0x0000000780900000, 0x000000079dd00000, 0x00000007c0000000)
  eden space 110592K, 15% used [0x0000000780900000,0x0000000781a47890,0x0000000787500000)
  from space 1024K, 3% used [0x000000079db00000,0x000000079db08000,0x000000079dc00000)
  to   space 512K, 0% used [0x000000079dc80000,0x000000079dc80000,0x000000079dd00000)
 ParOldGen       total 191488K, used 101006K [0x0000000701a00000, 0x000000070d500000, 0x0000000780900000)
  object space 191488K, 52% used [0x0000000701a00000,0x0000000707ca3818,0x000000070d500000)
 Metaspace       used 8799K, capacity 9006K, committed 9216K, reserved 1056768K
  class space    used 948K, capacity 999K, committed 1024K, reserved 1048576K

（1）GC, Full GC说明了这次垃圾收集的停顿类型，而不是用来区分新生代GC还是老年代GC。如果有”Full”，则表示这次GC发生了”Stop-The-World”。

（2）PSYoungGen, ParOldGen，Metaspace 表示GC发生的区域，这里显示的区域名称与使用的GC收集器密切相关，不同收集器对于不同区域所显示的名称可能不同。

（3）接下来”111648K->32K(131584K)”的含义是：GC前该内存区域已使用容量 -> GC后该内存区域已使用容量(该内存区域的总容量)。

（4）”212646K->101030K(323072K)”的含义是：GC前Java堆已使用容量 -> GC后Java堆已使用容量（Java堆总容量） 。

（5）”0.0005877 secs” 表示该内存区域GC所占用的时间，单位是秒。

（6）[Times: user=0.01 sys=0.01, real=0.00 secs]：分别表示用户态消耗CPU时间, 内核态消耗CPU时间，操作从开始到结束所经过的墙钟时间。

（7）Allocation Failure 代表了 GC 的原因，没有足够的空间分配资源。

　　PS，CPU时间与墙钟时间的区别是：墙钟时间包括各种非运算的等待耗时，例如等待磁盘I/O、等待线程阻塞等；而CPU时间不包括这些耗时。

　　当系统有多cpu或者多核的话，多线程操作会叠加这些CPU时间，所以有时看到user或sys时间超过real时间是完全正常的。 　　 　　

尝试减少 GC 次数的实践

直接调整堆大小

-Xms1024m -Xmx1024m 。

发现 Minor GC 在 Eden 300m 左右开始发生，GC 次数明显减少，原因还是内存无法分配。从程序运行结果来看，运行时间并没有改变，所以可以确定程序执行慢，不是 GC 的原因，是代码逻辑的原因。

[GC (Allocation Failure) [PSYoungGen: 348672K->498K(347648K)] 587643K->240102K(1047040K), 0.0015896 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC (Allocation Failure) [PSYoungGen: 347634K->64K(348160K)] 587238K->240182K(1047552K), 0.0013313 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 

Heap
 PSYoungGen      total 348160K, used 275395K [0x00000000eab00000, 0x0000000100000000, 0x0000000100000000)
  eden space 347136K, 79% used [0x00000000eab00000,0x00000000fb7e0ef0,0x00000000ffe00000)
  from space 1024K, 6% used [0x00000000ffe00000,0x00000000ffe10000,0x00000000fff00000)
  to   space 1024K, 0% used [0x00000000fff00000,0x00000000fff00000,0x0000000100000000)
 ParOldGen       total 699392K, used 240118K [0x00000000c0000000, 0x00000000eab00000, 0x00000000eab00000)
  object space 699392K, 34% used [0x00000000c0000000,0x00000000cea7d958,0x00000000eab00000)
 Metaspace       used 12864K, capacity 13342K, committed 13696K, reserved 1060864K
  class space    used 1436K, capacity 1554K, committed 1664K, reserved 1048576K

将循环中不用的矩阵对象置 null 测试

一般 null 对象会被作为垃圾处理，有利于收集器判定垃圾，提高 GC 效率。

从结果来看基本没有变化，思考原因，应该是矩阵对象本来就比较大，在 Eden 区存放不下时发生 GC，清楚无用对象。这里将较大对象置 null，对 GC 次数影响不大。

总结

通过 Jconsle 与 GC 日志，简单实践了 JVM 相关参数应用，查看了程序运行时 JVM 内存状态。派出了论文代码运行缓慢关于 GC 方面的原因。