本文主要分析一个频繁GC (Allocation Failure)及young gc时间过长的case。
allocation failure为主
),平均270多毫秒,最大值将近7秒-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 -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)
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引发的。
这里使用的是java8,参数没有明确指定metaspace的大小和上限,查看一下
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
相关参数
即元数据在当前分配大小的最大占用大小
),如果空闲比小于这个参数(即超过了最大占用大小
),那么将对meta space进行扩容。即元数据在当前分配大小的最小占用大小
),如果空闲比大于这个参数(即小于最小占用大小
),那么将对meta space进行缩容.由于没有设置,在机器上的默认值为:
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)主要分为了三次
这里可以到full gc的reason是Ergonomics,是因为开启了UseAdaptiveSizePolicy,jvm自己进行自适应调整引发的full gc
分析完full gc之后我们看下young gc,看log里头99%都是GC (Allocation Failure)造成的young gc。Allocation Failure表示向young generation(eden)给新对象申请空间,但是young generation(eden)剩余的合适空间不够所需的大小导致的minor gc。
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
作用于下次gc
)。下次gc如果对象没释放的话,超过阈值的对象将晋升到old generation。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
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。
墙钟时间包括各种非运算的等待耗时,例如等待磁盘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(
分配
)的额度不够。
-XX:PretenureSizeThreshold设置大对象直接进入年老代的阈值,当对象大小超过这个值时,将直接在年老代分配。
),不行则最后考虑在eden申请空间
从上面的分析可以看出,young generation貌似有点大,ygc时间长;另外每次ygc之后survivor空间基本是空的,说明新生对象产生快,生命周期也短,原本设计的survivor空间没有派上用场。因此可以考虑缩小下young generation的大小,或者改为G1试试。
关于-XX:+PrintTenuringDistribution有几个要点,要明确一下:
survivor
)gc之后打印
)