2015-11-06

JVM监控与调优

题外话

本文当前的范围是Java 8之前的虚拟机，因为Java 8之后虚拟机的架构有比较大的调整，存储类的元数据信息的永久代被删除了，而是放在虚拟机的元空间。
JDK 7及之前的版本中永久代有如下的特点：

永久代和堆在内存分配上是相连的；
永久代的垃圾回收和老年代的垃圾回收是绑定的，一旦其中一个区域被占满，这两个区都要进行垃圾回收；
永久代一段连续的内存空间，在32位机器默认的永久代的大小为64M，64位的机器则为85M；当然，在JVM启动之前可以通过设置-XX:MaxPermSize的值来控制永久代的大小；

Java虚拟机

Java虚拟机的架构如下图，其中和性能调优相关的组件有三个：Heap，JIT compiler 和 Garbage Collector。
这是一张图片

针对内存堆heap中创建的Java对象，采用的是垃圾回收机制进行处理。垃圾回收在Oracle官网叫 Automatic Garbage Collection，其目的寻找确定堆内存中哪些对象在使用，哪些不在使用，并且删除销毁那些不在使用的对象。
垃圾回收分为三步：

标记，Marking
这个阶段识别出哪些对象正在使用，哪些对象不再使用，不再使用的对象标记为可回收的对象，在使用的对象标记为不可回收。在标记阶段需要对所有的对象进行全扫描来做决策。
清除，Normal Deletion
这个阶段移除那些没有被引用的Java对象，并释放内存空间。
压缩，Deletion with Compacting
为了更好的性能，需要对不可回收依然使用的对象进行压缩，就是把这一类对象迁移在一起，使得新内存的分配变得的更容易和更快。

分代垃圾回收(Generational Garbage Collection)

由于标记和压缩堆内存中所有的对象是十分低效的，并且随着越来越多的对象被分配，垃圾回收的时间也会变得越来越长，因此引入引入了如下的回收策略：按着对象存活的时间窗口采用不同的垃圾回收机制，即是 Minor collections 和 Major collections。如下图：
这是一张图片
其中Y轴标识已分配的字节数，X轴标识随着时间已经被分配内存并且处于使用状态的字节数的情况。从这张图可以看出，只有很少的对象能够长时间需要保留下来，大部分对象只有很短的生命周期。

Java Hotspot Heap结构：
这是一张图片
Hotspot内存由三部分组成：

持久代，Permanent Generation：存储类和对象元数据的数据的地方，包括类的层级信息，方法数据和方法信息（如字节码，栈和变量大小），运行时常量池，已确定的符号引用和虚方法表。
年轻代，Young Generation：分为三个区，一个Eden区，两个Survivor区。新生代主要是存放新生成的Java对象，新生代的垃圾回收称为 minor garbage collection。
年老代，Old Genration：即是Tenured区，存放在年轻代经过多次垃圾回收依然存活的对象的区域，年老代的垃圾回收称为 major garbage collection。

垃圾回收触发时机

Minor Collection
在Eden空间已满，新对象申请空间失败时，就会触发Minor Collection，对Eden区域进行GC，清除非存活对象，并把尚且存活的对象移动到Survivor区。然后整理Survivor的两个区。这种方式的GC是对年轻代的Eden区进行，不会影响到年老代。因为大部分对象都是从Eden区开始的，同时Eden区不会分配的很大，所以Eden区的GC会频繁进行。因而，一般在这里需要使用速度快、效率高的算法，使Eden去能尽快空闲出来。

Major Collection(Full GC)
对整个堆进行整理，包括Young、Tenured和Perm。Major Collection因为需要对整个对进行回收，所以比Minor Collection要慢，因此应该尽可能减少Full GC的次数。在对JVM调优的过程中，很大一部分工作就是对于Major Collection的调节。有如下原因可能导致Full GC：

