老李分享：《Java Performance》笔记2——JVM命令行选项及垃圾收集日志解析 2

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 secondsApplication 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 testremote2622 jstatdjps返回jstatd，则说明远程系统上的jstatd已经配置成功，启动VisualVM创建远程连接即可进行远程监控。