4.Throughput垃圾收集器输出日志详解:

使用Throughput垃圾收集器(JVM命令行选项:-XX:+UseParallelGC或-XX:+UseParallelOldGC -XX:+PrintGCDetails -verbose:gc),垃圾收集器输出日志格式化如下:

(1).Minor GC日志详解:

[GC 

[PSYoungGen: 15424K->640K(17280K)] 

26822K->19050K(35712K), 0.0260617 secs] 

[Times: user=0.06 sys=0.00, real=0.03 secs] 

A.标签GC说明这是Minor GC的日志输出.

B.第2行[PSYoungGen: 15424K->640K(17280K)]是新生代信息,PSYoungGen表示新生代使用的是多线程垃圾收集器Parallel Scavenge(使用-XX:+UseParallelGC或-XX:+UseParallelOldGC自动开启),”->”左边的26822K是垃圾收集前新生代的占用量,”->”右边的640K是垃圾收集后新生代的占用量。新生代进一步被分为Eden和2块Survivor,因为Minor GC之后Eden为空,所以此处的630K也是Survivor的占用量,括号中的17280K是Eden和一块正被占用的Survivor的和。

C.第3行26822K->19050K(35712K)是垃圾收集前后java堆(新生代和老年代的占用量总和)的使用情况,以及java堆的大小(新生代和老年代的总和)。”->”左边的26822K是垃圾收集前java堆的占用量,”->”右边的19050K是垃圾收集后java堆的占用量,括号中的35712K是java堆总量。

通过java堆大小和新生代大小可以计算出老年代大小,例如新生代大小为17280K,堆大小为35712K,则老年代大小=35712K - 17280K = 18432K.

D.第4行[Times: user=0.06 sys=0.00, real=0.03 secs] 是CPU使用时间,user是垃圾收集使用的用户态CPU时间,sys是垃圾收集使用的系统态CPU时间,real是垃圾收集实际执行时间。

(2).Full GC日志详解:

[Full GC 

[PSYoungGen: 640K->615K(17280K)] 

[PSOldGen: 18410K->18432K(32704K)] 

19050K->19047K(49984K) 

[PSPermGen: 2148K->2148K(12288K)], 0.0379846 secs]

[Times: user=0.03 sys=0.00, real=0.03 secs] 

A.标签Full GC说明这是Full GC的日志输出。

B.第2行的PSYoungGen是新生代的信息,Full GC会对新生代、老年代和永久代都进行垃圾收集。

C.第3行的PSOldGen: 18410K->18432K(32704K)是老年代信息,PSOldGen表明老年代使用的是多线程垃圾收集器Parallel Old(通过-XX:+UseParallelOldGC开启),”->”左边的18410K是垃圾收集前老年代占用量,”->”右边的18432K垃圾收集后老年代占用量,括号中的32704K是老年代大小。

D.第4行19050K->19047K(49984K)是java堆的使用情况,与之前Minor GC的含义相同。

E.第5行PSPermGen: 2148K->2148K(12288K)]是永久代信息,PSPermGen表明永久代使用的是多线程垃圾收集器Parallel Old,”->”左边的2148K是垃圾收集前永久代占用量,”->”右边的2148K垃圾收集后永久代占用量,括号中的12288K是永久代大小。

F.第6行是垃圾收集CPU使用时间,与之前Minor GC的含义相同。

5.CMS垃圾收集器输出日志详解:

使用CMS垃圾收集器(JVM命令行选项:-XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -verbose:gc),垃圾收集器输出日志格式化如下:

(1).Minor GC日志详解:

[GC 

[ParNew: 14784K->1600K(14784K), 0.0184961 secs] 

38262K->31810K(63936K), 0.0185291 secs] 

[Times: user=0.06 sys=0.00, real=0.00 secs] 

A. 标签GC表明这是Minor GC的日志输出。

B. 第2行ParNew: 14784K->1600K(14784K)是新生代信息,如果使用CMS并发垃圾收集器,新生代会自动使用多线程的垃圾收集器ParNew(使用-XX:+UseParNewGC开启),ParNew表示为了配合CMS垃圾收集器在新生代使用的是多线程垃圾胡搜机器ParNew,如果配合CMS使用的是串行垃圾收集器,这里的标签则为DefNew。”->”左边的14784K是垃圾收集前新生代占用量,”->”右边的1600K是垃圾收集后新生代占用量即Survivor的占用量,括号中的14784K是新生代大小。