年老代（Tenured）被写满;
持久代（Perm）被写满;
System.gc()被显示调用;
上一次GC之后Heap的各域分配策略动态变化;

Garbage Collector

经过发展，Java已有如下的垃圾回收器：

Serial收集器/SerialOld收集器
Serial收集器/Serial Old收集器，是单线程的，使用“复制”算法。当它工作时，必须暂停其它所有工作线程。特点：简单而高效。对于运行在Client模式下的虚拟机来说是一个很好的选择。
串行收集器并不是只能使用一个CPU进行收集，而是当JVM需要进行垃圾回收的时候，需要中断所有的用户线程，知道它回收结束为止，因此又号称“Stop The World” 的垃圾回收器。
Serial收集器默认新旧生代的回收器搭配为Serial+ SerialOld
ParNew收集器
ParNew收集器其实就是多线程版本的Serial收集器，同样有
Stop The World的问题，他是多CPU模式下的首选回收器（该回收器在单CPU的环境下回收效率远远低于Serial收集器，所以一定要注意场景哦），也是Server模式下默认的新生代收集器。除了Serial收集器外，目前只有它能与CMS收集器配合工作。
ParallelScavenge/ParallelOld收集器
ParallelScavenge又被称为是吞吐量优先的收集器，也是使用“复制”算法的、并行的多线程收集器。这些都和ParNew收集器一样。但它关注的是吞吐量（CPU用于运行用户代码的时间与CPU总消耗时间的比值），而其它收集器（Serial/Serial Old、ParNew、CMS）关注的是垃圾收集时用户线程的停顿时间。
Parallel Old收集器是Parallel Scavenge收集器的老年代版本。
CMS
CMS(Concurrent Mark Sweep）)又称响应时间优先(最短回收停顿)的回收器，使用并发模式回收垃圾，使用”标记-清除“算法，CMS对CPU是非常敏感的，它的回收线程数=（CPU+3）/4，因此当CPU是2核的实惠，回收线程将占用的CPU资源的50%，而当CPU核心数为4时仅占用25%。
CMS收集器分4个步骤进行垃圾收集工作：
a. 初始标记(CMS initial mark)
b. 并发标记(CMS concurrent mark)
c. 重新标记(CMS remark)
d. 并发清除(CMS concurrent sweep)
GarbageFirst(G1)
G1（Garbage First）收集器，基于“标记-整理”算法，可以非常精确地控制停顿。其实这是一个新的垃圾回收器，既可以回收新生代也可以回收旧生代，SunHotSpot 1.6u14以上EarlyAccess版本加入了这个回收器

监控命令

JDK自带的性能调优监控工具，包括：VisualVM、jConsole、jps、jstack、jmap、jhat、jstat、hprof等。
jstack 主要用于查看Java进程内的线程堆栈信息。
例子：

# jps
6923 HelloWorld
14009 Jps

# jstack -m 6923

jmap 主要用于查看堆内存的使用情况。
例子：

# jmap -heap 6923 
Attaching to process ID 6923, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 24.65-b04

using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC

