深入JVM彻底剖析前面ygc越来越慢的case

阿里JVM团队的同学帮助从JVM层面继续深入的剖析了下前面那个ygc越来越慢的case,分析文章相当的赞,思路清晰,工具熟练,JVM代码熟练,请看这位同学(阿里JVM团队:寒泉子)写的文章,我转载到这。

Demo分析
虽然这个demo代码逻辑很简单,但是其实这是一个特殊的demo,并不简单,如果我们将XStream对象换成Object对象,会发现不存在这个问题,既然如此那有必要进去看看这个XStream的构造函数(请大家直接翻XStream的代码,这里就不贴了)。

这个构造函数还是很复杂的,里面会创建很多的对象,上面还有一些方法实现我就不贴了,总之都是在不断构建各种大大小小的对象,一个XStream对象构建出来的时候大概好像有12M的样子。

那到底是哪些对象会导致ygc不断增长呢,于是可能想到逐步替换上面这些逻辑,比如将最后一个构造函数里的那些逻辑都禁掉,然后我们再跑测试看看还会不会让ygc不断恶化,最终我们会发现,如果我们直接使用如下构造函数构造对象时,如果传入的classloader是AppClassLoader,那会发现这个问题不再出现了,代码如下:

[java]
public static void main(String[] args) throws Exception {
int i=0;
while (true) {
XStream xs = new XStream(null,null, new ClassLoaderReference(XStreamTest.class.getClassLoader()),null, new DefaultConverterLookup());
xs.toString();
xs=null;
}
}
[/java]

是不是觉得很神奇,由此可见,这个classloader至关重要。

不得不说的类加载器
这里着重要说的两个概念是初始类加载器和定义类加载器。举个栗子说吧,AClassLoader->BClassLoader->CClassLoader,表示AClassLoader在加载类的时候会委托BClassLoader类加载器来加载,BClassLoader加载类的时候会委托CClassLoader来加载,假如我们使用AClassLoader来加载X这个类,而X这个类最终是被CClassLoader来加载的,那么我们称CClassLoader为X类的定义类加载器,而AClassLoader和BClassLoader分别为X类的初始类加载器,JVM在加载某个类的时候对这三种类加载器都会记录,记录的数据结构是一个叫做SystemDictionary的hashtable,其key是根据ClassLoader对象和类名算出来的hash值,而value是真正的由定义类加载器加载的Klass对象,因为初始类加载器和定义类加载器是不同的classloader,因此算出来的hash值也是不同的,因此在SystemDictionary里会有多项值的value都是指向同一个Klass对象。

那么JVM为什么要分这两种类加载器呢,其实主要是为了快速找到已经加载的类,比如我们已经通过AClassLoader来触发了对X类的加载,当我们再次使用AClassLoader这个类加载器来加载X这个类的时候就不需要再委托给BClassLoader去找了,因为加载过的类在JVM里有这个类加载器的直接加载的记录,只需要直接返回对应的Klass对象即可。

Demo中的类加载器是否会加载类
我们的demo里发现构建了一个CompositeClassLoader的类加载器,那到底有没有用这个类加载器加载类呢,我们可以设置一个断点在CompositeClassLoader的loadClass方法上,可以看到会进入断点。
可见确实有类加载的动作,根据类加载委托机制,在这个Demo中我们能肯定类是交给AppClassLoader来加载的,这样一来CompositeClassLoader就变成了初始类加载器,而AppClassLoader会是定义类加载器,都会在SystemDictionary里存在,因此当我们不断new XStream的时候会不断new CompositeClassLoader对象,加载类的时候会不断往SystemDictionary里插入记录,从而使SystemDictionary越来越膨胀,那自然而然会想到如果GC过程不断去扫描这个SystemDictionary的话,那随着SystemDictionary不断膨胀,那么GC的效率也就越低,抱着验证下猜想的方式我们可以使用perf工具来看看,如果发现cpu占比排前的函数如果都是操作SystemDictionary的,那就基本验证了我们的说法,下面是perf工具的截图,基本证实了这一点。
perf

SystemDictionary为什么会影响GC过程
想象一下这么个情况,我们加载了一个类,然后构建了一个对象(这个对象在eden里构建)当一个属性设置到这个类里,如果gc发生的时候,这个对象是不是要被找出来标活才行,那么自然而然我们加载的类肯定是我们一项重要的gc root,这样SystemDictionary就成为了gc过程中的被扫描对象了,事实也是如此,可以看vm的具体代码(代码在:SharedHeap::process_strong_roots,感兴趣的同学可以直接翻这部分代码)。

看上面的SH_PS_SystemDictionary_oops_do task就知道了,这个就是对SystemDictionary进行扫描。

