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

1.JVM命令行选项：

HotSpot VM运行时系统解析命令行选项，并据此配置HotSpot VM，

HotSpot的命令行选项主要有3类：

A. 标准选项：

JVM规范要求所有的JVM都必须实现的选项，它们在发行版之间保持稳定，但也可能在后续的发行版中被废除。如：-client，-server等等。

B. 非标准选项：

以”-X”为前缀，不保证、也不强制所有JVM实现都必须支持，它可能未经通知就在发行版之间发生改变。如：-Xms，-Xmx等等。

C. 非稳定选项：

以”-XX”为前缀，通常是为了特定需要而对JVM的运行进行校正，并且可能需要有系统配置参数的访问权限，也可能不经通知就在发行版之间发生变动。如：-XX:+DisableExplicitGC，-XX:+AggressiveOpts等等。

命令行选项用于控制HotSpot VM的内部变量，每个变量都有类型和默认值。对于内部变量为布尔类型的选项来说，只要在HotSpot VM命令行上添加或去掉它就可以控制这些变量。对于带有布尔标记的非稳定选项来说，选项名前面的”+”或”-”表示true或false。

对于形如-XX:OptionName=<N>的非稳定选项来说，几乎所有附加选项为整数的选项，整数后面都可以接后缀k、m、g，表示千、百万和十亿。

2.32位与64位JVM：

早期的HotSpot VM是32位JVM，内存地址空间限制为4G，但是实际java堆的大小还进一步受限于底层操作系统，随着服务器系统的内存越来越大，64位HotSpot VM应运而生，它可以突破内存地址空间为4G的限制，可以使JVM使用更多的内存，但是随之而来的是64位JVM也带来了性能损失：HotSpot VM内部java对象表示(称为普通对象指针，Ordinary Object Pointers，oops)的长度从32位变为64位，导致CPU高速缓存行(CPU Cache Line)中可用的oops变少，从而降低了CPU缓存命中率，因此导致64位JVM性能通常比32位JVM性能下降约8%~15%。

为了改善64位JVM性能，OpenJDK和HotSpot VM添加了称为压缩指针(Compressed oops)的新特性，使用-XX:CompressedOops命令行选项开启，使得64位JVM性能等于甚至高于32位JVM。

压缩指针是通过对其(Alignment)和偏移量(Offset)将64位指针压缩为32位，即使用了更小更节省空间的压缩指针代替完整长度的64位指针，使得CPU缓存使用率得以提高，从而提高了性能。

此外，在某些平台上(Intel或AMD x64)，64位JVM可以使用更多的CPU寄存器，避免寄存器卸载(当活跃状态即变量数目超过CPU寄存器时，多出的活跃状态只能存放在内存中，被称为寄存器卸载)，由于CPU寄存器的访问速度高于内存，因此避免寄存器卸载可以让程序运行的更快。

3.CMS垃圾收集过程：

CMS(Concurrent Mark-Sweep GC)是HotSpot VM中的Mostly-Concurrent垃圾收集器，它管理新生代的方式与Parallel收集器和Serial收集器相同，而它在老年代则是尽可能并发执行，每个垃圾收集周期只有两次短的停顿。CMS垃圾收集器分为以下阶段：

A.初始标记：

标记从GC Roots直接可达的老年代对象，需要短暂停顿。

B.并发标记：

标记从初始标记标记的老年代对象可达的存活对象。

C.并发预清除：

为了减少重新标记工作量，完成一些原本在重新标记阶段完成的工作，即重新遍历那些在标记期间因并发而被改掉的对象，可以非常有效地减少重新标记的停顿。

D.重新标记：

因为在并发标记期间应用可能正在运行并更新引用，所以到并发标记结束时，未必所有的存货对象都能确保被标记，因此需要重新标记，即重新遍历所有在并发标记期间有变动的对象并进行最后的标记，追踪更改的对象可以重用数据结构卡表，因为重新标记比初始标记更为重要，因此并发执行以提高效率，需要短暂停顿。

E.并发清除：

清除整个java堆，释放没有迁移的垃圾对象。

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创建远程连接即可进行远程监控。

如下图，右键”远程”>”添加远程主机”：

在打开的添加远程主机窗口中，添加配置了jstatd的远程主机名，如下图：

(2).使用JMX远程监控：

如果远程应用配置了JMX连接，VisualVM也可以通过JMX进行远程连接，同时还可以在Monitor窗口发起垃圾收集或者堆转储的请求。

A.远程系统配置JMX：

为远程系统配置如下启动属性：

com.sun.management.jmxremote.port=<port number>

com.sun.management.jmxremote.ssl=<true | false>

com.sun.management.jmxremote.authenticate=<true | false>

B.配置VisualVM的JMX连接：

在VisualVM的菜单上选择File>Add JMX Connection(添加JMX连接)，如下图：

在添加JMX连接的窗口输入框中添加如下信息：

hostname:<port number>；

显示名称可选，默认使用连接框中的输入；

如果设置了com.sun.management.jmxremote.authenticate=true，则需要输入用户名和口令，如下图：