深刻索求JVM,驾驭原理

Posted by

前言:

由于最近写的程序在运行一段时间后出现高cpu,然后不可用故进而进行排查,最终定位到由于metaspace引起fullgc,不断的fullgc又占用大量cpu导致程序最终不可用。下面就是这次过程的分析排查和总结,便于以后温故,同时也希望能给遇到同样问题的同学一些参考。

Java 8彻底将永久代移除出了HotSpot JVM,将其原有的数据迁移至Java
Heap或Metaspace。这一篇文章我们来总结一下Metaspace(元空间)的特性。如有错误,敬请指出,谢谢~

一次CMS GC问题排查过程(理解原理+读懂GC日志) – iamzhongyong –
ITeye技术网站
http://iamzhongyong.iteye.com/blog/1989829

一 jvm的内存分配情况:

Eden Survivor1 Survivor2 Tenured
Tenured 包含perm jdk<=7

jvm内存young区图.png

gc类型分为:minor gc 和 major gc ,major的速度比minor慢10倍至少

发生在 young(主要是Survivor)区的gc称为 minor gc
发生在 old(Tenured)区的gc称为 major gc


这个是之前处理过的一个线上问题,处理过程断断续续,经历了两周多的时间,中间各种尝试,总结如下。这篇文章分三部分:
1、问题的场景和处理过程;2、GC的一些理论东西;3、看懂GC的日志
先说一下问题吧
问题场景:线上机器在半夜会推送一个700M左右的数据,这个时候有个数据置换的过程,也就是说有700M*2的数据在heap区域中,线上系统超时比较多,导致了很严重(严重程度就不说了)的问题。
问题原因:看日志,系统接口超时的时候,系统出现了FullGC,这个时候stop-the-world了,也就停机了。分析gc的日志,发现有promotion
failed,根据FullGC触发的条件,这个时候就会出现FullGC了。日志如下:
1
2

1.问题描述

jstat -gcutil 26819
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 43.75 0.00 42.22 67.19 50.93 4955 30.970 4890 3505.049 3536.020
可以看到M(metaSpace使用率)的值是67.19,metaSpace使用率为67.19;O为42.22,old区使用率为42.22

top -H -p 26819
26821 appdev 20 0 6864m 1.2g 13m R 87.6 7.5 53:40.18 java
26822 appdev 20 0 6864m 1.2g 13m R 87.6 7.5 53:41.40 java
26823 appdev 20 0 6864m 1.2g 13m R 87.6 7.5 53:43.64 java
26824 appdev 20 0 6864m 1.2g 13m R 85.6 7.5 53:41.59 java
26825 appdev 20 0 6864m 1.2g 13m R 85.6 7.5 53:43.82 java
26826 appdev 20 0 6864m 1.2g 13m R 85.6 7.5 53:40.47 java
26827 appdev 20 0 6864m 1.2g 13m R 85.6 7.5 53:45.05 java
26828 appdev 20 0 6864m 1.2g 13m R 83.6 7.5 53:39.08 java
可以发现26821到26828的cpu使用率很高,26821转为16进制为68c5

jstack 26819 > 26819.text
vim 26819.text 然后搜索68c5-68cc
“GC task thread#0 (ParallelGC)” os_prio=0 tid=0x00007f0aa401e000
nid=0x68c5 runnable

“GC task thread#1 (ParallelGC)” os_prio=0 tid=0x00007f0aa4020000
nid=0x68c6 runnable

“GC task thread#2 (ParallelGC)” os_prio=0 tid=0x00007f0aa4021800
nid=0x68c7 runnable

“GC task thread#3 (ParallelGC)” os_prio=0 tid=0x00007f0aa4023800
nid=0x68c8 runnable

“GC task thread#4 (ParallelGC)” os_prio=0 tid=0x00007f0aa4025800
nid=0x68c9 runnable

“GC task thread#5 (ParallelGC)” os_prio=0 tid=0x00007f0aa4027000
nid=0x68ca runnable

“GC task thread#6 (ParallelGC)” os_prio=0 tid=0x00007f0aa4029000
nid=0x68cb runnable

“GC task thread#7 (ParallelGC)” os_prio=0 tid=0x00007f0aa402a800
nid=0x68cc runnable

可以发现一致是full
gc的线程在执行,占用cpu较高的资源,并且一致持续,表明一直达到了full
gc的条件但是又不能回收掉内存从而占用大量cpu,导致程序不可用。

查看启动配置参数如下:
-Xms1000m -Xmx1000m -XX:MaxNewSize=256m -XX:ThreadStackSize=256
-XX:MetaspaceSize=38m -XX:MaxMetaspaceSize=380m
分析程序的逻辑,程序会加载很多jar到内存,程序是一个公共服务,很多同事会上传jar,然后程序把jar加载到classloader进行分析并保存。

