通过jinfo工具在full GC前后做heap dump

想像一个Java进程在远程服务器上突然遇到频繁full GC的状况。我们只是想动态的改变HeapDumpBeforeFullGC与HeapDumpAfterFullGC参数来获取full GC前后的heap dump，并不想在侵入到Java程序内去通过代码做这个工作。这种场景里jinfo就能派上用场了——它已经把相关的JMX操作给封装好了。
（提醒：如果找不到打出来的heap dump的话，请设置HeapDumpPath。这个参数指定heap dump的目录。
-XX:HeapDumpPath=path/to/your/heap/dumps/dir）

上一篇其实已经提到了，通过jinfo -flag同样可以设置标记为manageable的VM参数。参考jinfo的帮助文档：

引用

Command prompt代码

 

1. $ jinfo -help   
2. Usage:   
3.     jinfo [option] <pid>   
4.         (to connect to running process)   
5.     jinfo [option] <executable <core>   
6.         (to connect to a core file)   
7.     jinfo [option] [server_id@]<remote server IP or hostname>   
8.         (to connect to remote debug server)   
9.   
10. where <option> is one of:   
11.     -flag <name>         to print the value of the named VM flag   
12.     -flag [+|-]<name>    to enable or disable the named VM flag   
13.     -flag <name>=<value> to set the named VM flag to the given value   
14.     -flags               to print VM flags   
15.     -sysprops            to print Java system properties   
16.     <no option>          to print both of the above   
17.     -h | -help           to print this help message  

$ jinfo -helpUsage:    jinfo [option] <pid>        (to connect to running process)    jinfo [option] <executable <core>        (to connect to a core file)    jinfo [option] [server_id@]<remote server IP or hostname>        (to connect to remote debug server)where <option> is one of:    -flag <name>         to print the value of the named VM flag    -flag [+|-]<name>    to enable or disable the named VM flag    -flag <name>=<value> to set the named VM flag to the given value    -flags               to print VM flags    -sysprops            to print Java system properties    <no option>          to print both of the above    -h | -help           to print this help message

于是上一篇的实验可以用jinfo来做一次。

同样是在当前目录下放一个.hotspotrc文件来显示GC日志：

.hotspotrc代码

 

1. +PrintGCDetails  

+PrintGCDetails

然后开groovysh来执行三次System.gc()。其中，第一次System.gc()之后在命令行调用下列命令：

Command prompt代码

 

1. $ jps   
2. 18711 Jps   
3. 18650 GroovyStarter   
4. $ jinfo -flag +HeapDumpBeforeFullGC 18650  
5. $ jinfo -flag +HeapDumpAfterFullGC 18650  

$ jps18711 Jps18650 GroovyStarter$ jinfo -flag +HeapDumpBeforeFullGC 18650$ jinfo -flag +HeapDumpAfterFullGC 18650

然后在第二次System.gc()之后再调用：

Command prompt代码

 

1. $ jinfo -flag -HeapDumpBeforeFullGC 18650  
2. $ jinfo -flag -HeapDumpAfterFullGC 18650  

$ jinfo -flag -HeapDumpBeforeFullGC 18650$ jinfo -flag -HeapDumpAfterFullGC 18650

那么可以观察到Groovy Shell的运行状况是：

Groovysh代码

 

1. $ groovysh   
2. [GC [PSYoungGen: 14016K->1344K(16320K)] 14016K->1344K(53696K), 0.0072690 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]    
3. [GC [PSYoungGen: 15360K->2288K(30336K)] 15360K->4824K(67712K), 0.0183850 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]    
4. Groovy Shell (1.7.7, JVM: 1.6.0_25)   
5. Type 'help' or '\h' for help.   
6. ----------------------------------------------------------------------------------------------------------------------------   
7. groovy:000> System.gc()   
8. [GC [PSYoungGen: 26693K->2288K(30336K)] 29229K->8748K(67712K), 0.0262440 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]    
9. [Full GC (System) [PSYoungGen: 2288K->0K(30336K)] [PSOldGen: 6460K->8725K(37376K)] 8748K->8725K(67712K) [PSPermGen: 16933K->16933K(34176K)], 0.1172670 secs] [Times: user=0.11 sys=0.01, real=0.12 secs]    
10. ===> null   
11. groovy:000> System.gc()   
12. [GC [PSYoungGen: 2932K->256K(30336K)] 11658K->8981K(67712K), 0.0017600 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]    
13. [Heap Dump: Dumping heap to java_pid18650.hprof ...   
14. Heap dump file created [18535501 bytes in 0.317 secs]   
15. , 0.3208840 secs][Full GC (System) [PSYoungGen: 256K->0K(30336K)] [PSOldGen: 8725K->8918K(37376K)] 8981K->8918K(67712K) [PSPermGen: 17045K->17045K(38464K)], 0.1131950 secs] [Times: user=0.11 sys=0.00, real=0.11 secs]    
16. [Heap DumpDumping heap to java_pid18650.hprof.1 ...   
17. Heap dump file created [18440786 bytes in 0.318 secs]   
18. , 0.3179790 secs]===> null   
19. groovy:000> System.gc()   
20. [GC [PSYoungGen: 1016K->160K(30336K)] 9935K->9078K(67712K), 0.0020120 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]    
21. [Full GC (System) [PSYoungGen: 160K->0K(30336K)] [PSOldGen: 8918K->9028K(37376K)] 9078K->9028K(67712K) [PSPermGen: 17077K->17077K(36928K)], 0.1111340 secs] [Times: user=0.11 sys=0.00, real=0.11 secs]    
22. ===> null   
23. groovy:000> quit   
24. Heap   
25.  PSYoungGen      total 30336K, used 2427K [0x00000000edc00000, 0x00000000efbe0000, 0x0000000100000000)   
26.   eden space 28032K, 8% used [0x00000000edc00000,0x00000000ede5ef68,0x00000000ef760000)   
27.   from space 2304K, 0% used [0x00000000ef760000,0x00000000ef760000,0x00000000ef9a0000)   
28.   to   space 2304K, 0% used [0x00000000ef9a0000,0x00000000ef9a0000,0x00000000efbe0000)   
29.  PSOldGen        total 37376K, used 9028K [0x00000000c9400000, 0x00000000cb880000, 0x00000000edc00000)   
30.   object space 37376K, 24% used [0x00000000c9400000,0x00000000c9cd12b0,0x00000000cb880000)   
31.  PSPermGen       total 36928K, used 17142K [0x00000000c4200000, 0x00000000c6610000, 0x00000000c9400000)   
32.   object space 36928K, 46% used [0x00000000c4200000,0x00000000c52bdbb0,0x00000000c6610000)  

