JVM调优：选择合适的GC collector （一）

骑猪看日落 2021-05-12 11:54 454阅读 0赞

正文之前，先介绍一人：Jon Masamitsu。此人背景不详，不过他在SUN做的就是JVM，所以他的blog我认为是每一个想对JVM调优的人都应该读一读的。本文的很多观点和一些图也是取自他的blog。  
blog link：[http://blogs.sun.com/jonthecollector/ ][http_blogs.sun.com_jonthecollector]  
  
在他的一篇blog【1】中，写到了GC调优的最重要的三个选项：  
排在第三位的是young generation在整个JVM heap中所占的比重；  
排在第二位的是整个JVM heap的大小；  
排在第一位的就是选择合适的GC collector，这也是本文的内容所在。

**基本概念**

先科普一些基本知识。JVM Heap在实现中被切分成了不同的generation（很多中文翻译成‘代’），比如生命周期短的对象会放在young generation，而生命周期长的对象放在tenured generation中，如下图（摘自【2】）。

![Center][]

当GC只发生在young generation中，回收young generation中的对象，称为Minor GC；当GC发生在tenured generation时则称为Major GC或者Full GC。一般的，Minor GC的发生频率要比Major GC高很多。  
关于generation的知识，这里不多谈了，感兴趣的参见【2】，或者很多网上的文章。

![Center 1][]

上图（摘自【3】）很清楚的列出了JVM提供的几种GC collector。

其中负责Young Generation的collector有三种：  
**Serial** ：最简单的collector，只有一个thread负责GC，并且，在执行GC的时候，会暂停整个程序（所谓的“stop-the-world”），如下图所示；

![Center 2][]

Parallel Scavenge：   
和Serial相比，它的特点在于使用multi-thread来处理GC，当然，在执行的时候，仍然会“stop-the-world”，好处在于，暂停的时间也许更短；

![Center 3][]

**ParNew：**   
它基本上和Parallel Scavenge非常相似，唯一的区别，在于它做了强化能够和CMS一起使用；  
  
负责Tenured Generation的collector也有三种：  
**Serial Old：**   
单线程，采用的是mark-sweep-compact回收方法（好吧，我承认我不知道什么是mark-sweep-compact，对我来说，只记住了它是单线程的），图示和Serial类似；

**Parallel Old：**   
同理，多线程的GC collector；

**CMS：**   
全称“concurrent-mark-sweep”，它是最并发，暂停时间最低的collector，之所以称为concurrent，是因为它在执行GC任务的时候，GC thread是和application thread一起工作的，基本上不需要暂停application thread，如下图所示；

![Center 4][]

6种collector介绍完了。不过，在设定JVM参数的时候，很少有人去分别制定young generation和tenured generation的collector，而是提供了几套选择方案：  
**-XX:+UseSerialGC：**   
相当于”Serial” + “SerialOld”，这个方案直观上就应该是性能最差的，我的实验证明也确实如此；  
**-XX:+UseParallelGC：**   
相当于” Parallel Scavenge” + “SerialOld”，也就是说，在young generation中是多线程处理，但是在tenured generation中则是单线程；  
**-XX:+UseParallelOldGC：**   
相当于” Parallel Scavenge” + “ParallelOld”，都是多线程并行处理；  
**-XX:+UseConcMarkSweepGC：**   
相当于"ParNew" + "CMS" + "Serial Old"，即在young generation中采用ParNew，多线程处理；在tenured generation中使用CMS，以求得到最低的暂停时间，但是，采用CMS有可能出现”Concurrent Mode Failure”（这个后面再说），如果出现了，就只能采用”SerialOld”模式了；  
【3】中还提到了一个方案：UseParNewGC，不过我在其它地方很少看见有人用它，就不介绍了。

**实验和结果**

说了这么多，还是用实验验证一下吧。  
被实验的系统可以看做是一个内存数据库，所有的数据和查询都是在内存中进行，测试用的workload即包含将数据写入到内存中，也包含各式各样的查询。这样一个系统和测试数据，在运行过程中，由于处理大量的查询，所以肯定会随时产生很多的短周期对象，所以young generation对应的Minor GC会比较频繁，同时，由于不断有新的数据写入到数据库，而这些数据都属于长周期对象，所以tenured generation的使用率是不断增长。

实验使用的是一台DELL的服务器，有48G内存，有2个CPU，各4个core，所以总共8个core。为了实验的方便，我只是用了大概16G内存给JVM使用。

**SerialGC**

先看第一张图：

![Center 5][]

图中的采样点有些密集，截取其中的一小段放大如下：

![Center 6][]

图的纵轴表示的是系统的throughput，单位是request/second。我设定的计算throughput的时间间隔是5秒，也就是说，图中的每一个点，都是一个5秒时间区间内系统throughput的平均值。  
图的横轴表示的是时间维度。  
后面几张图的设定和这个图是一样的。  
  
这张图采用的是**SerialGC** ，整个JVM的参数设置如下：  
java -jar -Xms10g -Xmx15g \-XX:+UseSerialGC -XX:NewSize=6g -XX:MaxNewSize=6g -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -Xloggc:./log/gc.log Slaver.jar   
  
其中，\-XX:NewSize=6g -XX:MaxNewSize=6g 表示的是将young generation的初始化size和最大size都设置成了6G，也就是说在整个系统运行过程中，young generation的size是不会变的。这是因为JVM会根据实际的运行情况动态的调节young generation和tenured generation的比例，而这样的设置能够避免这种动态的调整，便于观察实验结果。  
\-Xms10g -Xmx15g 表示将JVM Heap的初始Size设置为10G，而它的最大Size设置为15G。相当于初始的时候tenured generation的大小约等于(10-6)G，而它可以增长为(15-6)G （只是近似计算，忽略了perm generation的size）。  
\-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -Xloggc:./log/gc.log 这些参数，是将GC的细节和Heap的变化记录到gc.log中。  
Slaver.jar 是俺的程序....  
对于后面的实验，这些参数都不会变动。唯一变动的就只是选择不同的Collector。

OK，回到实验结果图。  
这张图有一个很有趣的现象是它的抖动非常大，几乎总是一个点高，紧挨着一个点就会低。这意味着系统的throughput在不断的震荡。这个现象的原因是实验过程中，Minor GC的发生频率基本上是7-9秒一次（通过log观察到的），而前面提到了我们计算throughput的时间区间是5秒，所以，基本上每隔一个时间区间就会发生一次Minor GC，而发生Minor GC的时间区间它的平均throughput就会降低。  
为了证明这一点，我随意找了一段Minor GC的log：  
900.692: \[GC 900.692: \[DefNew: 5334222K->300781K(5662336K), 0.8988610 secs\] 7654628K->2641401K(9856640K), 0.8990190 secs\] \[Times: **user=0.86** sys=0.03, **real=0.89 secs** \]   
解释一下这段log：  
900.692 表明这次GC发生在系统启动后的900.062秒这一时刻；  
5334222K->300781K(5662336K) 表明young generation在这次GC中从5334222K降低到了300781K，而young generation的size是5662336K（注意，这个值近似于我们之前设定的6G），这个过程花费了0.8988610秒；  
7654628K->2641401K(9856640K) 表明这个JVM Heap从7654628K降低到了2641401K（这两个值之差应该和上面的那两个值之差几乎相等，因为这是Minor GC，所以整个Heap清理出的空间其实就是young generation清理出的空间）；  
user=0.86 sys=0.03, real=0.89 secs 表明这次GC的user time是0.86，而real time是0.89秒 （不理解user/sys/real的见【4】）  
我们之前提到过，SerialGC是需要将整个application暂停的，所以，这次GC将整个application暂停了0.89秒，就是这个暂停导致了系统throughput的下降；

图中更有意思的现象是在横轴1700附近，系统的throughput直线下降到几乎为0。直观的猜测，这里应该是发生了Full GC。果然，在log中找到了它：  
1700.750: \[GC 1700.750: \[DefNew: 5335802K->302541K(5662336K), **0.9367800 secs** \]1701.687: \[Tenured: 4210828K->4211008K(4211008K), **17.6799010 secs** \] 9526754K->4513370K(9873344K), \[Perm : 11048K->11048K(21248K)\], 18.6220490 secs\] \[Times: **user=18.61** sys=0.01, **real=18.62 secs** \].   
  
这里最重要的是这句：\[Tenured: 4210828K->4211008K(4211008K), 17.6799010 secs\] ，表示对tenured generation进行了GC，花费了17.6799010秒（由于我写入的数据是要一直保存的，所以这次GC几乎没有在tenured generation中清除任何的dead object，所以下降幅度不大4210828K->4211008K）。  
而这次GC总的花费了18.62 secs，意味着系统在这18秒内都被暂停了，在这18秒内系统几乎没有任何的throughput。所以，采用Seral GC，意味着系统在发生Full GC的时候，将会有大概十几秒的时间对外界的请求没有响应，如果是一个Web Server的话，意味着这十几秒用户没法浏览网页。这个感觉可不好。  
  
此外，log还记录了Full GC发生前后Heap的情况：  
\{Heap before GC invocations=204 (full 0):  
...........................................  
tenured generation   **total 4194304K** , used 4190951K \[0x00007fe2c82e0000, 0x00007fe3c82e0000, 0x00007fe5082e0000)  
   the space 4194304K,  **99% used **\[0x00007fe2c82e0000, 0x00007fe3c7f99dd8, 0x00007fe3c7f99e00, 0x00007fe3c82e0000)  
........................................  
........................................  
Heap after GC invocations=205 (full 1):  
....................................................................  
tenured generation   **total 7018348K** , used 4211008K \[0x00007fe2c82e0000, 0x00007fe4748bb000, 0x00007fe5082e0000)  
   the space 7018348K,  **59% used** \[0x00007fe2c82e0000, 0x00007fe3c9330000, 0x00007fe3c9330000, 0x00007fe4748bb000)  
......................................................  
\}   
从log可以看到，在GC发生之前，Heap里面的tenured generation的占用率已经到了99%，意味着tenured generation已经满了。所以，可以判断出，Full GC发生的条件就是tenured generation已经满了。  
而在GC发生之后，发现total space从4194304K增长到了7018348K。还记得吗，我们在设置JVM的时候，初始Heap的Size是10G，最大的Size是15G，那多出的5G就是用于generation的增长的。

最后，你能够发现，无论是Minor GC还是Major GC，它的user time和real time的值相差不大，如果你了解user time和real time的意义，就能够知道这意味着GC这个任务是有单线程执行的，才会出现这种情况。这也和SerialGC的概念相吻合了。

（未完待续）

**Reference：**

【1】[The Second Most Important GC Tuning Knob][]   
【2】[Java SE 6 HotSpot\[tm\] Virtual Machine Garbage Collection Tuning ][Java SE 6 HotSpot_tm_ Virtual Machine Garbage Collection Tuning]  
【3】[Our Collectors][]   
【4】 [user / sys /real time][user _ sys _real time]

[http_blogs.sun.com_jonthecollector]: http://blogs.sun.com/jonthecollector/
[Center]: /images/20210511/83daabb6fb0847a8b6cfc9c39a767b4b.png
[Center 1]: /images/20210511/41918c357c5d431d94e73f1202bd4e28.png
[Center 2]: /images/20210511/6c92005739ff4506aefcb5b67164d1c9.png
[Center 3]: /images/20210511/7db6382f687842589905f46c404fd859.png
[Center 4]: /images/20210511/e6e1b20ab12e45708514a3ad882ef114.png
[Center 5]: /images/20210511/3fe9928217ca42c58ba67834c2e7ceb1.png
[Center 6]: /images/20210511/c4e084867db24e9187940be7ea57de60.png
[The Second Most Important GC Tuning Knob]: http://blogs.sun.com/jonthecollector/entry/the_second_most_important_gc
[Java SE 6 HotSpot_tm_ Virtual Machine Garbage Collection Tuning]: http://www.oracle.com/technetwork/java/javase/gc-tuning-6-140523.html
[Our Collectors]: http://blogs.sun.com/jonthecollector/entry/our_collectors
[user _ sys _real time]: http://stackoverflow.com/questions/556405/what-do-real-user-and-sys-mean-in-the-output-of-time1