一、引言:永久代为什么被移出HotSpot JVM了?

详见:JEP 122: Remove the Permanent
Generation 
原因主要有两个:

  • 1、由于Permanent
    Generation内存经常不够用或发生内存泄露,引发恼人的java.lang.OutOfMemoryError:
    PermGen
     (在Java Web开发中非常常见)。
  • 2、移除Permanent Generation可以促进HotSpot JVM与 JRockit
    VM的融合,因为JRockit没有永久代。

This is part of the JRockit and Hotspot convergence effort. JRockit
customers do not need to configure the permanent generation (since
JRockit does not have a permanent generation) and are accustomed to
not configuring the permanent generation.

根据上面的各种原因,永久代最终被移除,方法区移至Metaspace,字符串常量移至Java
Heap

2013

11
-27T03:
00
:
53.638

0800
:
35333.562
: [GC
35333.562
: [ParNew (promotion failed): 1877376K->1877376K(1877376K),
15.7989680
secs]
35349.361
: [CMS: 2144171K->2129287K(2146304K),
10.4200280
sec

s] 3514052K->2129287K(4023680K), [CMS Perm :
119979K->118652K(190132K)],
26.2193500
secs] [Times: user=
30.35
sys=
5.19
, real=
26.22
secs]

问题解决:中间调整过几次,先搞了几台机器做了验证,后来逐步推广的。
1、调大heap区,由原来的4g,调整到5g,young区的大小不变,还是2g,这时候old区就由2g变为3g了(这样保证old区有足够的空间);
2、设置-XX:UseCMSInitiatingOccupancyOnly,其实这个不关这个问题,只是发现半夜CMS进行的有点频繁,就禁止掉了悲观策略;
3、设置CMS区回收的比例,从80%调整到75%,让old区尽早的进行,有足够的空间剩余;

为什么要有GC(垃圾回收)?
JVM通过GC来回收堆和方法区中的内存,GC的基本原理就是找到程序中不再被使用的对象,然后回收掉这些对象占用的内存。

主要的收集器有哪些?
引用计数器和跟踪计数器两种。
引用计数器记录对象是否被引用,当计数器为零时,说明对象已经不再被使用,可以进行回收。java中的对象有复杂的引用关系,不是很适合引用计数器,所以sun
jdk中并没有实现这种GC方式。
跟踪收集器,全局记录数据的引用状态,基于一定的条件触发。执行的时候,从根集合开始扫描对象的引用关系,主要有复制(copying)、标记-清除(Mark-Sweep)、标记-压缩(Mark-Compact)那种算法。

跟踪计数器的三种算法简介?
复制:从根集合搜扫描出存活的对象,然后将存活的对象复制到一块新的未使用的空间中,当要回收的空间中存活的对象较少时,比较高效;
标记清除:从根集合开始扫描,对存活的对象进行标记,比较完毕后,再扫描整个空间中未标记的对象,然后进行回收,不需要对对象进行移动;
标记压缩:标记形式和“标记清除”一样,但是回收不存活的对象后,会把所有存活的对象在内存空间中进行移动,好处是减少了内存碎片,缺点是成本比较高;

