JVM调优和问题诊断是一个老生常谈,而又总也谈不好、谈不完的话题。常常是在本地开发、调试,甚至测试都没啥问题,一旦上线就纰漏百出,这种情况不鲜见,个人小项目、公司产品甚至大公司的产品多少都会遇到和 JVM 深人打交道的时候。本文不去照搬现成的各式调优建议,而试图通过对 JVM 的监控,结合使用 JSF 框架编写的测试项目,寻找内存泄漏问题的根源;通过使用一系列的工具来分析问题的细节,并最终尝试提供一些合理的、有效的改进建议和方法。
近日接到某同学告急消息,他的JSF(JSF2,下文都简称JSF)站点部署到线上之后,JVM内存占用一直上升,直到溢出。这让我颇感意外,接触JSF这么久,还真没好好注意过线上的性能问题,来的早不如来得巧,得嘞,就你了。
这是个比较典型的新闻性的站,类似虎嗅或36Kr这样的资讯站,PV量不多,但也不算少。整站是由JSF构建,页面打开速度尚可,这和站点部署在国内的云主机有一定关系。目前的情况是本地运行时,查看VM占用情况都比较正常;一旦部署上线,略有访问量之后,内存占用就飙升,直到内存耗尽,情况万分危急。
正好我这里有一个JSF的小项目,本打算用来讲解JSF的事件原理和组件编写的(由于最近忙于移动应用而暂时搁置),不妨用来演示一下这个情况。首先来看看没有任何优化,一个简单的不能再简单的页面,关联一个ViewScope的BackingBean,
图1. 简单的JSF页面
这里,我们将要用到几个工具,它们分别是VisualVM、SoapUI和Memory Analyzer。下图显示的是经过3次SoapUI的压测之后,在VisualVM里看到的堆情况。
图2. 经过3次压力测试之后的内存情况
图中A点是压测过后内存情况,B点是手工执行了一下GC。由此可以看出,在经历3次剧烈的波动之后,曲线整体是呈一个上扬的趋势,换句话说,内存占用是只升不降(注:这还是在手工执行了GC之后)。这就有点意思了,让人忍不住去探究探究。那么到底是什么原因导致内存只升不降呢?
带着这样的疑问,我们来打开VisualVM的Profiler(这也是一个特别有用的功能点),看看究竟是谁才是罪魁祸首。
图3. Profiler during 4th Load Test
图4. Profiler during 4th Load Test 2
图3 和图4 是第4次压测期间的Profiler情况,可以看到 char[] 是一颗耀眼明星,蓝框中的生存代数达到了惊人的37代,也就意味着,这货在GC执行了37次之后,还顽强的活着。
图5. Profiler during 5th Load Test
图5 可以更加明显的看到, char[] 的存活代数已达到了惊人的 47 !也就说,内存回收对这货完全无用啊。当然,说完全无用是有点夸张,至少说明了有很多的 char[] 存活着。仔细的看图表,还可以看到,String 对象好像也很多,好像也是存活了 47 代,等等,好像有点什么发现了?String 为什么这个多?为什么没被回收?为什么和 char[] 一样活得久?一连串的问题浮现出来。
回到Java里来,String的背后存储是用的 char[],哦,既然这样,那也就是说,堆里面的老代中,存在了太多了的字符串无法回收,是这样么?带着这样的疑问,去做一个堆的dump。在这里,由于我是本地,就直接在“监视”标签页中执行dump就完了,如果是线上的服务器,可别这么搞呀。
话说,拿到了dump文件,用神器mat(Eclipse Memory Analyzer 简称 mat)打开它。
图6. mat open wizard
向导我们直接选择“Leak Suspects Report”,恩,看来这个内存泄漏是的高发病、常见病嘛。
图7. overview – mat
哎呀呀,神器就是神器,刚刚打开dump文件,啥也没干呢,就看到这么个惊喜呀,红果果的告诉我谁是头号疑犯,恩,靠谱。等等,好像有点不对劲,刚刚在Profiler里明明得出结论是 String 太多回收不了,这里怎么是 org.apache.catalina.session.StandardSession 呢?好奇怪。究竟是什么情况?接着往下看,我们看一下Histogram好了。
图7. Histogram – mat
图7的堆dump文件显示了,在堆中占用排序后,排名靠前都基本都是和 HashMap、char[] 相关,好像有点端倪了,来来,继续。HashMap也好,StandardSession也好,这些都不直观,我们来看最直观的 char[]. 打开 char[]的 Object List,
图8. objects of char[] – mat
我们看到了一堆熟悉的字符串,有木有? “j_idt9″、”j_id1″这些是JSF为页面视图组件树上的组件自动生成的ID,图8 还可以看到,相同的字符串,存在很多份,并没有重用。
图9. open Path To GC Roots -mat
随便选一个字符串,我们来看看它到 GC Root 的路径上有哪些对象。
图10. Path to GC Roots – mat
到目前为止,我们都在看图,没有涉及什么高深理论,实际上,这里需要补充一个理论:垃圾对象判定方法。常用的有两种,一种是所谓的引用计数法(Python在用),它简单易用易理解,缺点也很明显,无法解决对象相互引用而无法回收的问题。另外一种就是根路径搜索法(GC Roots Trace)。是在现在主流的程序语言中(Java、C#甚至古老的Lisp),均使用跟路径搜索算法(关于根路径搜索更加详细的内容可以参阅这里。另外更加深入、全面的讲解可以参看周志明的《深入理解Java虚拟机 JVM高级特性与最佳实践》 一书第三章)。
回到图10, 我们可以看到,我们选定一个字符串对象,到GC Root的路径上居然有10个对象,都是些什么呢?噢,我们看到了熟悉的东西:com.sun.faces.util.LRUMap .好家伙,果不其然,JSF脱不了干系啊。还有一个老熟人: StandardSession。种种迹象表明,这是由于JSF的缓存(LRUMap)了大量的字符串,而缓存对象本身又通过一条路径引用到了GC Root上来。这样一来,无论如何都无法被JVM标记为垃圾了,回收也就无从谈起。
读者朋友,你有想起来什么吗?对啦,我在本文开头的时候说过,测试页面是一个ViewScopedBackingBean,是不是?既然是 ViewScoped,也就是 Request 级别的生存周期,问题就来了,怎么会在Session里面缓存这么多东西呢?这是其一。其二,你不奇怪为什么会有这么多Session对象么?我的并发测试只是5个线程并发而已。为了解释这些疑问,追根溯源,下一篇将深入挖掘JSF的源代码,带您探寻JSF占用大量内存背后的原因,敬请期待。
(待续)
Happy new year!
Bill 2014-01-01