Java
Java虚拟机

Java虚拟机04 - 垃圾收集器之串行收集器

简介:Java虚拟机在执行Java程序的过程中会把它所管理的内存划分为若干个不同的数据区域。这些区域都有各自的用途,以及创建和销毁的时间,有的区域随着虚拟机进程的启动而存在,有些区域则依赖用户线程的启动和结束而建立和销毁。

1. 垃圾收集器概述

下图展示了7种作用于不同分代的收集器,如果两个收集器之间存在连线,就说明它们可以搭配使用。虚拟机所处的区域,则表示它是属于新生代收集器还是老年代收集器。

1.七种常见的垃圾收集器.png

下面将逐一介绍这些收集器的特性、基本原理和使用场景,同时给出一些模拟生产环境测试的例子,并重点分析CMS和G1这两款相对复杂的收集器,了解它们的部分运作细节。

目前为止还没有最好的收集器出现,更没有万能的收集器,所以我们需要针对具体应用选择最合适的收集器,一般都是搭配使用。

2. 串行收集器

串行收集器是所有垃圾收集器中最古老的一种,也是JDK中最基本的垃圾收集器之一,串行收集器在新生代的具体代表是Serial收集器,而在老年代则是Serial Old收集器。它们的特点就是单线程运行及独占式运行,因此会带来很不好的用户体验。虽然它的收集方式对程序的运行并不友好,但由于它的单线程执行特性,应用于但CPU硬件平台的性能可以超过其他的并行或并发处理器;同时,老年代的串行收集器Serial Old可以与多种新生代收集器配合使用,同时也可以作为CMS回收期的备用回收期。

2.1 Serial收集器

  • 在JDK 1.3.1之前是虚拟机新生代收集的唯一选择。
  • 只会使用一个CPU或一条收集线程去完成垃圾收集工作。
  • 在使用它进行垃圾收集时,必须暂停其他所有的工作线程(Stop The World),直到它收集结束。
  • 由虚拟机在后台自动发起和自动完成的,在用户不可见的情况下需要将用户正常工作的线程全部停掉。
  • 是虚拟机在Client模式下默认使用的新生代收集器。

注:使用-XX:+UseSerialGC参数可以设置在新生代使用Serial收集器。

2.2 Serial Old收集器

  • Serial Old是Serial收集器的老年代版本,它同样是一个单线程收集器,使用“标记-整理”算法。
  • 主要意义是在于给Client模式下的虚拟机使用。
  • 如果在Server模式下,那么它主要还有两大用途:
    • 在JDK 1.5以及之前的版本中与Parallel Scavenge收集器搭配使用;
    • 作为CMS收集器的后备预案,在并发收集发生Concurrent Mode Failure时使用。这两点都将在后面的内容中详细讲解。

Serial和Serial Old收集器的工作过程如下图所示:

2.Serial和Serial Old运行流程.png

要启用老年代串行收集器,可以尝试使用下面的参数:

  • -XX:+UseSerialGC:新生代和老年代都是用串行收集器;
  • -XX:+UseParNewGC:新生代使用ParNew收集器,老年代使用串行收集器;
  • -XX:+UseParallelGC:新生代使用Parallel GC收集器,老年代使用串行收集器。

2.3 串行收集器测试

接下来将对特定的一些垃圾收集器进行压力测试,这里统一使用Tomcat构建一个简单的Web页面,然后使用JMeter对其进行压力测试。在没有特殊说明的情况下,测试环境配置如下:

  • JDK版本:1.6.0_45
  • Tomcat版本:6.0.53
  • JMeter版本:2.13

在测试之前需要设置CATALINA_OPTS参数,让运行环境的Java虚拟机强制使用串行收集器,参数如下:

  • CATALINA_OPTS="-Xloggc:/Users/qinly/Desktop/Java_Test/gc.log -XX:+PrintGCDetails -Xms32M -Xmx32M -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/Users/qinly/Desktop/Java_Test/ -XX:+UseSerialGC -XX:PermSize=32M"