java内存区域的形式是啥样的?
这里就不再介绍了,之前有一篇文章中专门介绍这个的(http://iamzhongyong.iteye.com/blog/1333100)。

新生代可用的GC?
新生代中对象存活的时间比较短,因此给予Copying算法实现,Eden区域存放新创建的对象,S0和S1区其中一块用于存放在Minor
GC的时候作为复制存活对象的目标空间,另外一块清空。
串行GC(Serial
GC)
比较适合单CPU的情况,可以通过-XX:UseSerialGC来强行制定;
并行回收GC(Parallel
Scavenge)
,启动的时候按照设置的参数来划定Eden/S0/S1区域的大小,但是在运行时,会根据Minor
GC的频率、消耗时间来动态调整三个区域的大小,可以用过-XX:UseAdaptiveSizePolicy来固定大小,不进行动态调整;
并行GC(ParNew)划分Eden、S1、S0的区域上和串行GC一样。并行GC需要配合旧生代使用CMS
GC(这是他和并行回收GC的不同)(如果配置了CMS
GC的方式,那么新生代默认采取的就是并行GC的方式);

啥时候会触发Minor GC?
当Eden区域分配内存时,发现空间不足,JVM就会触发Minor
GC,程序中System.gc()也可以来触发。

旧生代可用的GC方式有哪几种?
串行GC(Serial MSC)、并行GC(Parallel MSC)、并发GC(CMS);

关于CMS?
采用CMS时候,新生代必须使用Serial GC或者ParNew
GC两种。CMS共有七个步骤,只有Initial Marking和Final
Marking两个阶段是stop-the-world的,其他步骤均和应用并行进行。持久代的GC也采用CMS,通过-XX:CMSPermGenSweepingEnabled
-XX:CMSClassUnloadingEnabled来制定。在采用cms
gc的情况下,ygc变慢的原因通常是由于old gen出现了大量的碎片。

为啥CMS会有内存碎片,如何避免?
由于在CMS的回收步骤中,没有对内存进行压缩,所以会有内存碎片出现,CMS提供了一个整理碎片的功能,通过-XX:UseCompactAtFullCollection来启动此功能,启动这个功能后,默认每次执行Full
GC的时候会进行整理(也可以通过-XX:CMSFullGCsBeforeCompaction=n来制定多少次Full
GC之后来执行整理),整理碎片会stop-the-world.

啥时候会触发CMS GC?
1、旧生代或者持久代已经使用的空间达到设定的百分比时(CMSInitiatingOccupancyFraction这个设置old区,perm区也可以设置);
2、JVM自动触发(JVM的动态策略,也就是悲观策略)(基于之前GC的频率以及旧生代的增长趋势来评估决定什么时候开始执行),如果不希望JVM自行决定,可以通过-XX:UseCMSInitiatingOccupancyOnly=true来制定;
3、设置了 -XX:CMSClassUnloadingE考虑nabled 这个则考虑Perm区;

啥时候会触发Full GC?
一、旧生代空间不足:java.lang.outOfMemoryError:java heap space;
二、Perm空间满:java.lang.outOfMemoryError:PermGen space;
三、CMS GC时出现promotion failed 和concurrent mode failure(Concurrent
mode
failure发生的原因一般是CMS正在进行,但是由于old区内存不足,需要尽快回收old区里面的死的java对象,这个时候foreground
gc需要被触发,停止所有的java线程,同时终止CMS,直接进行MSC。);
四、统计得到的minor GC晋升到旧生代的平均大小大于旧生代的剩余空间;
五、主动触发Full GC(执行jmap -histo:live [pid])来避免碎片问题;

为啥heap小于3g不建议使用CMS GC这种方式?

为什么不建议


毕大师的这篇文章讲的很清楚。
1、触发比例不好设置,设置大了,那么剩余的空间就少了很多,设置小了,那old区还没放置多少东西,就要进行回收了;
2、CMS进行的时候,是并行的,也就意味着如果过于频繁的话,会和应用的强占CPU;
3、CMS会有内存 碎片问题;
4、YGC的速率变慢(由于CMS
GC的实现原理,导致对象从新生代晋升到旧生代时,寻找哪里能放下的这个步骤比ParallelOld
GC是慢一些的,因此就导致了YGC速度会有一定程度的下降。);

JVM的悲观策略是啥?
所谓的悲观策略(http://tmalltesting.com/archives/663
我们性能测试团队一个同学分析的案例),就是JVM不按照JVM指定的参数来进行CMS
GC,而是根据内存情况以及之前回收的方式动态调整,自行进行GC。旧生代剩余的空间(available)大于新生代中使用的空间(max_promotion_in_bytes),或者大于之前平均晋升的old的大小(av_promo),返回false。cms
gc是每隔一个周期(默认2s)就会做一次这个检查,如果为false,则不执行YGC,而触发cms
gc。

我们经常使用的是啥GC方式?
针对目前线上机器的情况(8G的物流内存),heap区一般设置在4g或者5g左右,一般是使用CMS
GC,这时候:
young区使用ParNew(并行GC),Old+Perm(需要单独设置)使用CMS,整个堆(young+old+perm)使用MSC((Mark
Sweep Compact)是CMS GC算法的Full
GC算法,单线程回收整个堆,回收过程有严格的步骤。压缩,所以回收完理论上任何Generation都不会有内存碎片)压缩回收的方式。

读懂GC日志?
基本上都是这种格式:回收前区域占用的大小->回收后区域占用的大小(区域设置的大小),占用的时间


1、promotion failed的一段日志
1
2

2.问题分析:

根据jdk8的metaspace的fullgc的触发条件,初始metaspacesize是38m意味着当第一次加载的class达到38m的时候进行第一次gc(根据JDK
8的特性,G1和CMS都会很好地收集Metaspace区(一般都伴随着Full
GC)。),然后jvm会动态调整 (gc后会进行调整)metaspacesize的大小。

JDK8: Metaspace
In JDK 8, classes metadata is now stored in the native heap
and this space is called Metaspace. There are some new flags added for
Metaspace in JDK 8:
-XX:MetaspaceSize=<NNN>
where <NNN> is the initial amount of space(the initial
high-water-mark) allocated for class metadata (in bytes) that may induce
a
garbage collection to unload classes. The amount is approximate. After
the
high-water-mark is first reached, the next high-water-mark is managed
by
the garbage collector
-XX:MaxMetaspaceSize=<NNN>
where <NNN> is the maximum amount of space to be allocated for
class
metadata (in bytes). This flag can be used to limit the amount of
space
allocated for class metadata. This value is approximate. By default
there
is no limit set.
-XX:MinMetaspaceFreeRatio=<NNN>
where <NNN> is the minimum percentage of class metadata capacity
free after a GC to avoid an increase in the amount of space
(high-water-mark) allocated for class metadata that will induce a
garbage
collection.
-XX:MaxMetaspaceFreeRatio=<NNN>
where <NNN> is the maximum percentage of class metadata capacity
free after a GC to avoid a reduction in the amount of space
(high-water-mark) allocated for class metadata that will induce a
garbage
collection.
By default class
metadata allocation is only limited by the amount of available native
memory. We
can use the new option MaxMetaspaceSize to limit the amount of native
memory
used for the class metadata. It is analogous(类似) to MaxPermSize. A
garbage collection is induced to collect the dead classloaders
and classes when the class metadata usage reaches MetaspaceSize
(12Mbytes on
the 32bit client VM and 16Mbytes on the 32bit server VM with larger
sizes on
the 64bit VMs). Set MetaspaceSize to a higher value to delay the
induced
garbage collections. After an induced garbage collection, the class
metadata usage
needed to induce the next garbage collection may be increased.

根据这段描述可以知道:
1.当metadata usage reaches
MetaspaceSize(默认MetaspaceSize在64为server上是20.8m)就会触发gc;
2.XX:MinMetaspaceFreeRatio是用来避免下次申请的空闲metadata大于暂时拥有的空闲metadata而触发gc,举个例子就是,当metaspacesize的使用大小达到了第一次设置的初始值6m,这时进行进行扩容(之前已经做过MinMetaspaceExpansion和MaxMetaspaceExpansion扩展,但还是失败),然后gc后,由于回收调的内存很小,然后计算((待commit内存)/(待commit内存+已经commmited内存)
==40%,(待commit内存+已经commmited内存)大于了metaspaceSize那么将尝试做扩容,也就是增大触发metaspaceGC的阈值,不过这个增量至少是MinMetaspaceExpansion才会做,不然不会增加这个阈值)
,这个参数主要是为了避免触发metaspaceGC的阈值和gc之后committed的内存的量比较接近,于是将这个阈值(metaspaceSize)进行扩大,尽量减小下次gc的几率。
3.同理-XX:MaxMetaspaceFreeRatio(默认70)是用来避免下次申请的空闲metadata很小,远远小于现在的空闲内存从而导致gc。主要作用是减小不必要的内存占用空间。

jdk8的metaspace引发的fullgc:
jdk8使用metaspace代替之前的perm,metaspace使用native
memory,默认情况下使用的最大大小是系统内存大小,当然也可以使用-XX:MaxMetaspaceSize设置最大大小,这个设置和之前的max
perm
size是一样的。同时当设置-XX:MaxMetaspaceSize这个参数后,我们也可以实现和max
perm引起oom的问题。
We can achieve the famed OOM error by setting the MaxMetaspaceSize
argument to JVM and running the sample program provided.
metaspaceSize默认初始大小:
MetaspaceSize (12Mbytes on the 32bit client VM and 16Mbytes on the 32bit
server VM with larger sizes on the 64bit VMs).
可以通过-XX:MetaspaceSize
设置我们需要的初始大小,设置大点可以增加第一次达到full gc的时间。

ps:下面是调整了下参数重启的进程,和上面的进程Id有出入。
jstat -gc 1706
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
31744.0 32768.0 0.0 21603.6 195584.0 192805.8 761856.0 384823.3 467712.0
309814.3 65536.0 36929.1 101 2.887 3 1.224 4.112
分析:MC是已经commited的内存,MU是当前使用的内存。这里有个疑惑就是MC是不是就是metaspace已经总共使用的内存,因为这个值已经达到了maxmetaspacesize,同时为什么mu不是和mc一样我猜测是由于碎片内存导致,这里有知道的同学可以告诉我下。在达到maxmetaspacesize的时候执行了3次fullgc。但是接下来由于不断申请内存,不断fullgc,fullgc不能回收内存,这时候fullgc的频率增大很多。在接下来
top -H -p
1706查看cpu可以看到大量高cpu进程,通过jstack查看都是在进行fullgc。

jmap -clstats 1706
第一次:total = 131 8016 13892091 N/A alive=45, dead=86 N/A
第二次:total = 1345 37619 77242171 N/A alive=1170, dead=175 N/A
alive的classloader基本都是自己创建的
classLoader不断增加,每次gc并没有回收掉classloader
VM中的Class只有满足以下三个条件,才能被GC回收,也就是该Class被卸载(unload):

  • 该类所有的实例都已经被GC,也就是JVM中不存在该Class的任何实例。
  • 加载该类的ClassLoader已经被GC。ClassLoader被回收需要所有ClassLoader的所有类的实例都被回收。
  • 该类的java.lang.Class
    对象没有在任何地方被引用,如不能在任何地方通过反射访问该类的方法

jcmd 1706 GC.class_stats | awk ‘{print $13}’ | sort | uniq -c | sort
-nrk1 > topclass.txt

class.png

通过自定义的classloader加载的类重复多次,并且数量一直增加。
看到大量的类重复数量

二、探秘元空间

由于Metaspace的资料比较少,这里主要是依据Oracle官方的Java虚拟机规范及Oracle
Blog里的几篇文章来总结的。 
首先,Metaspace(元空间)是哪一块区域?官方的解释是:

In JDK 8, classes metadata is now stored in the native heap and
this space is called Metaspace.

也就是说,JDK 8开始把类的元数据放到本地化的堆内存(native
heap)中,这一块区域就叫Metaspace,中文名叫元空间。

2013

11
-27T03:
00
:
53.638

0800
:
35333.562
: [GC
35333.562
: [ParNew (promotion failed): 1877376K->1877376K(1877376K),
15.7989680
secs]
35349.361
: [CMS: 2144171K->2129287K(2146304K),
10.4200280
sec

s] 3514052K->2129287K(4023680K), [CMS Perm :
119979K->118652K(190132K)],
26.2193500
secs] [Times: user=
30.35
sys=
5.19
, real=
26.22
secs]

解释如下:
1
2
3
4
5

1877376K->1877376K(1877376K),
15.7989680
secs young区

2144171K->2129287K(2146304K),
10.4200280
sec old区情况

3514052K->2129287K(4023680K) heap区情况

119979K->118652K(190132K)],
26.2193500
secs perm区情况

