序
本文主要分析一个频繁 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 gcAllocation 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
- 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?
来源: https://juejin.im/post/5a9b811a6fb9a028e46e1c88