但是这里要说的是虽然有对SystemDictionary进行扫描,但是ygc的过程并不会对SystemDictionary进行处理,如果要对它进行处理需要开启类卸载的vm参数,CMS算法下,CMS GC和Full GC在开启CMSClassUnloadingEnabled的情况下是可能对类做卸载动作的,此时会对SystemDictionary进行清理,所以当我们在跑上面demo的时候,通过jmap -dump:live,format=b,file=heap.bin 命令执行完之后,ygc的时间瞬间降下来了,不过又会慢慢回去,这是因为jmap的这个命令会做一次gc,这个gc过程会对SystemDictionary进行清理。

修改VM代码验证
很遗憾hotspot目前没有对ygc的每个task做一个时间的统计,因此无法直接知道是不是SH_PS_SystemDictionary_oops_do这个task导致了ygc的时间变长,为了证明这个结论,我特地修改了一下代码,在上面的代码上加了一行:
GCTraceTime t(“SystemDictionary_OOPS_DO”,PrintGCDetails,true,NULL);
然后重新编译,跑我们的demo,测试结果如下:
2016-03-14T23:57:24.293+0800: [GC2016-03-14T23:57:24.294+0800: [ParNew2016-03-14T23:57:24.296+0800: [SystemDictionary_OOPS_DO, 0.0578430 secs]
: 81920K->3184K(92160K), 0.0889740 secs] 81920K->3184K(514048K), 0.0900970 secs] [Times: user=0.27 sys=0.00, real=0.09 secs]
2016-03-14T23:57:28.467+0800: [GC2016-03-14T23:57:28.468+0800: [ParNew2016-03-14T23:57:28.468+0800: [SystemDictionary_OOPS_DO, 0.0779210 secs]
: 85104K->5175K(92160K), 0.1071520 secs] 85104K->5175K(514048K), 0.1080490 secs] [Times: user=0.65 sys=0.00, real=0.11 secs]
2016-03-14T23:57:32.984+0800: [GC2016-03-14T23:57:32.984+0800: [ParNew2016-03-14T23:57:32.984+0800: [SystemDictionary_OOPS_DO, 0.1075680 secs]
: 87095K->8188K(92160K), 0.1434270 secs] 87095K->8188K(514048K), 0.1439870 secs] [Times: user=0.90 sys=0.01, real=0.14 secs]
2016-03-14T23:57:37.900+0800: [GC2016-03-14T23:57:37.900+0800: [ParNew2016-03-14T23:57:37.901+0800: [SystemDictionary_OOPS_DO, 0.1745390 secs]
: 90108K->7093K(92160K), 0.2876260 secs] 90108K->9992K(514048K), 0.2884150 secs] [Times: user=1.44 sys=0.02, real=0.29 secs]

我们会发现YGC的时间变长的时候,SystemDictionary_OOPS_DO的时间也会相应变长多少,因此验证了我们的说法。

有同学提到如果Demo代码改成不new XStream,而是直接new CompositeClassLoader或CustomClassLoader则不会出问题,按照上面的分析也很容易解释,就是因为如果直接new CustomClassLoader的话,并没触发loadClass这动作,而new XStream的话在构造器里就在loadClass。

有同学提到在JDK 8中跑这个case不会出现问题,原因是:jdk8在对SystemDictionary扫描时做了优化,增加了一层cache,大大减少了需要扫描的入口数。

=============================
欢迎关注微信公众号:hellojavacases

关于此微信号:
分享Java问题排查的Case、Java业界的动态和新技术、Java的一些小知识点Test,以及和大家一起讨论一些Java问题或场景,这里只有Java细节的分享,没有大道理、大架构和大框架。

公众号上发布的消息都存放在http://hellojava.info上。

一个jstack/jmap等不能用的case

今天一个同学问我:”我排查问题时总是遇到,jmap -heap或-histo 不能用,是不是我们机器配置有啥问题哇? ” 分享下这个case的解决过程。

登上同学说的那台不能用的机器,执行jstack,报错:“get_thread_regs failed for a lwp”,这个问题以前碰到过,但忘了当时是什么原因了,执行其他的jmap -histo什么也卡着不动。

既然jstack没法弄,就pstack看看进程到底什么状况吧,于是pstack [pid]看,发现有一个线程的堆栈信息有点奇怪:
#0 0x00000038e720cd91 in sem_wait ()

对系统函数不太懂,但总觉得sem_wait这个有点奇怪,于是Google之,基本明白了这个是由于进程在等信号,这个时候通常会block住其他所有的线程,于是立刻ps看了下进程的状态,果然进程的状态变成了T,那上面碰到的所有现象都很容易解释了,于是执行:kill -CONT [pid],一切恢复正常。