C. 第3行38262K->31810K(63936K)是垃圾收集前后java堆的占用量和java堆的大小,与前面的Throughput中的含义相同。

D. 第4行是垃圾收集CPU使用时间,与之前Throughput中的含义相同。

(2).Full GC日志详解:

[GC 

[1 CMS-initial-mark: 30210K(49152K)] 31810K(63936K), 0.0015854 secs] 

[Times: user=0.00 sys=0.00, real=0.00 secs] 

[CMS-concurrent-mark: 0.098/0.098 secs] 

[Times: user=0.36 sys=0.00, real=0.11 secs] 

[CMS-concurrent-preclean: 0.001/0.001 secs] 

[Times: user=0.00 sys=0.00, real=0.00 secs] 

[GC

[YG occupancy: 2116 K (14784 K)]

[Rescan (parallel) , 0.0005306 secs]

[weak refs processing, 0.0000034 secs] 

[1 CMS-remark: 30210K(49152K)] 32326K(63936K), 0.0005675 secs] 

[Times: user=0.00 sys=0.00, real=0.00 secs] 

[CMS-concurrent-sweep: 0.021/0.021 secs] 

[Times: user=0.13 sys=0.00, real=0.03 secs] 

[CMS-concurrent-reset: 0.000/0.000 secs] 

[Times: user=0.00 sys=0.00, real=0.00 secs] 

A.第2行[1 CMS-initial-mark: 30210K(49152K)] 31810K(63936K)是CMS初始标记阶段,30210K是垃圾收集前老年代占用量,49152K老年代大小,31810K是垃圾收集前堆占用,括号中的63936K是java堆大小。

B.第4行CMS-concurrent-mark是CMS并发标记阶段。

C.第6行CMS-concurrent-preclean是CMS的并发预清除阶段。

D.第12行1 CMS-remark: 30210K(49152K)] 32326K(63936K)是CMS的重新标记阶段,30210K是垃圾收集前老年代占用量,49152K老年代大小,32326K是垃圾收集前堆占用,括号中的63936K是java堆大小。

E.第14行CMS-concurrent-sweep是CMS的并发清除阶段。

F.第16行CMS-concurrent-reset是CMS最后阶段,为下一轮并发收集周期做准备。

CMS垃圾收集周期中堆减少量,需要通过CMS开始和结束的Minor GC来观察。

6.包含时间戳的垃圾收集日志:

还是以Throughput为例,说明两种包含时间戳的垃圾收集日志:

(1).输出自JVM启动以来到垃圾收集之间流逝的秒数:

使用-XX:+PrintGCTimeStamps结合-XX:+PrintGCDetails 的JVM命令行选项,可以在垃圾收集日志中输出自JVM启动以来到垃圾收集之间流逝的秒数,垃圾收集日志如下:

0.479: [GC 

[PSYoungGen: 8959K->640K(8960K)] 12468K->8096K(19904K), 0.0081423 secs] 

[Times: user=0.03 sys=0.00, real=0.01 secs] 

0.487: [Full GC 

[PSYoungGen: 640K->0K(8960K)] 

[PSOldGen: 7456K->8094K(17088K)] 8096K->8094K(26048K) 

[PSPermGen: 2148K->2148K(12288K)], 0.0154271 secs] 

[Times: user=0.02 sys=0.00, real=0.02 secs] 

(2).输出符合ISO8601标准的时间戳:
使用-XX:+PrintGCDateStamps结合-XX:+PrintGCDetails的JVM命令行选项,可以在垃圾收集日志中输出形如YYYY-MM-DD-T-HH-MM-SS.mmm-TZ的时间戳,垃圾收集日志如下:

2015-05-13T14:51:04.781+0800: [GC 

[PSYoungGen: 8950K->640K(8960K)] 

12472K->8100K(19904K), 0.0075851 secs] 

[Times: user=0.06 sys=0.00, real=0.01 secs] 

2015-05-13T14:51:04.796+0800: [Full GC 

[PSYoungGen: 640K->0K(8960K)]

[PSOldGen: 7460K->8097K(17920K)] 8100K->8097K(26880K) 

[PSPermGen: 2148K->2148K(12288K)], 0.0151887 secs] 

[Times: user=0.01 sys=0.00, real=0.02 secs] 

