7点微信公众号:请点这里。7点测试网QQ总群:277957570。

7点测试网

 找回密码
 注册7点

QQ登录

只需一步,快速开始

查看: 2208|回复: 5

压力测试中JVM内存暴涨原因分析实战(转)

[复制链接]
发表于 2014-1-18 11:15:25 | 显示全部楼层 |阅读模式
本帖最后由 backtracker 于 2014-1-18 11:18 编辑

工作之中写了个小的Web应用,类似于脚手架的demo应用,用spring搭的,在tomcat里运行。

程序写完了,想看看能承受多大的访问压力,遂开始进行压力测试。没有用复杂的loadrunner压测,采用了一个简单的url压测工具http_load,只是单纯地用来压某个url的并发访问。

压测环境介绍:
      一台普通的linux服务器,双核,4G内存。
      tomcat启动内存和最大内存设置为1G,最大处理线程数为默认的200个,http_load模拟200个用户并发访问,持续10分钟
Shell代码  
  1. $ http_load -p 200 -s 600 url  
复制代码


使用lambdaprobe 监控tomcat的运行情况,发现jvm内存一直在上涨,从1%增长到90%,最后居然内存溢出了!才压了10分钟而已,感觉到非常奇怪。

于是决定看看jvm的gc日志,在catalina.sh文件中加入jvm参数:
-Xloggc:gclog.vgc -XX:+PrintGCTimeStamps -XX:-PrintGCDetails -XX:+UseConcMarkSweepGC

观察输出的日志文件,发现将近每半秒进行一次GC操作,但是每秒内存还是在均匀上涨1M左右
Gc日志片断代码  
  1. 30.788: [GC 71240K->45204K(1045312K), 0.0673630 secs]  
  2. 31.519: [GC 71444K->45718K(1045312K), 0.0311260 secs]  
  3. 32.096: [GC 71958K->46210K(1045312K), 0.0425230 secs]  
  4. 32.714: [GC 72450K->46686K(1045312K), 0.0818290 secs]  
  5. 33.520: [GC 72926K->46970K(1045312K), 0.0288800 secs]  
  6. 34.757: [GC 73210K->47461K(1045312K), 0.0598320 secs]  
  7. 35.720: [GC 73701K->47802K(1045312K), 0.0303100 secs]  
  8. 36.576: [GC 74042K->48105K(1045312K), 0.0387580 secs]  
  9. 37.340: [GC 74345K->48541K(1045312K), 0.0298160 secs]  
  10. 38.099: [GC 74781K->49045K(1045312K), 0.0287100 secs]  
  11. 38.729: [GC 75285K->49463K(1045312K), 0.0271920 secs]  
  12. 39.428: [GC 75703K->49936K(1045312K), 0.0338770 secs]  
  13. 39.982: [GC 76176K->50422K(1045312K), 0.0341610 secs]  
  14. 40.444: [GC 76662K->50849K(1045312K), 0.0407040 secs]  
  15. 40.977: [GC 77089K->51304K(1045312K), 0.0308000 secs]  
复制代码



于是想看看到底是哪些内存对象占用了过多的内存:
     首先找出tomcat进程ID,然后运行如下命令,获得其JVM内存对象的占用情况
Shell代码  收藏代码
$ jmap -histo 进程号|head -n 20  

     结果如下:
