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

上一篇：通过JMX控制在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的帮助文档：

引用

$ jinfo -help
Usage:
    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日志：

+PrintGCDetails

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

$ jps
18711 Jps
18650 GroovyStarter
$ jinfo -flag +HeapDumpBeforeFullGC 18650
$ jinfo -flag +HeapDumpAfterFullGC 18650

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

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

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

$ 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] 
===> null
groovy: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]===> null
groovy: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] 
===> null
groovy:000> quit
Heap
 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

评论

16 楼 Nature_night 2012-04-01  

哦，最近在做即时通信的项目，偶尔会有这方面的问题，造成消息丢失。
很谢谢你的帮忙。

15 楼 RednaxelaFX 2012-04-01  

Nature_night 写道

RednaxelaFX能不能帮忙解决1个题外问题: tcp/ip中tcp重发的次数和超时时间是多少?
(我请教了很多javaeye的朋友都不知道。)

抱歉，这个也不是我的现有知识范围内能解决的…

14 楼 Nature_night 2012-04-01  

非常感谢你细致的回答。

RednaxelaFX能不能帮忙解决1个题外问题: tcp/ip中tcp重发的次数和超时时间是多少?
(我请教了很多javaeye的朋友都不知道。)

问题如下：
TCP/IP中,发送端在发送消息时，如若对方突然拔网线后,tcp的超时重发是9分钟吗?而这一点我们在socket编程中是没法及时获取send失败的,它由tcp协议来控制重发,重发一定次数超时后才通知我们sokcet有问题吧?我查了资料都没讲清楚。

1,server发送端发送消息时, 突然对方拔掉网线。而发送端此时还连接认为是好的，发送消息到缓冲队列，然后由系统层tcp/ip把消息取走并有序的发送数据,等待tcp段的ack确认。
若接收端突然拔网线后,就没有收到ack确认,就启动tcp重发机制和超时。

现在代码里,希望能及时处理这种消息丢失情况,请问RednaxelaFX如何处理较好,谢谢。

2,我查了linux c接口，里面有send timeout选项。而java socket类没有。
并且我怀疑c接口的send timeout选项，可能是指把数据从缓存队列拷到系统层发送。


我现在使用的是mina框架
以上有错误的认识，请RednaxelaFX指明。感激不尽。

13 楼 RednaxelaFX 2012-04-01  

Nature_night 写道

请问: jmap -histo:live <pid>
这也命令不是查看存活的对象吗, 他也会触发来执行一次full GC吗？

哇，我还不知道呢。这命令我经常在用，竟然不清楚原理。惭愧呀

是用来看对象数量和大小的。但你可以无视它的输出，只要它的副作用，就是做full GC。
注意只有加了:live才有效果，不加就没这效果。

12 楼 Nature_night 2012-04-01  

请问: jmap -histo:live <pid>
这也命令不是查看存活的对象吗, 他也会触发来执行一次full GC吗？

哇，我还不知道呢。这命令我经常在用，竟然不清楚原理。惭愧呀

11 楼 RednaxelaFX 2012-04-01  

Nature_night 写道

谢谢RednaxelaFX。
你说的方法我都明白，我是想请教在Groovy Shell里如何针对某个java程序手动调用gc()。
文章中Groovysh没有指定是对哪个java进程进行gc吧?

再次谢谢你的帮忙。

这篇文章是用Groovy shell来演示一个Java进程自己触发full GC。并不是触发别的Java进程做full GC。
要触发别的进程做full GC可以通过JMX来做；当然，Groovy也是可以用JMX去跟别的Java进程连接的。其实更简单的办法是用jmap -histo:live <pid>，这就足以让目标进程做一次full GC了。

10 楼 Nature_night 2012-04-01  

谢谢RednaxelaFX。
你说的方法我都明白，我是想请教在Groovy Shell里如何针对某个java程序手动调用gc()。
文章中Groovysh没有指定是对哪个java进程进行gc吧?

再次谢谢你的帮忙。

9 楼 RednaxelaFX 2012-04-01  

Nature_night 写道

请问，这个可以应用在sun的jdk程序吗？
例如，我的一台server上跑了N个java程序，我要在线不中断某个程序，然后用你的方法监控某个程序是否内存泄露，请问可行吗？ 谢谢。
具体怎么做，能否告诉我方法或者给个链接。

这帖说的就是具体方法了呃

你知道一台server上跑着N个Java程序的话，每个Java程序的pid你也应该知道；不知道的话可以用jps来查询。