[Times: user=
30.35
sys=
5.19
, real=
26.22
secs] 整个过程的时间消耗

2、一段正常的CMS的日志
1
2
3
4
5
6
7
8
9
10
11
12
13
14

gc日志分析:

第一次fullgc:
[Heap Dump (before full gc): , 0.4032181
secs]2018-01-10T16:37:44.658+0800: 21.673: [Full GC (Metadata GC
Threshold) [PSYoungGen: 14337K->0K(235520K)] [ParOldGen:
18787K->30930K(761856K)] 33125K->30930K(997376K), [Metaspace:
37827K->37827K(1083392K)], 0.1360661 secs] [Times: user=0.65
sys=0.04, real=0.14 secs]
主要是Metaspace这里:[Metaspace: 37827K->37827K(1083392K)]
达到了我们设定的初始值38m,并且gc并没有回收掉内存。1083392K这个值怀疑是使用了CompressedClassSpaceSize
= 1073741824 (1024.0MB)这个导致的。
第四次fullgc:
[Heap Dump (before full gc): , 5.3642805
secs]2018-01-10T16:53:43.811+0800: 980.825: [Full GC (Metadata GC
Threshold) [PSYoungGen: 21613K->0K(231424K)] [ParOldGen:
390439K->400478K(761856K)] 412053K->400478K(993280K),
[Metaspace: 314108K->313262K(1458176K)], 1.2320834 secs] [Times:
user=7.86 sys=0.06, real=1.23 secs]
主要是Metaspace这里:[Metaspace:
314108K->313262K(1458176K)]达到了我们设定的MinMetaspaceFreeRatio,并且gc几乎没有回收掉内存。1458176K这个值是CompressedClassSpaceSize
= 1073741824 (1024.0MB)和 MaxMetaspaceSize = 503316480 (480.0MB)的和。

