首页 > 代码库 > 浅析JVM中的GC日志
浅析JVM中的GC日志
目录
一、GC日志的格式分析
二、运行时开启GC日志
一、GC日志的格式分析
在讲述GC日志之前,我们先来运行下面这段代码
1 package com.example; 2 3 public class TestMinorGC { 4 private static final int _1MB = 1024*1024; 5 6 public static void testAllocation() { 7 byte[] allocation1, allocation2, allocation3, allocation4; 8 9 allocation1 = new byte[2 * _1MB]; 10 allocation2 = new byte[2 * _1MB]; 11 allocation3 = new byte[2 * _1MB]; 12 allocation4 = new byte[4 * _1MB]; 13 } 14 15 public static void main() { 16 testAllocation(); 17 } 18 }
配置如下的虚拟机参数运行上述程序:
1 vm option: -Xms20M -Xmx20M -Xmn10M -verbose:gc -XX:+PrintGCDetails -XX:SurvivorRatio=8
注: -XX:+PrintGCDetails参数用于告诉虚拟机在发生垃圾收集行为时打印内存回收日志,并且在进程退出的时候输出当前内存的各区域分配情况。
最终,程序输出:
1 [GC [PSYoungGen: 7307K->480K(9216K)] 7307K->6624K(19456K), 0.0072860 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] 2 [Full GC [PSYoungGen: 480K->0K(9216K)] [ParOldGen: 6144K->6476K(10240K)] 6624K->6476K(19456K) [PSPermGen: 2920K->2919K(21504K)], 0.0178620 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 3 [Full GC [PSYoungGen: 4354K->1024K(9216K)] [ParOldGen: 6476K->9536K(10240K)] 10831K->10560K(19456K) [PSPermGen: 2921K->2921K(21504K)], 0.0139610 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 4 [Full GC [PSYoungGen: 7339K->0K(9216K)] [ParOldGen: 9536K->4419K(10240K)] 16876K->4419K(19456K) [PSPermGen: 3004K->3004K(21504K)], 0.0120490 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 5 Heap 6 PSYoungGen total 9216K, used 4190K [0x00000007ff600000, 0x0000000800000000, 0x0000000800000000) 7 eden space 8192K, 51% used [0x00000007ff600000,0x00000007ffa17a18,0x00000007ffe00000) 8 from space 1024K, 0% used [0x00000007ffe00000,0x00000007ffe00000,0x00000007fff00000) 9 to space 1024K, 0% used [0x00000007fff00000,0x00000007fff00000,0x0000000800000000) 10 ParOldGen total 10240K, used 4419K [0x00000007fec00000, 0x00000007ff600000, 0x00000007ff600000) 11 object space 10240K, 43% used [0x00000007fec00000,0x00000007ff050eb0,0x00000007ff600000) 12 PSPermGen total 21504K, used 3010K [0x00000007f9a00000, 0x00000007faf00000, 0x00000007fec00000) 13 object space 21504K, 14% used [0x00000007f9a00000,0x00000007f9cf0bf8,0x00000007faf00000)
程序输出一大段看不懂的文字,这些就是本文要讲述的GC日志,下面来介绍一下GC日志的格式:
(1)GC, Full GC说明了这次垃圾收集的停顿类型,而不是用来区分新生代GC还是老年代GC。如果有"Full",则表示这次GC发生了"Stop-The-World"。
(2)PSYoungGen, ParOldGen,PSPermGen表示GC发生的区域,这里显示的区域名称与使用的GC收集器密切相关,不同收集器对于不同区域所显示的名称可能不同。
(3)接下来"7307K->480K(9216K)"的含义是:GC前该内存区域已使用容量 -> GC后该内存区域已使用容量(该内存区域的总容量)。
(4)"7307K->6624K(19456K)"的含义是:GC前Java堆已使用容量 -> GC后Java堆已使用容量(Java堆总容量) 。
(5)"0.0072860 secs" 表示该内存区域GC所占用的时间,单位是秒。
(6)[Times: user=0.01 sys=0.01, real=0.00 secs]:分别表示用户态消耗CPU时间, 内核态消耗CPU时间,操作从开始到结束所经过的墙钟时间。
PS,CPU时间与墙钟时间的区别是:墙钟时间包括各种非运算的等待耗时,例如等待磁盘I/O、等待线程阻塞等;而CPU时间不包括这些耗时。
当系统有多cpu或者多核的话,多线程操作会叠加这些CPU时间,所以有时看到user或sys时间超过real时间是完全正常的。
二、运行时开启GC日志
我们经常会遇到JVM运行时出错的情况。若能在启动时加入一些启动选项(startup option),便可以获取与bug相关的重要线索,从而有希望根治它们。但在实际操作时,我们总是忘记添加-XX:+HeapDumpOnOutOfMemoryError
或 -XX:+PrintGCDetails
这样必要的flag。
每当面对如此窘境,我们只能关闭JVM,修改启动参数(startup parameter),然后默默祈祷,希望问题场景(problematic situation)能在重启之后得以重现。这种方法偶尔奏效,在场景重现后你或许还能收集到足够的证据,以便动手根治潜在的问题。
不难看出,前文所述的方法问题显著——你必须执行一次额外的重启才能加入那烦人的debug选项,而不能借助中断(outage)实现。事实上,JDK bundle提供了一种可行的变通方案,如果将之收入麾下,偶尔还能从中获益。
jinfo
在JDK bundle中隐藏着一个精悍的小工具——jinfo。作为一个命令行工具,jinfo用于收集正在运行的Java进程的配置信息。jinfo吸引眼球的地方在于,它能通过-flag
选项动态修改指定的Java进程中的某些JVM flag的值。虽然这样的flag数量有限,但它们偶尔能够帮助到你。通过以下的命令你便能看到JVM中哪些flag可以被jinfo动态修改:
my-precious me$ java -XX:+PrintFlagsFinal -version|grep manageable intx CMSAbortablePrecleanWaitMillis = 100 {manageable} intx CMSWaitDuration = 2000 {manageable} bool HeapDumpAfterFullGC = false {manageable} bool HeapDumpBeforeFullGC = false {manageable} bool HeapDumpOnOutOfMemoryError = false {manageable} ... cut for brevity ... bool PrintGC = false {manageable} bool PrintGCDateStamps = false {manageable} bool PrintGCDetails = false {manageable} bool PrintGCTimeStamps = false {manageable}
通过选项-XX:+PrintFlagsFinal
可以列出所有的JVM flag,而其中的标注为manageable
的flag则是值得我们关注的部分。这些flag可通过JDK management interface(-XX:+PrintFlagsFinal)动态修改。虽然在JConsole中也能查到与其十分相似的MBean。但在我看来,以命令行的方式查看它们更加的便捷。
如何使用jinfo
让我们通过实战来学习如何使用jinfo。在下面的例子中,我们将在一个正在运行的JVM中动态开启GC日志功能:
my-precious me$ jps 12278 HighAllocationRate 12279 Jps 12269 JConsole my-precious me$ jinfo -flag +PrintGCDetails 12278 my-precious me$ jinfo -flag +PrintGC 12278 my-precious me$
在jinfo中需要打开-XX:+PrintGC
和 -XX:+PrintGCDetails
两个选项才能开启GC日志,这与用命令行参数的方式实现有着细微的差别——如果你通过启动脚本(startup script)来设置参数,仅需-XX:+PrintGCDetails
即可,因为-XX:+PrintGC
会被自动打开。
不过,从standard output的结果来看,PID为12278的进程的GC日志的确能够滚动地显示出来:
... [GC (Allocation Failure) [PSYoungGen: 876416K->102624K(909312K)] 1094420K->320820K(1161216K), 0.2173131 secs] [Times: user=0.74 sys=0.00, real=0.22 secs] ... [GC (Allocation Failure) [PSYoungGen: 890304K->102240K(917504K)] 1108924K->320956K(1169408K), 0.2446639 secs] [Times: user=0.82 sys=0.01, real=0.25 secs] ...
同理,若想关闭GC日志功能,只需要执行jinfo -flag -PrintGCDetails 12278
和 jinfo -flag -PrintGC 12278
命令即可。
浅析JVM中的GC日志