Heap Configuration:
   MinHeapFreeRatio = 40
   MaxHeapFreeRatio = 70
   MaxHeapSize      = 25769803776 (24576.0MB)
   NewSize          = 2147483648 (2048.0MB)
   MaxNewSize       = 2147483648 (2048.0MB)
   OldSize          = 5439488 (5.1875MB)
   NewRatio         = 2
   SurvivorRatio    = 8
   PermSize         = 21757952 (20.75MB)
   MaxPermSize      = 85983232 (82.0MB)
   G1HeapRegionSize = 0 (0.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 1932787712 (1843.25MB)
   used     = 1216988784 (1160.6109466552734MB)
   free     = 715798928 (682.6390533447266MB)
   62.96546570759655% used
Eden Space:
   capacity = 1718091776 (1638.5MB)
   used     = 1210401768 (1154.3290786743164MB)
   free     = 507690008 (484.1709213256836MB)
   70.45035573233545% used
From Space:
   capacity = 214695936 (204.75MB)
   used     = 6587016 (6.281867980957031MB)
   free     = 208108920 (198.46813201904297MB)
   3.068067389966804% used
To Space:
   capacity = 214695936 (204.75MB)
   used     = 0 (0.0MB)
   free     = 214695936 (204.75MB)
   0.0% used
concurrent mark-sweep generation:
   capacity = 23622320128 (22528.0MB)
   used     = 9615124536 (9169.697319030762MB)
   free     = 14007195592 (13358.302680969238MB)
   40.703556991436265% used
Perm Generation:
   capacity = 64733184 (61.734375MB)
   used     = 39187912 (37.37250518798828MB)
   free     = 25545272 (24.36186981201172MB)
   60.537593825139204% used

11258 interned Strings occupying 1021928 bytes.

jstat 主要用于查看Java进程的统计信息。

例子1：

# jstat -gc 6923 2000 200000
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       PC     PU    YGC     YGCT    FGC    FGCT     GCT   
209664.0 209664.0 83598.2 39179.8 1677824.0 1677824.0 23068672.0 10786771.2 64496.0 38947.4  21541 11322.520   6     35.315 11357.835
209664.0 209664.0  0.0   48833.8 1677824.0 502293.9 23068672.0 10787056.8 64496.0 38947.4  21541 11325.066   6     35.315 11360.380
209664.0 209664.0  0.0   48833.8 1677824.0 1013386.7 23068672.0 10787056.8 64496.0 38947.4  21541 11325.066   6     35.315 11360.380
209664.0 209664.0  0.0   48833.8 1677824.0 1515312.1 23068672.0 10787056.8 64496.0 38947.4  21541 11325.066   6     35.315 11360.380
209664.0 209664.0 79664.9  0.0   1677824.0 363216.4 23068672.0 10787062.6 64496.0 38947.4  21542 11325.180   6     35.315 11360.494

显示结果标题栏字段含义：
S0C：Survivor 0区容量(Capacity)。
S1C：Survivor 1区容量(Capacity)。
S0U：Survivor 0区使用量(Used)。
S1U：Survivor 1区使用量(Used)。
EC： Eden区容量。
EU： Eden区使用量。
OC： Old区容量。
OU： Old区使用量。
PC： Perm区容量。
PU： Perm区使用量。
YGC： Young GC次数。
YGCT：Young GC耗时。
FGC： Full GC次数。
FGCT：Full GC耗时。
GCT： GC总耗时。

例子2：

# jstat -gcutil 6923 2000 1000
  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT   
  1.73   0.00  70.22  40.62  99.85   2764  125.732     0    0.000  125.732
  1.73   0.00  70.22  40.62  99.85   2764  125.732     0    0.000  125.732
  1.73   0.00  70.22  40.62  99.85   2764  125.732     0    0.000  125.732
  1.73   0.00  70.22  40.62  99.85   2764  125.732     0    0.000  125.732
  1.73   0.00  70.22  40.62  99.85   2764  125.732     0    0.000  125.732
  1.73   0.00  70.36  40.62  99.85   2764  125.732     0    0.000  125.732
  1.73   0.00  70.36  40.62  99.85   2764  125.732     0    0.000  125.732
  1.73   0.00  70.36  40.62  99.85   2764  125.732     0    0.000  125.732
  1.73   0.00  70.39  40.62  99.85   2764  125.732     0    0.000  125.732
  1.73   0.00  70.42  40.62  99.85   2764  125.732     0    0.000  125.732
  1.73   0.00  70.80  40.62  99.85   2764  125.732     0    0.000  125.732
  1.73   0.00  70.80  40.62  99.85   2764  125.732     0    0.000  125.732
  1.73   0.00  71.04  40.62  99.85   2764  125.732     0    0.000  125.732
  1.73   0.00  71.17  40.62  99.85   2764  125.732     0    0.000  125.732

GC 日志输出参数配置

打开 -verbose:gc 开关可显示GC的操作内容，包括最忙和最空闲收集行为发生的时间、收集前后的内存大小、收集需要的时间等。
打开 -xx:+printGCdetails 开关，可以详细了解GC中的变化。
打开 -XX:+PrintGCTimeStamps 开关，可以了解这些垃圾收集发生的时间，自JVM启动以后以秒计量。
打开 -xx:+PrintHeapAtGC 开关了解堆的更详细的信息。
打开 -XX:+PrintTenuringDistribution 开关了解获得使用期的对象权。
打开 -Xloggc:/var/log/gclogs/gc.log gc日志产生的路径
打开 -XX:+PrintGCApplicationStoppedTime 输出GC造成应用暂停的时间
打开 -XX:+PrintGCDateStamps GC发生的时间信息

GC 日志输出样例

Minor GC日志：

2015-05-08T15:50:10.113+0800: 5.930: [GC2015-05-08T15:50:10.113+0800: 5.930: [ParNew: 174706K->16932K(184320K), 0.0309770 secs] 201085K->43310K(1028096K), 0.0311100 secs] [Times: user=0.14 sys=0.00, real=0.03 secs]

表示发生一次Minor GC，ParNew是新生代的gc算法，174706K表示Eden区的存活对象的内存总和，16932K表示回收后的存活对象的内存总和，184320K是整个eden区的内存总和。0.0309770 secs表示minor gc花费的时间。
201085K->43310K(1028096K) 表明这个JVM Heap从 201085K 降低到了 43310K。
[Times: user=0.14 sys=0.00, real=0.03 secs]表明这次GC的user time是0.14，而real time是0.03秒；( user/sys/real 的解释参见：http://stackoverflow.com/questions/556405/what-do-real-user-and-sys-mean-in-the-output-of-time1 )

Full GC日志：

2015-04-08T17:31:19.816+0800: 8317.639: [Full GC2015-04-08T17:31:19.816+0800: 8317.639: [CMS: 603725K->464743K(843776K), 0.6577700 secs] 788045K->464743K(1028096K), [CMS Perm : 40447K->40446K(67100K)], 0.6579650 secs] [Times: user=0.54 sys=0.00, real=0.65 secs]

最前面的数字 8317.639 代表GC发生的时间，是从Java虚拟机启动以来经过的秒数；
表示发生了一次Full GC，有Full说明发生了Stop-The-World，，如果是调用system.gc()方法所触发的收集，将显示(System)；
整个JVM都停顿了 0.6577700 秒，输出说明同上。只是 CMS: 603725K->464743K(843776K), 0.6577700 secs 表示的是Old区。788045K->464743K(1028096K) 表示的是整个Heap区。
CMS Perm表示GC发生的区域，名称是由收集器决定的。

参考：

http://docs.oracle.com/javase/8/docs/technotes/guides/vm/gctuning/generations.html
http://www.oracle.com/webfolder/technetwork/tutorials/obe/java/gc01/index.html
http://www.oracle.com/technetwork/java/gc-tuning-5-138395.html
http://www.oracle.com/technetwork/java/javase/gc-tuning-6-140523.html
http://www.infoq.com/cn/articles/Java-PERMGEN-Removed
http://docs.oracle.com/cd/E21764_01/web.1111/e13814/jvm_tuning.htm#PERFM169
http://blog.csdn.net/ning109314/article/details/10411495
http://jbutton.iteye.com/blog/1569746
http://buddie.iteye.com/blog/1824937
http://www.cnblogs.com/ggjucheng/p/3977384.html
http://blog.csdn.net/historyasamirror/article/details/6233007
http://sargeraswang.com/blog/2014/02/03/la-ji-shou-ji-qi-yu-nei-cun-fen-pei-ce-lue/

On The Open Way

自信人生二百年，会当水击三千里！