后面就是频率很快的重复fullgc。

1、优点

使用本地化的内存有什么好处呢?最直接的表现就是java.lang.OutOfMemoryError:
PermGen
 空间问题将不复存在,因为默认的类的元数据分配只受本地内存大小的限制,也就是说本地内存剩余多少,理论上Metaspace就可以有多大(貌似容量还与操作系统的虚拟内存有关?这里不太清楚),这解决了空间不足的问题。不过,让Metaspace变得无限大显然是不现实的,因此我们也要限制Metaspace的大小:使用-XX:MaxMetaspaceSize参数来指定Metaspace区域的大小。JVM默认在运行时根据需要动态地设置MaxMetaspaceSize的大小。 
除此之外,它还有以下优点(没有完全理解,先贴出来吧,来自StackOverflow):

  • Take advantage of Java Language Specification property : Classes and
    associated metadata lifetimes match class loader’s
  • Linear allocation only
  • No individual reclamation (except for RedefineClasses and class
    loading failure)
  • No GC scan or compaction
  • No relocation for metaspace objects

2013

11
-27T04:
00
:
12.819

0800
:
38892.743
: [GC [
1
CMS-initial-mark: 1547313K(2146304K)] 1734957K(4023680K),
0.1390860
secs] [Times: user=
0.14
sys=
0.00
, real=
0.14
secs]