对你要关注的进程按这贴的方式执行jinfo让目标进程在full GC前后打出heap dump，
然后离线对heap dump做对比分析（可以用MAT或类似的工具），
在收集到足够数据之后再按这帖的方式用jinfo把full GC前后打heap dump的功能关闭掉。

要注意这样heap dump只会在full GC前后打出；如果你的程序很久都不做full GC那就别用这种方式。
直接用jmap -dump来得更直接些。具体用法请善用搜索引擎。

8 楼 Nature_night 2012-04-01  

请问，这个可以应用在sun的jdk程序吗？
例如，我的一台server上跑了N个java程序，我要在线不中断某个程序，然后用你的方法监控某个程序是否内存泄露，请问可行吗？ 谢谢。
具体怎么做，能否告诉我方法或者给个链接。

非常感谢，RednaxelaFX

7 楼 RednaxelaFX 2011-11-04  

@hittyt
哈哈，原来是你的当前目录下有.hotspotrc里配了+PrintGCDetails，使得jinfo、jps这些工具执行的时候把它们自己的GC heap layout给打印出来了。那些跟你想要的信息是没关系的。

6 楼 RednaxelaFX 2011-11-04  

hittyt 写道

按照你的提示，将原来的jinfo -flag -HeapDumpBeforeFullGC 16540修改为jinfo -flag +HeapDumpBeforeFullGC 16540，得到的控制台输出还是刚才我贴出来的那段，这里，PermGen、
YoungGen、OldGen的大小都是对不上的。

很简单，有两个注意点：

1、你虽然在命令行参数里设置了-XX:+UseConcMarkSweepGC，但实际上GC日志里看到的却是用了ParallelScavenge（也就是-XX:+UseParallelGC，server默认GC）。这足以说明你的命令行参数根本没正确传给你看的JVM。检查一下你是如何启动Java程序的吧，或许你的启动脚本里什么东西写错了。例如我们以前见过的情况就是：

JAVA_OPTS='-XX:+UseConcMarkSweepGC ...'
JAVA_OPTS='$JAVA_OPTS -XX:PermSize=192m ...'
JAVA_OPTS='...'

看到最后那行发生什么事了么？前面设置的JAVA_OPTS全被覆盖了。
也见过脚本写错是把变量名写错了，前面设置的是JAVA_OTPS而后面用的是JAVA_OPTS

2、jinfo -flag +HeapDumpBeforeFullGC <pid>
这句正确执行之后本来就不会在console上输出任何东西。只是开启了VM的heap dump功能就完事了。然后在发生full GC的时候你就应该在Java进程的“工作目录”（或者说“当前目录”）看到相应的heap dump文件。

5 楼 hittyt 2011-11-04  

RednaxelaFX 写道

hittyt 写道

楼主你好，我尝试这按照你说的方法希望找出Full GC时的一些上下文：

jinfo -flag -HeapDumpBeforeFullGC 16540

但是在控制台得到的这些输出好像有些不对头啊。
比如：我的PermSize明明设置成了192m，但这里的PSPermGen显示的total却只有21248K？这是为什么呢？
还有full GC是的heap dump是在哪里生成的呢？我在当前目录下没有看到任何文件生成呢？

+HeapDumpBeforeFullGC才是启用，减号的话是禁用。你确定你前面有用过加号来启用并且随后发生过full GC么？

至于PermGen大小不对，请把完整的启动参数贴出来看看

jvm的启动参数如下：

-server -Xmx2g -Xms2g -Xmn256m -XX:PermSize=192m -Xss256k -XX:+DisableExplicitGC -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled -XX:+UseCMSCompactAtFullCollection -XX:LargePageSizeInBytes=128m -XX:+UseFastAccessorMethods -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=70

按照你的提示，将原来的jinfo -flag -HeapDumpBeforeFullGC 16540修改为jinfo -flag +HeapDumpBeforeFullGC 16540，得到的控制台输出还是刚才我贴出来的那段，这里，PermGen、
YoungGen、OldGen的大小都是对不上的。
至于是否确认进行了FullGC，我是使用jstat -gcutil来统计的GC次数，具体的信息如下：

