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

ddupnow

浏览: 40592 次
性别:
来自: 北京

最近访客更多访客>>

107x

angie

qyf404

zjy_369

博主相关

博客

微博

相册

留言

关于我

文章分类

社区版块

存档分类

JVM Tomcat JSP Loadrunner Linux

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

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

压测环境介绍：

一台普通的linux服务器，双核，4G内存。

tomcat启动内存和最大内存设置为1G，最大处理线程数为默认的200个，http_load模拟200个用户并发访问，持续10分钟

  $ 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左右

30.788: [GC 71240K->45204K(1045312K), 0.0673630 secs]
31.519: [GC 71444K->45718K(1045312K), 0.0311260 secs]
32.096: [GC 71958K->46210K(1045312K), 0.0425230 secs]
32.714: [GC 72450K->46686K(1045312K), 0.0818290 secs]
33.520: [GC 72926K->46970K(1045312K), 0.0288800 secs]
34.757: [GC 73210K->47461K(1045312K), 0.0598320 secs]
35.720: [GC 73701K->47802K(1045312K), 0.0303100 secs]
36.576: [GC 74042K->48105K(1045312K), 0.0387580 secs]
37.340: [GC 74345K->48541K(1045312K), 0.0298160 secs]
38.099: [GC 74781K->49045K(1045312K), 0.0287100 secs]
38.729: [GC 75285K->49463K(1045312K), 0.0271920 secs]
39.428: [GC 75703K->49936K(1045312K), 0.0338770 secs]
39.982: [GC 76176K->50422K(1045312K), 0.0341610 secs]
40.444: [GC 76662K->50849K(1045312K), 0.0407040 secs]
40.977: [GC 77089K->51304K(1045312K), 0.0308000 secs]

于是想看看到底是哪些内存对象占用了过多的内存:

首先找出tomcat进程ID，然后运行如下命令，获得其JVM内存对象的占用情况

$ jmap -histo 进程号|head -n 20

结果如下：

 num     #instances         #bytes  class name
----------------------------------------------
   1:       1040160       33285120  java.util.concurrent.ConcurrentHashMap$Segment
   2:       1040354       24968496  java.util.concurrent.locks.ReentrantLock$NonfairSync
   3:        192962       23240344  [C
   4:         32123       17892336  [B
   5:       1040287       17859608  [Ljava.util.concurrent.ConcurrentHashMap$HashEntry;
......
......

可以看到，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区的内存占用情况

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

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

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

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

发现该对象的父对象是org.apache.catalina.session.StandardManager.

查看tomcat源代码发现该类继承自ManagerBase，ManagerBase中果然有一个成员变量为ConcurrentHashMap！

    /**
     * The set of currently active Sessions for this Manager, keyed by
     * session identifier.
     */
    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编译后的文件会发现如下代码：

      response.setContentType("text/html");
      pageContext = _jspxFactory.getPageContext(this, request, response,
                null, true, 8192, true);
      _jspx_page_context = pageContext;
      application = pageContext.getServletContext();
      config = pageContext.getServletConfig();
      session = pageContext.getSession();
      out = pageContext.getOut();
      _jspx_out = out;

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

为了验证该问题，我在返回的JSP页面里加入了