3.问题解决:

有了以上基础,就知道怎么解决这次遇到的问题了。
总结下原因:classloader不断创建,classloader不断加载class,之前的classloader和class在fullgc的时候没有回收掉。

  1. 程序避免创建重复classloader,减少创建classLoader的数量。
  2. 减小XX:MinMetaspaceFreeRatio(默认40)的大小,可以看到现在是(100-67.19)。
  3. 设置更大的maxmetaspaceSize。

jdk8metadataspace参考:
http://www.sczyh30.com/posts/Java/jvm-metaspace/
http://blog.csdn.net/ouyang111222/article/details/53688986
http://lovestblog.cn/blog/2016/10/29/metaspace/
https://bugs.openjdk.java.net/browse/JDK-8151845
http://blog.csdn.net/ouyang111222/article/details/53688986
https://blogs.oracle.com/poonam/about-g1-garbage-collector%2c-permanent-generation-and-metaspace
http://zhuanlan.51cto.com/art/201706/541920.htm
http://blog.yongbin.me/2017/03/20/jaxb\_metaspace\_oom/

2、垃圾回收

如果Metaspace的空间占用达到了设定的最大值,那么就会触发GC来收集死亡对象和类的加载器。根据JDK
8的特性,G1和CMS都会很好地收集Metaspace区(一般都伴随着Full GC)。 
为了减少垃圾回收的频率及时间,控制吞吐量,对Metaspace进行适当的监控和调优是非常有必要的。如果在Metaspace区发生了频繁的Full
GC,那么可能表示存在内存泄露或Metaspace区的空间太小了。

2013

11
-27T04:
00
:
12.958

0800
:
38892.883
: [CMS-concurrent-mark-start]

延伸阅读

3、新增参数

  • -XX:MetaspaceSize是分配给类元数据空间(以字节计)的初始大小(Oracle逻辑存储上的初始高水位,the
    initial
    high-water-mark
     ),此值为估计值。MetaspaceSize的值设置的过大会延长垃圾回收时间。垃圾回收过后,引起下一次垃圾回收的类元数据空间的大小可能会变大。
  • -XX:MaxMetaspaceSize是分配给类元数据空间的最大值,超过此值就会触发Full
    GC,此值默认没有限制,但应取决于系统内存的大小。JVM会动态地改变此值。
  • -XX:MinMetaspaceFreeRatio表示一次GC以后,为了避免增加元数据空间的大小,空闲的类元数据的容量的最小比例,不够就会导致垃圾回收。
  • -XX:MaxMetaspaceFreeRatio表示一次GC以后,为了避免增加元数据空间的大小,空闲的类元数据的容量的最大比例,不够就会导致垃圾回收。

2013

11
-27T04:
00
:
19.231

0800
:
38899.155
: [CMS-concurrent-mark:
6.255
/
6.272
secs] [Times: user=
8.49
sys=
1.57
, real=
6.27
secs]

jdk中触发gc的条件:

1,System.gc()方法的调用
system.gc(), 此方法的调用是建议JVM进行Full
GC,虽然只是建议而非一定,但很多情况下它会触发 Full GC,从而增加Full
GC的频率,也即增加了间歇性停顿的次数。强烈建议能不使用此方法就别使用,让虚拟机自己去管理它的内存,可通过通过-XX:+
DisableExplicitGC来禁止RMI调用System.gc。
2,老年代代空间(old/Tenured)不足
老年代空间只有在新生代对象转入及创建为大对象、大数组时才会出现不足的现象,当执行Full
GC后空间仍然不足,则抛出如下错误:java.lang.OutOfMemoryError: Java heap
space 为避免以上两种状况引起的Full GC,调优时应尽量做到让对象在Minor
GC阶段被回收、让对象在新生代多存活一段时间及不要创建过大的对象及数组。
3,永生区(perm)空间不足(jdk<=7 ,在jdk8里面是metaspace
,后面会重点描述)