内存对象占用情况代码  收藏代码
  1. num     #instances         #bytes  class name  
  2. ----------------------------------------------  
  3.    1:       1040160       33285120  java.util.concurrent.ConcurrentHashMap$Segment  
  4.    2:       1040354       24968496  java.util.concurrent.locks.ReentrantLock$NonfairSync  
  5.    3:        192962       23240344  [C  
  6.    4:         32123       17892336  [B  
  7.    5:       1040287       17859608  [Ljava.util.concurrent.ConcurrentHashMap$HashEntry;  
  8. ......  
  9. ......  
复制代码

可以看到,java.util.concurrent.ConcurrentHashMap$Segment对象实例最多,且占用了大量的内存。当前JVM内存占用总量为155M,ConcurrentHashMap$Segment,ConcurrentHashMap$HashEntry,java.util.concurrent.locks.ReentrantLock加起来占用了差不多一半的内存!~

回头查看自己的程序代码,看是否有使用ConcurrentHashMap对象,或者滥用该对象的情况。

检查后发现自己程序并没有使用ConcurrentHashMap对象!~很郁闷,到底是哪里在大量的对ConcurrentHashMap进行操作,使得该Map越来越大呢?

经过网上搜索,发现一个比jconsole还强大的jvm监控工具,也是sun推出的,叫做visualvm ,下载下来该工具后,还可以下载几个插件,丰富其监控功能,甚为好用。
附上一个监控图,非常详细和动态的显示了Eden,S0,S1,Old,Perm区的内存占用情况
1.png



由于要分析出到底哪里的ConcurrentHashMap对象被不断的put操作,使其异常庞大,于是首先用visualvm把heap dump出来。在Monitor标签页中有一个Heap Dump按钮,点击就是,该操作会把当前的jvm内存情况导出到一个文件中。

visualvm可以分析dump文件,但是我使用之后感觉非常慢。然后就是另一个工具登场了,HeapAnalyzer , 用该工具来分析dump出的文件。该工具下载下来后为jar文件,直接java -jar运行之。

找出size最大的java.util.concurrent.ConcurrentHashMap$Segment对象:
2.png

查找出该对象的创建树结构:

3.png
发现该对象的父对象是org.apache.catalina.session.StandardManager.
查看tomcat源代码发现该类继承自ManagerBase,ManagerBase中果然有一个成员变量为ConcurrentHashMap!
Java代码  收藏代码
  1. /**
  2. * The set of currently active Sessions for this Manager, keyed by
  3. * session identifier.
  4. */  
  5. protected Map<String, Session> sessions = new ConcurrentHashMap<String, Session>();  
复制代码


该对象存储的就是大名鼎鼎的容器session。

原来,http_load模拟的Url请求没有附带cookie和url重写,也就没有JSESSIONID信息,导致每一个请求,容器都会创建一个新的session。短短10分钟内200个线程并发访问,导致session暴涨。

但是我查看了自己的程序代码,并没有对session进行操作,那么容器是在何时创建新的session呢?

谜底就在于返回的JSP页面。学过jsp/servlet都知道,jsp页面默认有个session变量,查看tomcat目录下的jsp编译后的文件会发现如下代码:
Java代码  
  1. response.setContentType("text/html");  
  2. pageContext = _jspxFactory.getPageContext(this, request, response,  
  3.           null, true, 8192, true);  
  4. _jspx_page_context = pageContext;  
  5. application = pageContext.getServletContext();  
  6. config = pageContext.getServletConfig();  
  7. session = pageContext.getSession();  
  8. out = pageContext.getOut();  
  9. _jspx_out = out;  
复制代码

getSession()方法会返回当前请求的JSESSIONID对应的session,如果没有就新创建一个session返回。

为了验证该问题,我在返回的JSP页面里加入了
Java代码  收藏代码
  1. <%@page session="false"%>  
复制代码

不使用session,再次进行压力测试,结果印证了我的想法。

下面是没加session="false"和加上了的两种情况的内存增长图,作为对比,结果非常明显:
4.png



这次事件也告诉我不能随便选择测试工具,因为真实用户访问都是会附带cookie信息的,不会出现每个请求都需要创建session的情况。

附:
tomcat使用ConcurrentHashMap来存储session,在并发访问的情况下有更好的性能。有关更多session知识,可以参考:
     http://java.chinaitlab.com/base/802833.html
     http://xuehu2009.iteye.com/blog/524303
发表于 2014-1-21 08:50:59 | 显示全部楼层
思路清晰,非常好一次JVM内存溢出跟踪思路
发表于 2014-11-21 13:06:14 | 显示全部楼层
好东西多谢分享。
发表于 2015-2-2 16:24:36 | 显示全部楼层
前段时间遇到有关sessionid、cookies、url重写的情况,菜鸟表示,我才知道。。。
发表于 2016-8-24 11:06:07 | 显示全部楼层
写的好,受教
您需要登录后才可以回帖 登录 | 注册7点

本版积分规则

QQ|Archiver|手机版|小黑屋|7点测试网 ( 京ICP备09084002号

GMT+8, 2018-8-14 22:10 , Processed in 0.231100 second(s), 24 queries .

Powered by Discuz! X3.1

© 2001-2013 Comsenz Inc.

快速回复 返回顶部 返回列表