频繁GC (Allocation Failure)及young gc时间过长分析

序

本文主要分析一个频繁GC (Allocation Failure)及young gc时间过长的case。html

症状

gc throughput percent逐步降低，从通常的99.96%逐步降低，跌破99%，进入98%，最低点能到94%
young gc time逐步增长，从通常的十几毫秒逐步上升，突破50，再突破100，150，200，250
在8.5天的时间内，发生了9000屡次gc，其中full gc为4次，平均将近8秒，大部分是young gc(allocation failure为主)，平均270多毫秒，最大值将近7秒
平均对象建立速率为10.63 mb/sec，平均的晋升速率为2 kb/sec，cpu使用率正常，没有明显的飙升

jvm参数

-XX:+UseParallelGC -XX:+UseParallelOldGC -XX:ParallelGCThreads=4 -XX:+UseAdaptiveSizePolicy -XX:MaxHeapSize=2147483648 -XX:MaxNewSize=1073741824 -XX:NewSize=1073741824 -XX:+PrintGCDetails -XX:+PrintTenuringDistribution -XX:+PrintGCTimeStamps
复制代码

jdk版本java

java -version
java version "1.8.0_66"
Java(TM) SE Runtime Environment (build 1.8.0_66-b17)
Java HotSpot(TM) 64-Bit Server VM (build 25.66-b17, mixed mode)
复制代码

full gc

27.066: [Full GC (Metadata GC Threshold) [PSYoungGen: 19211K->0K(917504K)] [ParOldGen: 80K->18440K(1048576K)] 19291K->18440K(1966080K), [Metaspace: 20943K->20943K(1069056K)], 0.5005658 secs] [Times: user=0.24 sys=0.01, real=0.50 secs] 
100.675: [Full GC (Metadata GC Threshold) [PSYoungGen: 14699K->0K(917504K)] [ParOldGen: 18464K->23826K(1048576K)] 33164K->23826K(1966080K), [Metaspace: 34777K->34777K(1081344K)], 0.7937738 secs] [Times: user=0.37 sys=0.01, real=0.79 secs]
195.073: [Full GC (Metadata GC Threshold) [PSYoungGen: 24843K->0K(1022464K)] [ParOldGen: 30048K->44782K(1048576K)] 54892K->44782K(2071040K), [Metaspace: 58220K->58220K(1101824K)], 3.7936515 secs] [Times: user=1.86 sys=0.02, real=3.79 secs] 
242605.669: [Full GC (Ergonomics) [PSYoungGen: 67276K->0K(882688K)] [ParOldGen: 1042358K->117634K(1048576K)] 1109635K->117634K(1931264K), [Metaspace: 91365K->90958K(1132544K)], 22.1573804 secs] [Times: user=2.50 sys=3.51, real=22.16 secs]
复制代码

能够发现发生的4次full gc，前三次都是因为Metadata GC Threshold形成的，只有最后一次是因为Ergonomics引起的。git

Full GC (Metadata GC Threshold)

这里使用的是java8，参数没有明确指定metaspace的大小和上限，查看一下github

jstat -gcmetacapacity 7
   MCMN       MCMX        MC       CCSMN      CCSMX       CCSC     YGC   FGC    FGCT     GCT
       0.0  1136640.0    99456.0        0.0  1048576.0    12160.0 38009    16  275.801 14361.992
复制代码

忽略后面的FGC，由于分析的日志只是其中四分之一
这里能够看到MCMX(Maximum metaspace capacity (kB))有一个多G，而MC(Metaspace capacity (kB))才97M左右，为啥会引发Full GC (Metadata GC Threshold)

相关参数segmentfault

-XX:MetaspaceSize，初始空间大小(也是初始的阈值，即初始的high-water-mark)，达到该值就会触发垃圾收集进行类型卸载，同时GC会对该值进行调整：若是释放了大量的空间，就适当下降该值；若是释放了不多的空间，那么在不超过MaxMetaspaceSize时，适当提升该值。
-XX:MaxMetaspaceSize，最大空间，默认是没有限制的，取决于本地系统空间容量。
-XX:MinMetaspaceFreeRatio，在GC以后，最小的Metaspace剩余空间容量的百分比(即元数据在当前分配大小的最大占用大小)，若是空闲比小于这个参数(即超过了最大占用大小)，那么将对meta space进行扩容。
-XX:MaxMetaspaceFreeRatio，在GC以后，最大的Metaspace剩余空间容量的百分比(即元数据在当前分配大小的最小占用大小)，若是空闲比大于这个参数(即小于最小占用大小)，那么将对meta space进行缩容.

