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.?標(biāo)簽GC表明這是Minor?GC的日志輸出。

B.?第2行ParNew:?14784K->1600K(14784K)是新生代信息，如果使用CMS并發(fā)垃圾收集器，新生代會自動使用多線程的垃圾收集器ParNew(使用-XX:+UseParNewGC開啟)，ParNew表示為了配合CMS垃圾收集器在新生代使用的是多線程垃圾胡搜機(jī)器ParNew，如果配合CMS使用的是串行垃圾收集器，這里的標(biāo)簽則為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初始標(biāo)記階段，30210K是垃圾收集前老年代占用量，49152K老年代大小，31810K是垃圾收集前堆占用，括號中的63936K是java堆大小。

B.第4行CMS-concurrent-mark是CMS并發(fā)標(biāo)記階段。

C.第6行CMS-concurrent-preclean是CMS的并發(fā)預(yù)清除階段。

D.第12行1?CMS-remark:?30210K(49152K)]?32326K(63936K)是CMS的重新標(biāo)記階段，30210K是垃圾收集前老年代占用量，49152K老年代大小，32326K是垃圾收集前堆占用，括號中的63936K是java堆大小。

E.第14行CMS-concurrent-sweep是CMS的并發(fā)清除階段。

F.第16行CMS-concurrent-reset是CMS最后階段，為下一輪并發(fā)收集周期做準(zhǔn)備。

CMS垃圾收集周期中堆減少量，需要通過CMS開始和結(jié)束的Minor?GC來觀察。

6.包含時間戳的垃圾收集日志：

還是以Throughput為例，說明兩種包含時間戳的垃圾收集日志：

(1).輸出自JVM啟動以來到垃圾收集之間流逝的秒數(shù)：

使用-XX:+PrintGCTimeStamps結(jié)合-XX:+PrintGCDetails?的JVM命令行選項，可以在垃圾收集日志中輸出自JVM啟動以來到垃圾收集之間流逝的秒數(shù)，垃圾收集日志如下：

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標(biāo)準(zhǔn)的時間戳：
使用-XX:+PrintGCDateStamps結(jié)合-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的時間持續(xù)時間和頻率，并推測它們的預(yù)期及進(jìn)行垃圾收集器調(diào)優(yōu)。

7.將垃圾收集日志保存到文件中：

使用-Xloggc:<filename>的JVM命令行選項，可以將垃圾收集的統(tǒng)計數(shù)據(jù)直接輸出到文件(<filename>是保存的文件名)，以便離線分析。結(jié)合-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.垃圾收集日志報告應(yīng)用停止時間和應(yīng)用并發(fā)時間：

通過使用-XX:+PrintGCApplicationConcurrentTime和-XX:+PrintGCApplicationStoppedTime的JVM命令行選項，同時結(jié)合-XX:+PrintGCDetails可以報告應(yīng)用在安全點(diǎn)操作之間的運(yùn)行時間，以及阻塞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

通過觀察安全點(diǎn)操作，有助于理解和量化延遲對JVM的影響，也可以用來辨別是JVM安全點(diǎn)操作還是應(yīng)用程序引入的延遲。

9.顯示垃圾收集：

System.gc()調(diào)用引起的顯示垃圾收集會在垃圾收集的日志輸出中有(System)標(biāo)記，例子如下：

[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]?

如果發(fā)現(xiàn)垃圾收集是顯示調(diào)用引起的，可以調(diào)查原因，然后決定是從源碼中移除System.gc()調(diào)用，或是通過-XX:+DisableExplicitGC禁止顯示垃圾收集。

10.VisualVM遠(yuǎn)程連接監(jiān)控：

(1).使用jstatd遠(yuǎn)程監(jiān)控：

VisualVM遠(yuǎn)程連接監(jiān)控時，必須在遠(yuǎn)程系統(tǒng)運(yùn)行后臺程序jstatd，jstatd雖然JDK5和JDK6發(fā)布，但是不包括在Java5或Java6的JRE中。

jstatd會啟動Java?RMI服務(wù)器，監(jiān)控HotSpot?VM的創(chuàng)建和終止，并為遠(yuǎn)程監(jiān)控工具如VisualVM提供關(guān)聯(lián)和監(jiān)控遠(yuǎn)程java應(yīng)用的接口。運(yùn)行jstatd必須和運(yùn)行被監(jiān)控的java應(yīng)用具有相同的用戶憑證，因此必須部署安全管理器和安全策略文件，安全策略文件例子如下：

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

當(dāng)遠(yuǎn)程系統(tǒng)運(yùn)行jstatd后，可以在本地系統(tǒng)運(yùn)行jps加遠(yuǎn)程主機(jī)名，驗(yàn)證能否關(guān)聯(lián)遠(yuǎn)程的jstatd(jps不帶主機(jī)名參數(shù)，列出本地能被監(jiān)控的應(yīng)用，如果帶主機(jī)名參數(shù)，返回遠(yuǎn)程可被監(jiān)控的java應(yīng)用)，例如遠(yuǎn)程主機(jī)名叫testromete，則例如：

$?jps?testremote

2622 jstatd

jps返回jstatd，則說明遠(yuǎn)程系統(tǒng)上的jstatd已經(jīng)配置成功，啟動VisualVM創(chuàng)建遠(yuǎn)程連接即可進(jìn)行遠(yuǎn)程監(jiān)控。

轉(zhuǎn)載于:https://blog.51cto.com/10988776/1746097

總結(jié)

以上是生活随笔為你收集整理的老李分享：《Java Performance》笔记2——JVM命令行选项及垃圾收集日志解析 2的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯，歡迎將生活随笔推薦給好友。