上述配置解释如下:

  • -Xloggc:/Users/LennonChin/Desktop/Java_Test/gc.log:配置GC日志的输出目录;
  • -XX:+PrintGCDetails:打印GC操作详情;
  • -Xms32M -Xmx32M:设置最大和最小堆内存都是32MB,即将堆内存大小限制为32MB;
  • -XX:+HeapDumpOnOutOfMemoryError:捕捉堆内存溢出异常;
  • -XX:HeapDumpPath=/Users/LennonChin/Desktop/Java_Test/:堆内存溢出时转储日志文件存放位置;
  • -XX:+UseSerialGC强制新生代和老年代都是用Serial GC;
  • -XX:PermSize=32M:设置永久代内存大小为32MB;

将测试的Web页面部署到Tomcat之后,使用JMeter对其进行压力测试,使用10个线程并发请求,每个线程循环请求1000次。在启动压力测试一段时间后,Tomcat环境发生了堆溢出异常如下:

  • java.lang.OutOfMemoryError: Java heap space
  • Dumping heap to /Users/LennonChin/Desktop/Java_Test/java_pid7292.hprof ...
  • Heap dump file created [53265027 bytes in 1.213 secs]
  • Exception in thread "Thread-25" java.lang.OutOfMemoryError: Java heap space
  • Exception in thread "AWT-Shutdown" Exception in thread "http-8080-7" java.lang.OutOfMemoryError: Java heap space
  • 2015-6-19 11:52:41 unknown unknown
  • 严重: Error processing request
  • java.lang.OutOfMemoryError: Java heap space
  • 2015-6-19 11:52:42 org.apache.jasper.runtime.JspFactoryImpl internalGetPageContext
  • 严重: Exception initializing page context
  • java.lang.OutOfMemoryError: Java heap space
  • at org.apache.catalina.session.ManagerBase.generateSessionId(ManagerBase.java:1206)
  • at org.apache.catalina.session.ManagerBase.createSession(ManagerBase.java:997)
  • at org.apache.catalina.session.StandardManager.createSession(StandardManager.java:285)
  • at org.apache.catalina.connector.Request.doGetSession(Request.java:2458)
  • at org.apache.catalina.connector.Request.getSession(Request.java:2167)
  • at org.apache.catalina.connector.RequestFacade.getSession(RequestFacade.java:833)
  • at org.apache.catalina.connector.RequestFacade.getSession(RequestFacade.java:844)
  • at org.apache.jasper.runtime.PageContextImpl._initialize(PageContextImpl.java:146)
  • at org.apache.jasper.runtime.PageContextImpl.initialize(PageContextImpl.java:124)
  • at org.apache.jasper.runtime.JspFactoryImpl.internalGetPageContext(JspFactoryImpl.java:107)
  • at org.apache.jasper.runtime.JspFactoryImpl.getPageContext(JspFactoryImpl.java:63)
  • at org.apache.jsp.index_jsp._jspService(index_jsp.java:44)
  • at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
  • at javax.servlet.http.HttpServlet.service(HttpServlet.java:723)
  • at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:388)
  • at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:321)
  • at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:267)
  • at javax.servlet.http.HttpServlet.service(HttpServlet.java:723)
  • at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
  • at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
  • at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
  • at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
  • at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
  • at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
  • at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
  • at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
  • at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:859)
  • at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:610)
  • at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:503)
  • at java.lang.Thread.run(Thread.java:695)

打开生成的转储文件,可以观察到下面的记录:

3.串行垃圾收集器堆溢出日志-1.png

4.串行垃圾收集器堆溢出日志-2.png

