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

最新推荐文章于 2024-09-30 15:11:21 发布
最新推荐文章于 2024-09-30 15:11:21 发布
阅读量1.9k 收藏 6
点赞数
文章标签： java 运维 runtime
原文链接：https://my.oschina.net/go4it/blog/1628795
版权

为什么80%的码农都做不了架构师？>>>   hot3.png

序

本文主要分析一个频繁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 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)

相关参数

  • -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 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)主要分为了三次

  • 第一次，[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 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。

doc

转载于:https://my.oschina.net/go4it/blog/1628795

weixin_33729196
关注
GC 分析
简简单单Onlinezuozuo
01-05 1668
文章目录GC 分析1、工具辅助2、GC (Allocation Failure)3、YGC 日志，进行拆解分析4、Spring Boot 优化 GC 分析 1、工具辅助 我们可以把 GC 的日志下载下来，然后通过一些可视化工具进行可视化 例如 GCViewer（https://github.com/chewiebug/GCViewer） 内存分销工具 JProfiler 2、GC (Allocation Failure) GC 日志中 GC (Allocation Failure) 形式的 GC 为 Y
GC 疑难情况问题排查与分析（上篇）
KimmKing的技术博客
09-22 450
本章介绍导致 GC 性能问题的典型情况。相关示例都来源于生产环境，为演示需要做了一定程度的精简。 名词说明：Allocation Rate，翻译为“分配速率”，而不是分配率。因为不是百分比，而是单位时间内分配的量。同理，Promotion Rate 翻译为“提升速率”。 高分配速率（High Allocation Rate） 分配速率（Allocation Rate）表示单位时间内分配的内...
[case9]频繁GC (Allocation Failure)及young gc时间过长分析
weixin_33701251的博客
03-04 2533
序 本文主要分析一个频繁GC (Allocation Failure)及young gc时间过长的case。 症状 gc throughput percent逐步下降，从一般的99.96%逐步下降，跌破99%，进入98%，最低点能到94% young gc time逐步增加，从一般的十几毫秒逐步上升，突破50，再突破100，150，20...
频繁GC (Allocation Failure)及young gc时间过长分析 
大JAVA解决方案
07-01 8800
序 本文主要分析一个频繁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 f...
GC垃圾回收（高薪常问）
最新发布
lcl020809的博客
09-30 475
大部分对象都在Eden区生成，回收时将该区存活的对象复制到s0区，然后清空Eden区，当s0区也存放满时，则将Eden区和S0区存活的对象复制到S1区，然后清空这两个区，S1满了就在复制到S0，如此往复。根搜索算法是把所有的引用关系 看作一张图，从节点GCROOT开始，寻找对应的引用节点，找到这个节点以后，继续寻找这个节点的引用节点，当所有的引用节点寻找完毕之后，剩余的节点则被认为是没有被引用到的节点，即可以当作垃圾。先去标记需要删除的对象，将所有存活的对象都移向一端，在移动的过程中清理掉可回收的对象。
java gc 时间过长_Java8应用young gc时间过长
weixin_30768103的博客
02-24 274
问题描述求教各位大神，Java 8应用young gc时间过长，平均耗时接近100ms，偶尔能到1.5s使用垃圾收集器parNew + CMS，几乎没有触发过CMS gc使用框架spring + mybatis + dubbo + rocketmqJVM参数：-server -Xmx5g -Xms5g -Xmn1g -XX:MetaspaceSize=512m -XX:MaxMetaspaceSi...
GC(Allocation Failure)引发的一些JVM知识点梳理
热门推荐
淡定一生2333的博客
10-12 14万+
日前查看某个程序的日志，发现一直在报GC相关的信息，不确定这样的信息是代表正确还是不正确，所以正好借此机会再复习下GC相关的内容： 以其中一行为例来解读下日志信息： [GC (Allocation Failure) [ParNew: 367523K->1293K(410432K), 0.0023988 secs] 522739K->156516K(1322496K), 0.0025...
GC (Allocation Failure) 日志分析
cab5的博客
09-19 3677
最近在做 SpringBoot 项目（我的项目最终是要被打成 docker image 的）调优的过程中，由于启动 Jar 的时候设置了XX:+PrintGCDetails 参数，所以在容器启动的过程中初夏了如下日志信息： [GC (Allocation Failure) [ParNew: 221714K->11707K(235968K), 0.0503991 secs] 246868K-...
CMS 触发GC(Allocation Failure)解析之标梵信息
标梵互动
01-08 2133
针对GC中发生的"Allocation Failure"，源码描述为：Allocation Failure is a cause of GC cycle to kick in. "Allocation Failure" means that no more space left in Eden to allocate object. So, it is normal cause of young GC. Older JVM were not printing GC cause for minor GC cy
java年轻代频繁gc_年轻代频繁ParNew GC，导致http服务rt飙高
weixin_36180471的博客
03-02 1524
背景介绍某日下午大约四点多，接到合作方消息，线上环境，我这边维护的某http服务突然大量超时(对方超时时间设置为300ms)，我迅速到鹰眼平台开启采样，发现该服务平均QPS到了120左右，平均RT在2秒多到3秒，部分毛刺高达5到6秒(正常时候在60ms左右)。qps情况：rt情况问题解决该服务是一个对内的运营平台服务(只部署了两台docker)预期qps个位数，近期没做过任何的线上发布，核心操作是...
Java中GC (Allocation Failure)日志分析实战
Java知音
06-28 2715
概述博主在最近使用spring batch的过程当中遇到了内存容量耗尽程序崩溃的问题，于是决定将此次的内存问题分析通过本篇博客记录下来。在分析gc日实例志之前，我们先通过一条《深入理解ja...
GC (Allocation Failure) 那些事
BITDDD小栈
07-07 2万+
GC (Allocation Failure) 那些事 平常写Java程序，经常看到 GC(Allocation Failure) 这个日志，大概查了查意思是是jvm在执行垃圾回收，一般情况下不影响程序运行，只会拖慢程序运行时间。但是经常遇到这个日志还是不爽，今天就盘一下！GC(Allocation Failure)造成的垃圾回收为young gc 又称minor gc。 Demo代码 下面这几行spark代码是经常引起 GC(Allocation Failure) 日志的代码写法，基....
young gc时间缩减
05-14 659
young gc的耗时主要有两个方面 从root对象进行扫描存活的对象 复制存活的对象 从缩短扫描存活对象的方面入手：首先我们先考虑root对象包含哪些 1、所有java线程以及线程栈帧里指向GC堆里的对象的引用 2、JNI Local & Global 3、由系统类加载器(system class loader)加载的对象，这些类是不能够被回收的 4、stack local Java方法的local变量或参数 5、其他，包含monitor & finalizable & n
记一次频繁YoungGC生产问题排查思路及解决方案
womeiyouzaihuashui的博客
04-16 7239
1、问题背景 系统开发了新功能上线，本来上完之后功能验收正常，就在大家都松了一口气安心听技术分享时，晚上6.56分突然收到了系统告警： YoungGC时间过长，说实话一开始看到这个告警心里是毫无波澜的，一是因为一次YoungGC时间过长影响不大，二是因为这是内部系统，虽然处理的数据量比较大，但是YoungGC不会影响功能正常运行。 当时心里的第一想法是：应该是刚启动导致系统有些不平稳，过一会儿就好了。 然而过了几分后，第二台主机也开始告警，意识到问题严重性的我赶紧跑上来排查问题。 2、GC日志分析 首先
年轻代频繁GC ParNew导致http变慢
Crecendow
08-09 2079
某日下午大约四点多，接到合作方消息，线上环境，我这边维护的某http服务突然大量超时（对方超时时间设置为300ms），我迅速到鹰眼平台开启采样，发现该服务平均QPS到了120左右，平均RT在2秒多到3秒，部分毛刺高达5到6秒（正常时候在60ms左右）。qps情况：rt情况。
G1收集器 - 垃圾回收器（GC）
Seven的博客
11-06 214
JDK 9以后默认使用，替代了CMS 收集器。
G1收集器
weixin_43921491的博客
09-15 826
前言 G1收集器是一款在server端运行的垃圾收集器，专门针对于拥有多核处理器和大内存的机器，在JDK 7u4版本发行时被正式推出，在JDK9中更被指定为官方GC收集器。它满足高吞吐量的同时满足GC停顿的时间尽可能短。G1收集器专门针对以下应用场景设计 可以像CMS收集器一样可以和应用并发运行 压缩空闲的内存碎片，却不需要冗长的GC停顿 对GC停顿可以做更好的预测 不想牺牲大量的吞吐量性能 不需要更大的Java Heap Can operate concurrently with appl
gc allocation failure
03-16
gc allocation failure是指在进行垃圾回收时，由于内存不足而无法分配新的对象空间，导致分配失败的情况。这通常是由于程序中存在内存泄漏或者内存占用过高等问题所导致的。需要通过优化程序代码或者增加内存等方式...
评论
添加红包

请填写红包祝福语或标题

个

红包个数最小为10个

元

红包金额最低5元

当前余额3.43元 前往充值 >
需支付：10.00元
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付元
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明：

1.余额是钱包充值的虚拟货币，按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载，可以购买VIP、付费专栏及课程。

余额充值