因为没有设置，在机器上的默认值为：bash

java -XX:+PrintFlagsFinal | grep Meta
    uintx InitialBootClassLoaderMetaspaceSize       = 4194304                             {product}
    uintx MaxMetaspaceExpansion                     = 5451776                             {product}
    uintx MaxMetaspaceFreeRatio                     = 70                                  {product}
    uintx MaxMetaspaceSize                          = 18446744073709547520                    {product}
    uintx MetaspaceSize                             = 21807104                            {pd product}
    uintx MinMetaspaceExpansion                     = 339968                              {product}
    uintx MinMetaspaceFreeRatio                     = 40                                  {product}
     bool TraceMetadataHumongousAllocation          = false                               {product}
     bool UseLargePagesInMetaspace                  = false                               {product}
复制代码

能够看到MinMetaspaceFreeRatio为40，MaxMetaspaceFreeRatio为70，MetaspaceSize为20M，Full GC (Metadata GC Threshold)主要分为了三次markdown

第一次，[Metaspace: 20943K->20943K(1069056K)]
第二次，[Metaspace: 34777K->34777K(1081344K)]
第三次，[Metaspace: 58220K->58220K(1101824K)]

能够看到metaspace的阈值不断动态调整，至于具体调整的逻辑，官方文档貌似没讲，这里暂时不深究。只要没有超过Max值就没有致命影响，可是对于低延时的应用来说，是要尽可能避免动态调整引发的gc耗时，能够根据调优计算并设置初始阈值来解决。多线程

Full GC (Ergonomics)

这里能够到full gc的reason是Ergonomics，是由于开启了UseAdaptiveSizePolicy，jvm本身进行自适应调整引起的full gcoracle

GC (Allocation Failure)

分析完full gc以后咱们看下young gc，看log里头99%都是GC (Allocation Failure)形成的young gc。Allocation Failure表示向young generation(eden)给新对象申请空间，可是young generation(eden)剩余的合适空间不够所需的大小致使的minor gc。jvm

-XX:+PrintTenuringDistribution

Desired survivor size 75497472 bytes, new threshold 2 (max 15)
- age   1:   68407384 bytes,   68407384 total
- age   2:   12494576 bytes,   80901960 total
- age   3:      79376 bytes,   80981336 total
- age   4:    2904256 bytes,   83885592 total
复制代码

这个Desired survivor size表示survivor区域容许容纳的最大空间大小为75497472 bytes
下面的对象列表为这次gc以后，survivor当前存活对象的年龄大小分布，total大小为83885592 > 75497472，而age1大小为68407384 < 75497472，所以new threshold变为2(做用于下次gc)。下次gc若是对象没释放的话，超过阈值的对象将晋升到old generation。

age list为空

59.463: [GC (Allocation Failure) 
Desired survivor size 134217728 bytes, new threshold 7 (max 15)
[PSYoungGen: 786432K->14020K(917504K)] 804872K->32469K(1966080K), 0.1116049 secs] [Times: user=0.10 sys=0.01, real=0.20 secs] 
复制代码

这里Desired survivor size这行下面并无各个age对象的分布，那就表示这次gc以后，当前survivor区域并无age小于max threshold的存活对象。而这里一个都没有输出，表示这次gc回收对象以后，没有存活的对象能够拷贝到新的survivor区。

gc以后survivor有对象的例子

jstat -gcutil -h10 7 10000 10000
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
  0.00  99.99  90.38  29.82  97.84  96.99    413  158.501     4   14.597  173.098
 11.60   0.00  76.00  29.83  97.84  96.99    414  158.511     4   14.597  173.109
 11.60   0.00  77.16  29.83  97.84  96.99    414  158.511     4   14.597  173.109
  0.00  13.67  60.04  29.83  97.84  96.99    415  158.578     4   14.597  173.176
  0.00  13.67  61.05  29.83  97.84  96.99    415  158.578     4   14.597  173.176