JVM规范中运行时数据区域中的方法区,在HotSpot虚拟机中又被习惯称为永生代或者永生区,Permanet
Generation中存放的为一些class的信息、常量、静态变量等数据,当系统中要加载的类、反射的类和调用的方法较多时,Permanet
Generation可能会被占满,在未配置为采用CMS GC的情况下也会执行Full
GC。如果经过Full
GC仍然回收不了,那么JVM会抛出如下错误信息:java.lang.OutOfMemoryError:
PermGen space 为避免Perm Gen占满造成Full GC现象,可采用的方法为增大Perm
Gen空间或转为使用CMS GC。
4,CMS GC时出现promotion failed和concurrent mode failure
对于采用CMS进行老年代GC的程序而言,尤其要注意GC日志中是否有promotion
failed和concurrent mode
failure两种状况,当这两种状况出现时可能会触发Full GC。promotion
failed是在进行Minor GC时,survivor
space放不下、对象只能放入老年代,而此时老年代也放不下造成的;concurrent
mode failure是在执行CMS
GC的过程中同时有对象要放入老年代,而此时老年代空间不足造成的(有时候“空间不足”是CMS
GC时当前的浮动垃圾过多导致暂时性的空间不足触发Full
GC)。对措施为:增大survivor
space、老年代空间或调低触发并发GC的比率(-XX:CMSInitiatingOccupancyFraction=70,预留空间为70%),但在JDK
5.0+、6.0+的版本中有可能会由于JDK的bug29导致CMS在remark完毕后很久才触发sweeping动作。对于这种状况,可通过设置-XX:
CMSMaxAbortablePrecleanTime=5(单位为ms)来避免。
5、统计得到的Minor
GC晋升到旧生代(Eden到S2和S1到S2的和)的平均大小大于老年代的剩余空间

这是一个较为复杂的触发情况,Hotspot为了避免由于新生代对象晋升到旧生代导致旧生代空间不足的现象,在进行Minor
GC时,做了一个判断,如果之前统计所得到的Minor
GC晋升到旧生代的平均大小大于旧生代的剩余空间,那么就直接触发Full
GC。例如程序第一次触发Minor
GC后,有6MB的对象晋升到旧生代,那么当下一次Minor
GC发生时,首先检查旧生代的剩余空间是否大于6MB,如果小于6MB,则执行Full
GC。当新生代采用PS GC时,方式稍有不同,PS GC是在Minor
GC后也会检查,例如上面的例子中第一次Minor GC后,PS
GC会检查此时旧生代的剩余空间是否大于6MB,如小于,则触发对旧生代的回收。
除了以上4种状况外,对于使用RMI来进行RPC或管理的Sun
JDK应用而言,默认情况下会一小时执行一次Full GC。可通过在启动时通过- java
-Dsun.rmi.dgc.client.gcInterval=3600000来设置Full
GC执行的间隔时间或通过-XX:+ DisableExplicitGC来禁止RMI调用System.gc。
6、堆中分配很大的对象
所谓大对象,是指需要大量连续内存空间的java对象,例如很长的数组,此种对象会直接进入老年代,而老年代虽然有很大的剩余空间,但是无法找到足够大的连续空间来分配给当前对象,此种情况就会触发JVM进行Full
GC。
为了解决这个问题,CMS垃圾收集器提供了一个可配置的参数,即-XX:+UseCMSCompactAtFullCollection开关参数,用于在“享受”完Full
GC服务之后额外免费赠送一个碎片整理的过程,空间碎片问题没有了,但提顿时间不得不变长了,JVM设计者们还提供了另外一个参数
-XX:CMSFullGCsBeforeCompaction,这个参数用于设置在执行多少次不压缩的Full
GC后,跟着来一次带压缩的。

延伸阅读参考:
http://engineering.xueqiu.com/blog/2015/06/25/jvm-gc-tuning/
http://www.cnblogs.com/redcreen/archive/2011/05/04/2037057.html
http://blog.csdn.net/chenleixing/article/details/46706039

4、监控与调优(待补充)

VisualVM,jstat,jstack可以监测元空间的动态,后续将更新这里。


2013

11
-27T04:
00
:
19.231

0800
:
38899.155
: [CMS-concurrent-preclean-start]

参考资料:

[1]《The Java Virtual Machine Specification, Java SE 8 Edition》,
Oracle. 
[2]What is the use of Metaspace in Java 8? –
StackOverflow 
[3]About G1 Garbage Collector, Permanent Generation and
Metaspace 
[4]JEP 122: Remove the Permanent
Generation 
[5]PermGen elimination in JDK 8 –
StackOverflow

版权声明:本文为博主原创文章,基于CC-BY-SA
4.0许可(自由转载-非商用-非衍生-保持署名)

 

转自:

2013

11
-27T04:
00
:
19.250

0800
:
38899.175
: [CMS-concurrent-preclean:
0.018
/
0.019
secs] [Times: user=
0.02
sys=
0.00
, real=
0.02
secs]

2013

11
-27T04:
00
:
19.250

0800
:
38899.175
: [CMS-concurrent-abortable-preclean-start]

CMS: abort preclean due to time
2013

11
-27T04:
00
:
25.252

0800
:
38905.176
: [CMS-concurrent-abortable-preclean:
5.993
/
6.002
secs] [Times: user=
6.97
sys=
2.16
, real=
6.00
secs]

2013

11
-27T04:
00
:
25.253