使用时间戳可以计算Minor GC和Full GC的时间持续时间和频率,并推测它们的预期及进行垃圾收集器调优。

7.将垃圾收集日志保存到文件中:

使用-Xloggc:<filename>的JVM命令行选项,可以将垃圾收集的统计数据直接输出到文件(<filename>是保存的文件名),以便离线分析。结合-Xloggc:<filename>和 -XX:+PrintGCDetails的JVM命令行选项,即使不使用-XX:+PrintGCTimeStamps选项,日志中也会自动添加时间戳,垃圾收集日志如下:

0.266: [GC 

[PSYoungGen: 14464K->640K(17280K)] 

25830K->18558K(35456K), 0.0129438 secs] 

[Times: user=0.00 sys=0.02, real=0.02 secs] 

0.279: [Full GC 

[PSYoungGen: 640K->379K(17280K)] 

[PSOldGen: 17918K->18175K(32896K)] 

18558K->18555K(50176K) 

[PSPermGen: 2148K->2148K(12288K)], 0.0332880 secs]

[Times: user=0.03 sys=0.00, real=0.03 secs] 

垃圾收集日志文件可以使用GCHisto(可以从http://java.net/projects/gchisto下载)读取分析。

8.垃圾收集日志报告应用停止时间和应用并发时间:

通过使用-XX:+PrintGCApplicationConcurrentTime和-XX:+PrintGCApplicationStoppedTime的JVM命令行选项,同时结合-XX:+PrintGCDetails可以报告应用在安全点操作之间的运行时间,以及阻塞java线程的时间,日志格式如下:

Application time: 0.0296541 seconds

[GC 

[PSYoungGen: 4160K->638K(4800K)] 

4160K->2216K(15744K), 0.0053580 secs] 

[Times: user=0.00 sys=0.00, real=0.00 secs] 

Total time for which application threads were stopped: 0.0054412 seconds

Application time: 0.0113375 seconds

[GC 

[PSYoungGen: 4798K->638K(8960K)] 

6376K->4156K(19904K), 0.0066910 secs] 

[Times: user=0.00 sys=0.00, real=0.00 secs] 

Total time for which application threads were stopped: 0.0068062 seconds

通过观察安全点操作,有助于理解和量化延迟对JVM的影响,也可以用来辨别是JVM安全点操作还是应用程序引入的延迟。

9.显示垃圾收集:

System.gc()调用引起的显示垃圾收集会在垃圾收集的日志输出中有(System)标记,例子如下:

[Full GC (System) 

[PSYoungGen: 0K->0K(4800K)] 

[PSOldGen: 151K->151K(10944K)] 

151K->151K(15744K) 

[PSPermGen: 2138K->2138K(12288K)], 0.0032678 secs] 

[Times: user=0.02 sys=0.00, real=0.02 secs] 

如果发现垃圾收集是显示调用引起的,可以调查原因,然后决定是从源码中移除System.gc()调用,或是通过-XX:+DisableExplicitGC禁止显示垃圾收集。

10.VisualVM远程连接监控:

(1).使用jstatd远程监控:

VisualVM远程连接监控时,必须在远程系统运行后台程序jstatd,jstatd虽然JDK5和JDK6发布,但是不包括在Java5或Java6的JRE中。

jstatd会启动Java RMI服务器,监控HotSpot VM的创建和终止,并为远程监控工具如VisualVM提供关联和监控远程java应用的接口。运行jstatd必须和运行被监控的java应用具有相同的用户凭证,因此必须部署安全管理器和安全策略文件,安全策略文件例子如下:

grant codebase “file:${java.home}/../lib/tools.jar” {

permission java.security.AllPermission;

};

假定上述的安全策略文件被保存为名叫jstatd.policy的文件,则可以使用如下的命令启用该策略并启动jstatd:

jstatd -J-Djava.security.policy=<path to policy file>/jstatd.policy

当远程系统运行jstatd后,可以在本地系统运行jps加远程主机名,验证能否关联远程的jstatd(jps不带主机名参数,列出本地能被监控的应用,如果带主机名参数,返回远程可被监控的java应用),例如远程主机名叫testromete,则例如:

$ jps testremote

2622 jstatd

jps返回jstatd,则说明远程系统上的jstatd已经配置成功,启动VisualVM创建远程连接即可进行远程监控。