复制代码

在ygc以前young generation = eden + S1；ygc以后，young generation = eden + S0
观察能够看到ygc以后old generation空间没变，表示这次ygc，没有对象晋升到old generation。
gc以后，存活对象搬移到了另一个survivor区域
这里因为是每一个10秒采样一次，存在延迟，即gc以后，立马有新对象在eden区域分配了，所以这里看到的eden区域有对象占用。

real time > usr time + sys time

722914.974: [GC (Allocation Failure) 
Desired survivor size 109576192 bytes, new threshold 15 (max 15)
[PSYoungGen: 876522K->8608K(941568K)] 1526192K->658293K(1990144K), 0.0102709 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
722975.207: [GC (Allocation Failure) 
Desired survivor size 103284736 bytes, new threshold 15 (max 15)
[PSYoungGen: 843168K->39278K(941568K)] 1492853K->688988K(1990144K), 0.3607036 secs] [Times: user=0.17 sys=0.00, real=0.36 secs] 
复制代码

里头有大于将近300次的gc的real time时间大于usr time + sys time。

real：指的是操做从开始到结束所通过的墙钟时间（WallClock Time）
user：指的是用户态消耗的CPU时间；
sys：指的是内核态消耗的CPU时间。

墙钟时间包括各类非运算的等待耗时，例如等待磁盘I/O、等待线程阻塞，而CPU时间不包括这些耗时，但当系统有多CPU或者多核的话，多线程操做会叠加这些CPU时间，因此看到user或sys时间超过real时间是彻底正常的。

user + sys 就是CPU花费的实际时间，注意这个值统计了全部CPU上的时间，若是进程工做在多线程的环境下，叠加了多线程的时间，这个值是会超出 real 所记录的值的，即 user + sys >= real 。

这里300屡次real time时间大于usr time + sys time，代表可能有两个问题，一个是IO操做密集，另外一个是cpu(分配)的额度不够。

新生代垃圾回收机制

新对象尝试栈上分配，不行再尝试TLAB分配，不行则考虑是否直接绕过eden区在年老代分配空间(-XX:PretenureSizeThreshold设置大对象直接进入年老代的阈值，当对象大小超过这个值时，将直接在年老代分配。)，不行则最后考虑在eden申请空间
向eden申请空间建立新对象，eden没有合适的空间，所以触发minor gc
minor gc将eden区及from survivor区域的存活对象进行处理
- 若是这些对象年龄达到阈值，则直接晋升到年老代
- 若要拷贝的对象太大，那么不会拷贝到to survivor，而是直接进入年老代
- 若to survivor区域空间不够/或者复制过程当中出现不够，则发生survivor溢出，直接进入年老代
- 其余的，若to survivor区域空间够，则存活对象拷贝到to survivor区域
此时eden区及from survivor区域的剩余对象为垃圾对象，直接抹掉回收，释放的空间成为新的可分配的空间
minor gc以后，若eden空间足够，则新对象在eden分配空间；若eden空间仍然不够，则新对象直接在年老代分配空间

小结

从上面的分析能够看出，young generation貌似有点大，ygc时间长；另外每次ygc以后survivor空间基本是空的，说明新生对象产生快，生命周期也短，本来设计的survivor空间没有派上用场。所以能够考虑缩小下young generation的大小，或者改成G1试试。

关于-XX:+PrintTenuringDistribution有几个要点，要明确一下：

这个打印的哪一个区域的对象分布(survivor)
是在gc以前打印，仍是在gc以后打印(gc以后打印)
一个新生对象第一次到survivor时其age算0仍是算1

对象的年龄就是他经历的MinorGC次数，对象首次分配时，年龄为0，第一次经历MinorGC以后，若尚未被回收，则年龄+1，因为是第一次经历MinorGC，所以进入survivor区。所以对象第一次进入survivor区域的时候年龄为1.

晋升阈值(new threshold)动态调整

若是底下age的total大小大于Desired survivor size的大小，那么就表明了survivor空间溢出了，被填满，而后会从新计算threshold。