可以发现,这个溢出是因为过多的请求导致org.apache.catalina.session.StandardManager创建了过多的session导致堆溢出。查看生成的GC日志片段如下:

  • 13.708: [Full GC 13.708: [Tenured: 21887K->21887K(21888K), 0.0819178 secs] 31679K->31679K(31680K), [Perm : 18954K->18954K(32768K)], 0.0819544 secs] [Times: user=0.08 sys=0.00, real=0.08 secs]
  • 13.790: [Full GC 13.790: [Tenured: 21887K->21887K(21888K), 0.0789649 secs] 31679K->31679K(31680K), [Perm : 18954K->18954K(32768K)], 0.0790084 secs] [Times: user=0.08 sys=0.00, real=0.08 secs]
  • 13.874: [Full GC 13.874: [Tenured: 21887K->21887K(21888K), 0.0770197 secs] 31679K->31679K(31680K), [Perm : 18954K->18954K(32768K)], 0.0770652 secs] [Times: user=0.08 sys=0.00, real=0.08 secs]
  • 13.952: [Full GC 13.952: [Tenured: 21887K->21887K(21888K), 0.0708793 secs] 31679K->31679K(31680K), [Perm : 18955K->18955K(32768K)], 0.0709155 secs] [Times: user=0.07 sys=0.00, real=0.07 secs]
  • 14.024: [Full GC 14.024: [Tenured: 21888K->21888K(21888K), 0.0698341 secs] 31679K->31679K(31680K), [Perm : 18955K->18955K(32768K)], 0.0698804 secs] [Times: user=0.07 sys=0.00, real=0.07 secs]

可以发现,Tomcat进行了大量频繁的Full GC,老年代的总大小为21888KB,已使用了大部分,整个堆的大小为31680KB,使用了31679KB。查看JMeter的聚合报告如下:

5.串行垃圾收集器测试JMeter聚合报告.png

由于发生了堆溢出,导致部分大部分后续的请求是失败的,请求的吞吐量持续下降,只有45次/秒。

接下来尝试增加堆的大小以提升性能,更改参数如下:

  • CATALINA_OPTS="-Xloggc:/Users/qinly/Desktop/Java_Test/gc.log -XX:+PrintGCDetails -Xms32M -Xmx512M -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/Users/qinly/Desktop/Java_Test/ -XX:+UseSerialGC -XX:PermSize=32M"