jstat -gcutil 16540 5s 10
[GC [PSYoungGen: 4032K->480K(4672K)] 4032K->480K(7552K), 0.0017910 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT   
 92.94   0.00  82.12  63.19  72.48   7422  138.845   292    7.029  145.874
 73.05   0.00  63.06  64.12  72.48   7424  138.877   292    7.029  145.906
 53.76   0.00  56.87  65.08  72.48   7426  138.906   292    7.029  145.936
100.00   0.00  49.34  65.57  72.48   7428  138.939   292    7.029  145.968
 70.13   0.00  78.23  67.23  72.49   7430  138.974   292    7.029  146.003
 94.27   0.00  55.79  68.41  72.49   7432  139.007   292    7.029  146.036
100.00   0.00  35.08  69.19  72.49   7434  139.051   292    7.029  146.080
  0.00 100.00  35.76  70.35  72.49   7435  139.104   293    7.047  146.151
 69.75   0.00  35.95  70.54  72.49   7436  139.128   293    7.047  146.175
[GC [PSYoungGen: 4512K->464K(8448K)] 4512K->464K(11328K), 0.0022880 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
  0.00  82.30  43.67  43.73  72.49   7437  139.140   294    7.071  146.210
Heap
 PSYoungGen      total 8448K, used 719K [0x00002aaae8b60000, 0x00002aaae9460000, 0x00002aab03600000)
  eden space 7936K, 3% used [0x00002aaae8b60000,0x00002aaae8b9fec0,0x00002aaae9320000)
  from space 512K, 90% used [0x00002aaae93e0000,0x00002aaae9454018,0x00002aaae9460000)
  to   space 640K, 0% used [0x00002aaae9320000,0x00002aaae9320000,0x00002aaae93c0000)
 PSOldGen        total 2880K, used 0K [0x00002aaab3600000, 0x00002aaab38d0000, 0x00002aaae8b60000)
  object space 2880K, 0% used [0x00002aaab3600000,0x00002aaab3600000,0x00002aaab38d0000)
 PSPermGen       total 21248K, used 4208K [0x00002aaaae200000, 0x00002aaaaf6c0000, 0x00002aaab3600000)
  object space 21248K, 19% used [0x00002aaaae200000,0x00002aaaae61c160,0x00002aaaaf6c0000)

这个是之前统计的50s内的GC情况。

4 楼 RednaxelaFX 2011-11-04  

hittyt 写道

楼主你好，我尝试这按照你说的方法希望找出Full GC时的一些上下文：

jinfo -flag -HeapDumpBeforeFullGC 16540

但是在控制台得到的这些输出好像有些不对头啊。
比如：我的PermSize明明设置成了192m，但这里的PSPermGen显示的total却只有21248K？这是为什么呢？
还有full GC是的heap dump是在哪里生成的呢？我在当前目录下没有看到任何文件生成呢？

+HeapDumpBeforeFullGC才是启用，减号的话是禁用。你确定你前面有用过加号来启用并且随后发生过full GC么？

至于PermGen大小不对，请把完整的启动参数贴出来看看

3 楼 hittyt 2011-11-04  

楼主你好，我尝试这按照你说的方法希望找出Full GC时的一些上下文：

jinfo -flag -HeapDumpBeforeFullGC 16540
Heap
 PSYoungGen      total 23872K, used 2867K [0x00002aaae8b60000, 0x00002aaaea600000, 0x00002aab03600000)
  eden space 20480K, 14% used [0x00002aaae8b60000,0x00002aaae8e2cea8,0x00002aaae9f60000)
  from space 3392K, 0% used [0x00002aaaea2b0000,0x00002aaaea2b0000,0x00002aaaea600000)
  to   space 3392K, 0% used [0x00002aaae9f60000,0x00002aaae9f60000,0x00002aaaea2b0000)
 PSOldGen        total 54656K, used 0K [0x00002aaab3600000, 0x00002aaab6b60000, 0x00002aaae8b60000)
  object space 54656K, 0% used [0x00002aaab3600000,0x00002aaab3600000,0x00002aaab6b60000)
 PSPermGen       total 21248K, used 3607K [0x00002aaaae200000, 0x00002aaaaf6c0000, 0x00002aaab3600000)
  object space 21248K, 16% used [0x00002aaaae200000,0x00002aaaae585ee0,0x00002aaaaf6c0000)

但是在控制台得到的这些输出好像有些不对头啊。
比如：我的PermSize明明设置成了192m，但这里的PSPermGen显示的total却只有21248K？这是为什么呢？
还有full GC是的heap dump是在哪里生成的呢？我在当前目录下没有看到任何文件生成呢？

2 楼 RednaxelaFX 2011-05-23  

ordinary 写道

没懂，怎么出了个groovy?

方便做实验而已。Groovy也是跑在JVM上的，用它的shell能很方便的触发System.gc()。
换用Java写的话，

System.gc();
System.in.read();System.in.read();
System.gc();
System.in.read();System.in.read();
System.gc();

1 楼 ordinary 2011-05-23  

没懂，怎么出了个groovy?