$ groovysh[GC [PSYoungGen: 14016K->1344K(16320K)] 14016K->1344K(53696K), 0.0072690 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC [PSYoungGen: 15360K->2288K(30336K)] 15360K->4824K(67712K), 0.0183850 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] Groovy Shell (1.7.7, JVM: 1.6.0_25)Type 'help' or '\h' for help.----------------------------------------------------------------------------------------------------------------------------groovy:000> System.gc()[GC [PSYoungGen: 26693K->2288K(30336K)] 29229K->8748K(67712K), 0.0262440 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] [Full GC (System) [PSYoungGen: 2288K->0K(30336K)] [PSOldGen: 6460K->8725K(37376K)] 8748K->8725K(67712K) [PSPermGen: 16933K->16933K(34176K)], 0.1172670 secs] [Times: user=0.11 sys=0.01, real=0.12 secs] ===> nullgroovy:000> System.gc()[GC [PSYoungGen: 2932K->256K(30336K)] 11658K->8981K(67712K), 0.0017600 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [Heap Dump: Dumping heap to java_pid18650.hprof ...Heap dump file created [18535501 bytes in 0.317 secs], 0.3208840 secs][Full GC (System) [PSYoungGen: 256K->0K(30336K)] [PSOldGen: 8725K->8918K(37376K)] 8981K->8918K(67712K) [PSPermGen: 17045K->17045K(38464K)], 0.1131950 secs] [Times: user=0.11 sys=0.00, real=0.11 secs] [Heap DumpDumping heap to java_pid18650.hprof.1 ...Heap dump file created [18440786 bytes in 0.318 secs], 0.3179790 secs]===> nullgroovy:000> System.gc()[GC [PSYoungGen: 1016K->160K(30336K)] 9935K->9078K(67712K), 0.0020120 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [Full GC (System) [PSYoungGen: 160K->0K(30336K)] [PSOldGen: 8918K->9028K(37376K)] 9078K->9028K(67712K) [PSPermGen: 17077K->17077K(36928K)], 0.1111340 secs] [Times: user=0.11 sys=0.00, real=0.11 secs] ===> nullgroovy:000> quitHeap PSYoungGen      total 30336K, used 2427K [0x00000000edc00000, 0x00000000efbe0000, 0x0000000100000000)  eden space 28032K, 8% used [0x00000000edc00000,0x00000000ede5ef68,0x00000000ef760000)  from space 2304K, 0% used [0x00000000ef760000,0x00000000ef760000,0x00000000ef9a0000)  to   space 2304K, 0% used [0x00000000ef9a0000,0x00000000ef9a0000,0x00000000efbe0000) PSOldGen        total 37376K, used 9028K [0x00000000c9400000, 0x00000000cb880000, 0x00000000edc00000)  object space 37376K, 24% used [0x00000000c9400000,0x00000000c9cd12b0,0x00000000cb880000) PSPermGen       total 36928K, used 17142K [0x00000000c4200000, 0x00000000c6610000, 0x00000000c9400000)  object space 36928K, 46% used [0x00000000c4200000,0x00000000c52bdbb0,0x00000000c6610000)

效果是：第二次System.gc()的时候，我们得到了两份HPROF格式的heap dump，而第一次与第三次都没有。

这样就可以很方便的在遇到full GC频繁的时候获取那么一两组heap dump来分析，而不需要在VM启动的时候就指定这两个参数——那样的话dump出来的文件就多了orz

(###)