相对于之前的设置,使用参数-Xmx512M将最大堆内存设置了512MB,再次进行压测,得到的GC日志如下:

  • 1.650: [GC 1.650: [DefNew: 8704K->1088K(9792K), 0.0059748 secs] 8704K->1325K(31680K), 0.0060444 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
  • 1.901: [GC 1.901: [DefNew: 9792K->967K(9792K), 0.0064291 secs] 10029K->2200K(31680K), 0.0064632 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
  • 2.178: [GC 2.178: [DefNew: 9671K->763K(9792K), 0.0046639 secs] 10904K->2931K(31680K), 0.0047049 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
  • 2.375: [GC 2.375: [DefNew: 9467K->1088K(9792K), 0.0063048 secs] 11635K->5320K(31680K), 0.0063387 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
  • 2.441: [GC 2.441: [DefNew: 9792K->1088K(9792K), 0.0122826 secs] 14024K->12046K(31680K), 0.0123176 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
  • 2.475: [GC 2.475: [DefNew: 9792K->1088K(9792K), 0.0125511 secs] 20750K->18719K(31680K), 0.0125841 secs] [Times: user=0.01 sys=0.01, real=0.02 secs]
  • 2.506: [GC 2.506: [DefNew: 9792K->1088K(9792K), 0.0127642 secs]2.519: [Tenured: 24531K->24576K(24576K), 0.0521178 secs] 27423K->25619K(34368K), [Perm : 15633K->15633K(32768K)], 0.0651392 secs] [Times: user=0.06 sys=0.00, real=0.07 secs]
  • 2.590: [GC 2.590: [DefNew: 16448K->2048K(18496K), 0.0368156 secs] 41024K->38167K(59456K), 0.0368486 secs] [Times: user=0.03 sys=0.00, real=0.04 secs]
  • 2.652: [GC 2.652: [DefNew: 18496K->2047K(18496K), 0.0217260 secs]2.674: [Tenured: 47845K->47871K(47872K), 0.0869958 secs] 54615K->47907K(66368K), [Perm : 15657K->15657K(32768K)], 0.1093052 secs] [Times: user=0.10 sys=0.00, real=0.11 secs]
  • 45.282: [GC 45.312: [DefNew: 32000K->1880K(35968K), 0.0356879 secs] 79871K->49752K(115756K), 0.0660870 secs] [Times: user=0.03 sys=0.00, real=0.07 secs]
  • 77.418: [GC 77.418: [DefNew: 33880K->3968K(35968K), 0.0214829 secs] 81752K->58423K(115756K), 0.0215342 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
  • 78.751: [GC 78.751: [DefNew: 35968K->3968K(35968K), 0.0298847 secs] 90423K->70986K(115756K), 0.0299376 secs]
  • 166.523: [GC 166.523: [DefNew: 35908K->3967K(35968K), 0.0144602 secs] 102927K->76474K(115756K), 0.0145167 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
  • Heap
  • def new generation total 35968K, used 25676K [7dae00000, 7dd500000, 7e58a0000)
  • eden space 32000K, 67% used [7dae00000, 7dc3332d8, 7dcd40000)
  • from space 3968K, 99% used [7dcd40000, 7dd11fff8, 7dd120000)
  • to space 3968K, 0% used [7dd120000, 7dd120000, 7dd500000)
  • tenured generation total 79788K, used 72506K [7e58a0000, 7ea68b000, 7fae00000)
  • the space 79788K, 90% used [7e58a0000, 7e9f6e828, 7e9f6ea00, 7ea68b000)
  • compacting perm gen total 32768K, used 19672K [7fae00000, 7fce00000, 800000000)
  • the space 32768K, 60% used [7fae00000, 7fc136220, 7fc136400, 7fce00000)
  • No shared spaces configured.

会发现,在请求过程中,随着请求的增加,堆的大小也在不断扩展。同时调整后的请求吞吐量大大提升,到了3300余次/秒,没有请求失败的情况:

6.调整最大堆大小后的JMeter聚合报告.png

由于在上面的请求中,堆的大小最后稳定在115756KB左右,因此可以尝试调整初始堆大小以减少GC操作,调整后的参数如下:

  • CATALINA_OPTS="-Xloggc:/Users/qinly/Desktop/Java_Test/gc.log -XX:+PrintGCDetails -Xms128M -Xmx512M -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/Users/qinly/Desktop/Java_Test/ -XX:+UseSerialGC -XX:PermSize=32M"

相对于之前的设置,使用参数-Xms128M将初始堆内存设置了128MB,这个大小是满足之前的请求压测所需的大小的;再次进行压测,得到的GC日志如下:

  • 4.850: [GC 4.850: [DefNew: 34944K->4152K(39296K), 0.0131496 secs] 34944K->4152K(126720K), 0.0132184 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
  • 5.023: [GC 5.023: [DefNew: 38717K->4352K(39296K), 0.0490089 secs] 38717K->30254K(126720K), 0.0490484 secs] [Times: user=0.05 sys=0.01, real=0.05 secs]
  • 5.097: [GC 5.097: [DefNew: 38791K->4352K(39296K), 0.0486193 secs] 64693K->57007K(126720K), 0.0486555 secs] [Times: user=0.05 sys=0.01, real=0.05 secs]
  • 5.168: [GC 5.168: [DefNew: 39296K->4352K(39296K), 0.0477271 secs] 91951K->84284K(126720K), 0.0477575 secs] [Times: user=0.04 sys=0.01, real=0.05 secs]
  • 5.237: [GC 5.237: [DefNew: 38483K->4352K(39296K), 0.0457583 secs]5.282: [Tenured: 107023K->107023K(107200K), 0.1662172 secs] 118416K->111375K(146496K), [Perm : 15686K->15686K(32768K)], 0.2127998 secs] [Times: user=0.20 sys=0.01, real=0.21 secs]
  • 5.506: [GC 5.506: [DefNew: 71424K->8895K(80320K), 0.1516625 secs] 178447K->164555K(258696K), 0.1517033 secs] [Times: user=0.14 sys=0.01, real=0.15 secs]
  • 43.518: [GC 43.518: [DefNew: 80319K->8896K(80320K), 0.0401541 secs] 235979K->174080K(258696K), 0.0402175 secs]

同时查看JMeter的聚合报告,可以发现请求的吞吐量也大大提升了,到了6300余次/秒:

7.调整初始堆大小后的JMeter聚合报告.png