频繁GC (Allocation Failure)及young gc时间过长分析
序
本文主要分析一个频繁GC (Allocation Failure)及young gc时间过长的case。
症状
- 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 -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引发的。
Full GC (Metadata GC Threshold)
这里使用的是java8,参数没有明确指定metaspace的大小和上限,查看一下
jstat -gcmetacapacity 7MCMN MCMX MC CCSMN CCSMX CCSC YGC FGC FGCT GCT0.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)
相关参数
- -XX:MetaspaceSize,初始空间大小(也是初始的阈值,即初始的high-water-mark),达到该值就会触发垃圾收集进行类型卸载,同时GC会对该值进行调整:如果释放了大量的空间,就适当降低该值;如果释放了很少的空间,那么在不超过MaxMetaspaceSize时,适当提高该值。
- -XX:MaxMetaspaceSize,最大空间,默认是没有限制的,取决于本地系统空间容量。
- -XX:MinMetaspaceFreeRatio,在GC之后,最小的Metaspace剩余空间容量的百分比(
即元数据在当前分配大小的最大占用大小
),如果空闲比小于这个参数(即超过了最大占用大小
),那么将对meta space进行扩容。 - -XX:MaxMetaspaceFreeRatio,在GC之后,最大的Metaspace剩余空间容量的百分比(
即元数据在当前分配大小的最小占用大小
),如果空闲比大于这个参数(即小于最小占用大小
),那么将对meta space进行缩容.
由于没有设置,在机器上的默认值为:
java -XX:+PrintFlagsFinal | grep Metauintx 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)主要分为了三次
- 第一次,[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 gc
GC (Allocation Failure)
分析完full gc之后我们看下young gc,看log里头99%都是GC (Allocation Failure)造成的young gc。Allocation Failure表示向young generation(eden)给新对象申请空间,但是young generation(eden)剩余的合适空间不够所需的大小导致的minor gc。
-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 10000S0 S1 E O M CCS YGC YGCT FGC FGCT GCT0.00 99.99 90.38 29.82 97.84 96.99 413 158.501 4 14.597 173.09811.60 0.00 76.00 29.83 97.84 96.99 414 158.511 4 14.597 173.10911.60 0.00 77.16 29.83 97.84 96.99 414 158.511 4 14.597 173.1090.00 13.67 60.04 29.83 97.84 96.99 415 158.578 4 14.597 173.1760.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。
doc
- jstat
- Size of Huge Objects directly allocated to Old Generation
- Java对象分配简要流程
- 记一次JVM优化过程
- Survivor空间溢出实例
- Java 垃圾回收的log,为什么 from和to大小不等?
- Useful JVM Flags – Part 5 (Young Generation Garbage Collection)
- JDK-6453675 : Request for documentation of -XX:+PrintTenuringDistribution output
- How to read the output of +PrintTenuringDistribution
- 一次GC Tuning小记
- JDK8 的FullGC 之 metaspace
- Java PermGen 去哪里了?
- Metaspace
- MetaspaceSize的坑
- JVM源码分析之Metaspace解密
- About G1 Garbage Collector, Permanent Generation and Metaspace
- 聊聊jvm的PermGen与Metaspace
- GC LOGGING – USER, SYS, REAL – WHICH TIME TO USE? & GANDHI
- REAL TIME IS GREATER THAN USER AND SYS TIME
- GC日志时间分析: user + sys < real
- What is promotion rate?
频繁GC (Allocation Failure)及young gc时间过长分析相关推荐
- GC (Allocation Failure) 那些事
GC (Allocation Failure) 那些事 平常写Spark程序,经常看到 GC(Allocation Failure) 这个日志,大概查了查意思是是jvm在执行垃圾回收,一般情况下不影响 ...
- Java中GC (Allocation Failure)日志分析实战
概述 博主在最近使用spring batch的过程当中遇到了内存容量耗尽程序崩溃的问题,于是决定将此次的内存问题分析通过本篇博客记录下来. 在分析gc日实例志之前,我们先通过一条<深入理解jav ...
- CMS 触发GC(Allocation Failure)解析之标梵信息
针对GC中发生的"Allocation Failure",源码描述为:Allocation Failure is a cause of GC cycle to kick in. & ...
- GC(Allocation Failure)
日前查看某个程序的日志,发现一直在报GC相关的信息,不确定这样的信息是代表正确还是不正确,所以正好借此机会再复习下GC相关的内容: 以其中一行为例来解读下日志信息: [GC (Allocation F ...
- 每秒 10 万并发的 BI 系统如何频繁发生 Young GC?
作者 | 救火队队长 责编 | 伍杏玲 本文经授权转载自石杉的架构笔记(ID:shishan100) 本周我们的一个重点就是给大家再次强调JVM频繁GC对系统性能的危害性. 因此在分析完JVM发生GC ...
- 一次 Young GC 的优化实践
这个 GC 案例比较有意思,排查问题有点像侦探断案,先分析各种可能性,再按照获得的一个个证据,去排除各种可能性.然后定位原因,最终解决问题. 问题 某同学在微信上问我,有没有办法排查 YoungGC ...
- 一次 Young GC 的优化实践(FinalReference 相关)
本文转载自公众号:涤生的博客,阅读时间大约需要11分钟.涤生的文章看起来跟破案一样,很精彩,很有启发. 前言 博客已经好久没有更新了,主要原因是 18 年下半年工作比较忙,另外也没有比较有意思的题材, ...
- 手把手教你如何写出完美的JVM的Young GC
模拟JVM的Young GC JVM参数示范(基于JDK 1.8) 用如下JVM参数运行代码: # 初始新生代大小 5M -XX:NewSize=5242880 # 最大新生代大小 5M -XX:Ma ...
- GC暂停时间过长——排查分析
告警 本次GC日志分析 2022-11-17T17:58:50.518+0800: 1217960.132: [GC (Allocation Failure) 2022-11-17T17:58:50. ...
最新文章
- 时间序列入门教程,从理论到业务实践,Kaggle kernels Master 整理分享
- 用户切换命令:su 与 sudo
- centos php sftp 扩展,Linux(CentOS)上配置 SFTP
- iOS学习笔记(1)--认识Xcode6.1的Interface Builder和常用快捷键
- Golang手册与常用包手册
- 无监督学习 k-means_无监督学习-第1部分
- Docker swarm 笔记
- 经过实践的小企业的生存之道
- javascript return
- 一道打印菱形的面试题
- 编程:OJ中使用C编程最基础的操作
- linux opendir路径_Linux C/C++ ----目录文件的操作(opendir,readdir,closedir)
- 系统创建定时执行任务bat批处理删除指定N天前文件夹的文件
- 淘晶驰串口屏_ 串口屏卡顿的原因
- 并发编程四:深入理解java线程
- 基于JAVA基于Web的上门家教系统的设计与实现计算机毕业设计源码+系统+mysql数据库+lw文档+部署
- staruml 时序图操作
- 不同路径(一个机器人位于一个 m x n 网格的左上角)
- java 机器人捡豆子,【小孩老是注意力不集中】_小儿_怎么办-大众养生网
- 用rpm安装卸载软件