0800
:
38905.177
: [GC[YG occupancy:
573705
K (
1877376
K)]
38905.177
: [Rescan (parallel) ,
0.3685690
secs]
38905.546
: [weak refs processing,
0.0024100
secs]
38905.548
: [cla

ss unloading,
0.0177600
secs]
38905.566
: [scrub symbol & string tables,
0.0154090
secs] [
1
CMS-remark: 1547313K(2146304K)] 2121018K(4023680K),
0.4229380
secs] [Times: user=
1.41
sys=
0.01
, real=

0.43
secs]

2013

11
-27T04:
00
:
25.676

0800
:
38905.601
: [CMS-concurrent-sweep-start]

2013

11
-27T04:
00
:
26.436

0800
:
38906.360
: [CMS-concurrent-sweep:
0.759
/
0.760
secs] [Times: user=
1.06
sys=
0.48
, real=
0.76
secs]

2013

11
-27T04:
00
:
26.436

0800
:
38906.360
: [CMS-concurrent-reset-start]

2013

11
-27T04:
00
:
26.441

0800
:
38906.365
: [CMS-concurrent-reset:
0.005
/
0.005
secs] [Times: user=
0.00
sys=
0.00
, real=
0.00
secs]

这个是一个正常的CMS的日志,共分为七个步骤,重点关注initial-mark和remark这两个阶段,因为这两个是停机的。
A、[GC [1 CMS-initial-mark: 1547313K(2146304K)] 1734957K(4023680K),
0.1390860 secs] [Times: user=0.14 sys=0.00, real=0.14 secs]
各个数据依次表示标记前后old区的所有对象占内存大小和old的capacity,整个JavaHeap(不包括perm)所有对象占内存总的大小和JavaHeap的capacity。
B、2013-11-27T04:00:25.253+0800: 38905.177: [GC[YG occupancy: 573705 K
(1877376 K)]38905.177: [Rescan (parallel) , 0.3685690 secs]38905.546:
[weak refs processing, 0.0024100 secs]38905.548: [class unloading,
0.0177600 secs]38905.566: [scrub symbol & string tables, 0.0154090
secs] [1 CMS-remark: 1547313K(2146304K)] 2121018K(4023680K),
0.4229380 secs] [Times: user=1.41 sys=0.01, real=0.43 secs]
Rescan
(parallel)表示的是多线程处理young区和多线程扫描old+perm的卡表的总时间,
parallel 表示多GC线程并行。
weak refs processing 处理old区的弱引用的总时间,用于回收native
memory。
class unloading 回收SystemDictionary消耗的总时间。

3、一段正常的Young GC的日志
1
2

2013

11
-27T04:
00
:
07.345

0800
:
38887.270
: [GC
38887.270
: [ParNew: 1791076K->170624K(1877376K),
0.2324440
secs] 2988366K->1413629K(4023680K),
0.2326470
secs] [Times: user=
0.80
sys=
0.00
, real=
0
.

23
secs]

ParNew这个表明是并行的回收方式,具体的分别是young区、整个heap区的情况;

4、一段通过system.gc产生的FullGC日志
1

2013

07
-21T17:
44
:
01.554

0800
:
50.568
: [Full GC (System)
50.568
: [CMS: 943772K->220K(2596864K),
2.3424070
secs] 1477000K->220K(4061184K), [CMS Perm :
3361K->3361K(98304K)],
2.3425410
secs] [Times: user=
2.33
sys=
0.01
, real=
2.34
secs]

解释如下:
Full GC (System)意味着这是个system.gc调用产生的MSC。
“943772K->220K(2596864K), 2.3424070
secs”表示:这次MSC前后old区内总对象大小,old的capacity及这次MSC耗时。
“1477000K->220K(4061184K)”表示:这次MSC前后JavaHeap内总对象大小,JavaHeap的capacity。
“3361K->3361K(98304K)], 2.3425410
secs”表示:这次MSC前后Perm区内总对象大小,Perm区的capacity。

5、一个特殊的GC日志,根据动态计算直接进行的FullGC(MSC的方式)
1

2013

03
-13T13:
48
:
06.349

0800
:
7.092
: [GC
7.092
: [ParNew: 471872K->471872K(471872K),
0.0000420
secs]
7.092
: [CMS: 366666K->524287K(524288K),
27.0023450
secs] 838538K->829914K(996160K), [CMS Perm :
3196K->3195K(131072K)],
27.0025170
secs]

ParNew的时间特别短,jvm在minor
gc前会首先确认old是不是足够大,如果不够大,这次young
gc直接返回,进行MSC。

参考文章:
http://kenwublog.com/docs/java6-jvm-options-chinese-edition.htm
JVM参数大全
http://tmalltesting.com/archives/663
悲观策略

为什么不建议


CMS GC不建议3G的原因
毕玄的《分布式java基础》
如何读懂GC日志:
https://blogs.oracle.com/poonam/entry/understanding\_cms\_gc\_logs

相关文章

Leave a Reply

电子邮件地址不会被公开。 必填项已用*标注