继续查为什么进程状态会变成T,问问题的同学告诉了下我他在机器上执行过的一些命令,我看到其中一个很熟悉的命令:jmap -heap,看过我之前文章的同学估计会记得我很早以前分享过,在用cms gc的情况下,执行jmap -heap有些时候会导致进程变T,因此强烈建议别执行这个命令,如果想获取内存目前每个区域的使用状况,可通过jstat -gc或jstat -gccapacity来拿到。

到此为止,问题终于搞定,以后碰到jstack/jmap等不能用的时候,可以先看看进程的状态,因此还是那句话,执行任何一句命令都要清楚它带来的影响。

手头还有另外一个case,折腾了一个多星期了还是没太有头绪,case的现象是ygc越来越慢,但可以肯定不是由于cms gc碎片问题造成的,感兴趣的同学可以拿这个case去玩玩,如果能告诉我原因就更好了,:),执行下面的代码,启动参数可以为-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xms512m -Xmx512m -Xmn100m -XX:+UseConcMarkSweepGC:
[code]
import com.thoughtworks.xstream.XStream;

public class XStreamTest {

public static void main(String[] args) throws Exception {
while(true){
XStream xs = new XStream();
xs.toString();
xs = null;
}
}

}
[/code]

应该就可以看到ygc的速度从10+ms一直增长到100+ms之类的…

=============================
欢迎关注微信公众号:hellojavacases

关于此微信号:
分享Java问题排查的Case、Java业界的动态和新技术、Java的一些小知识点Test,以及和大家一起讨论一些Java问题或场景,这里只有Java细节的分享,没有大道理、大架构和大框架。

公众号上发布的消息都存放在http://hellojava.info上。

又一个勉强算是解决的Case

最近真心陷入了怪圈,近期处理的cases要么是没解决,要么就是稀里糊涂的解决掉,这周又碰到了一个这样的case,尽管目前是解决了,但其实背后的原因仍然不清楚,给大家分享下先,是一个关于Young GC越来越慢的Case。

应用的现象是启动的那段时间每次Young GC耗时大概是10-20ms,运行几个小时后,Young GC的耗时就会逐步增长到200+ms(注意,是逐步增长,不是突然增长到这么大),继续运行的话,甚至会逐步增长到1s以上,但每次Young GC存活的对象和刚启动的那段时间其实没什么变化。

之前也碰到过几次Young GC变慢的现象,原因是:
1. CMS GC的碎片问题;
2. 用到了Swap。

于是按照这两个思路去排查,看应用的启动参数,应用确实是采用的CMS GC,于是我就强制触发了下Full GC,结果发现还是一样,没什么变化,说明不是碎片问题造成的。

接着查是不是用到了Swap,free -m可以看到swap也没用过,这个时候我只好怀疑是不是内存条出什么问题了,请硬件的同事帮忙check了下内存条是ok的。

到了这步,又悲催了,超出了自己的经验范围,于是想着要么换一个GC方式试试,就把CMS GC换成了ParallelOldGC,结果还是一样。

到这个阶段已经彻底没哲了,开始瞎折腾,就在瞎折腾的那段时间突然发现了一个现象,就是permgen涨的很快,当然,fgc的时候也会回收掉,于是就想着先用btrace挂上看看为什么permgen涨的快。

可是这个应用是用的jdk 7,挂上btrace跟踪后直接crash了…只好按照这个思路去问应用的同学,按以往经验,permgen涨的快通常都是因为错误使用groovy,于是直接问是不是用到了groovy,答复是用到了,不过用的方法是jdk 7 invokedynamic的方式去执行的groovy脚本,而在这种情况下执行的方式其实是把groovy脚本编译成class来执行的,所以理论上不太可能出现重复装载class,但btrace脚本又挂不上,就很难去排查了。

这个时候应用的同学告诉了一个有用的信息是,这个应用最近从groovy 2.1.x升级到了2.3.x,猜想莫非是升级造成的,于是降级成2.1.9,再看,一切恢复正常了,到此问题算是解决了。

这个问题是解决了,但其实遗留了好几个疑问点还不知道原因:
1. 为什么permgen一直增长/回收,会造成ygc变得越来越慢,完全无法理解呀;
2. Groovy 2.3.x到底做了什么导致了class的不断重复装载,猜想是API上做了变化,还没来得及仔细看。

有经验的同学可以帮忙告知下我,谢谢,:)

=============================
欢迎关注微信公众号:hellojavacases

关于此微信号:
分享Java问题排查的Case、Java业界的动态和新技术、Java的一些小知识点Test,以及和大家一起讨论一些Java问题或场景,这里只有Java细节的分享,没有大道理、大架构和大框架。

公众号上发布的消息都存放在http://hellojava.info上。