JVM优化系列-Stop-The-World实战

导语
垃圾收集器的主要任务是识别和回收垃圾对象进行内存清理，为了让垃圾回收器可正常高效执行，在大部分的情况下会请求系统进入到一个停顿阶段，在这个停顿阶段对所欲应用进程进行终止，然后执行垃圾清理操作，只有所有应用线程都停止了才不会有新的垃圾产生。同时保证在停顿瞬间所有应用的一致性，更有利于垃圾清理的标记每个对象。所以在垃圾清理的过程中这样的停顿被称为是Stop-The-World。

文章目录

示例
分析问题
总结

示例

public class StopWorldTest {public static class MyThread extends Thread{HashMap map = new HashMap();@Overridepublic void run() {try{while (true){if (map.size()*512/1024/1024>=900){map.clear();System.out.println("clean map");}byte[] b1 ;for (int i =0;i<100;i++){b1 = new byte[512];map.put(System.nanoTime(),b1);}Thread.sleep(1);}} catch (InterruptedException e) {e.printStackTrace();}}}public static class PrintThread extends Thread{public static final long starttime = System.currentTimeMillis();@Overridepublic void run() {try {while (true){long t = System.currentTimeMillis()-starttime;System.out.println(t/1000+"."+t%1000);Thread.sleep(100);}} catch (InterruptedException e) {e.printStackTrace();}}}public static void main(String[] args) {MyThread t = new MyThread();PrintThread p = new PrintThread();t.start();p.start();}
}

上面代码，开启了两个线程，PrintThread负责在0.1秒的瞬间内进行一次时间戳输出。MyThread则是负责消耗内存资源，引起GC操作。当内存消耗大于900MB的时候，清空内存，防止内存溢出。

添加运行参数

-Xmx1g -Xms1g -Xmn512k -XX:+UseSerialGC -Xloggc:gc.log -XX:+PrintGCDetails

运行程序

Exception in thread "Thread-0" java.lang.OutOfMemoryError - klass: 'java/lang/OutOfMemoryError'
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  Internal Error (exceptions.cpp:427), pid=1230, tid=19715
#  fatal error: ExceptionMark destructor expects no pending exceptions
#
# JRE version: Java(TM) SE Runtime Environment (8.0_74-b02) (build 1.8.0_74-b02)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (25.74-b02 mixed mode bsd-amd64 compressed oops)
# Failed to write core dump. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again
#
# An error report file with more information is saved as:
# /Users/nihui/Documents/IDEAProject/JVM/jvm-perm/hs_err_pid1230.log
#
# If you would like to submit a bug report, please visit:
#   http://bugreport.java.com/bugreport/crash.jsp
#

45.676Exception in thread "MyThread-"
47.115
47.822
48.553
49.281
50.18
50.748*** java.lang.instrument ASSERTION FAILED ***: "!errorOutstanding" with message can't create name string at JPLISAgent.c line: 807java.lang.OutOfMemoryError: Java heap spaceat com.nihui.stoptheworld.StopWorldTest$MyThread.run(StopWorldTest.java:25)
55.750
58.860

其实在之前的分享中有看到过实际分配的内存跟代码中的内容其实是不相符的，在实际内存使用过程中还有考虑到其他类对象创建以及对象索引创建，所以如果没有不能合理的调整内存大小分配是无法出现测试结果的。

分析问题

对于这个问题的分析也是对之前学过的内容的总结。
首先来看看垃圾回收日志中其实在26秒左右的时候就已经Heap内存达到了900M，但是实际上并没有执行垃圾回收。而知继续扩展内存。但是最大的堆内存为1G如上面图中所展示的一样，继续分配就会导致Heap内存溢出，但是这个时候程序并没有停止。因为其中有一个PrintThread线程没有停止。

如上图所示，在内存溢出之后线程MyThread已经死了，而不是进入sleep。这个从另一个角度上可以印证了JVM的堆内存是线程共享的内存区域，当一个线程因为内存溢出操作而导致线程关闭，不会影响其他线程使用对堆内存。对堆内存进行垃圾回收之后，其他线程又可以继续使用，但是对于已经停止的线程就提供不了其他的帮助了。

上面说到当堆内存达到900MB的时候回自动对Map 进行clear但是实际的运行时调用对应代码之后并没有执行clear操作，就是因为没有考虑到整个的JVM使用中还有其他内容也在使用内存空间，当等到整个的线程运行完分配完内存之后，就已经是内存溢出了。

下面将代码调整到如下的内容

public class StopWorldTest {public static class MyThread extends Thread{HashMap map = new HashMap();@Overridepublic void run() {try{while (true){if (map.size()*512/1024/1024>=500){map.clear();System.out.println("clean map");}byte[] b1 ;for (int i =0;i<100;i++){b1 = new byte[512];map.put(System.nanoTime(),b1);}Thread.sleep(1);}} catch (InterruptedException e) {e.printStackTrace();}}}public static class PrintThread extends Thread{public static final long starttime = System.currentTimeMillis();@Overridepublic void run() {try {while (true){long t = System.currentTimeMillis()-starttime;System.out.println(t/1000+"."+t%1000);Thread.sleep(100);}} catch (InterruptedException e) {e.printStackTrace();}}}public static void main(String[] args) {MyThread t = new MyThread();PrintThread p = new PrintThread();t.setName("MyThread");p.setName("PrintThread");t.start();p.start();}
}

运行结果

30.282: [GC (Allocation Failure) 30.282: [DefNew: 447K->447K(448K), 0.0000344 secs]30.282: [Tenured: 1047932K->491318K(1048064K), 0.4429925 secs] 1048380K->491318K(1048512K), [Metaspace: 8690K->8690K(1056768K)], 0.4431948 secs] [Times: user=0.44 sys=0.00, real=0.44 secs] 46.834: [GC (Allocation Failure) 46.834: [DefNew: 447K->447K(448K), 0.0000142 secs]46.834: [Tenured: 1047967K->477397K(1048064K), 0.3491591 secs] 1048415K->477397K(1048512K), [Metaspace: 8792K->8792K(1056768K)], 0.3492485 secs] [Times: user=0.35 sys=0.00, real=0.35 secs] 63.685: [GC (Allocation Failure) 63.685: [DefNew: 447K->447K(448K), 0.0000318 secs]63.685: [Tenured: 1047893K->464358K(1048064K), 0.3490292 secs] 1048341K->464358K(1048512K), [Metaspace: 8820K->8820K(1056768K)], 0.3491777 secs] [Times: user=0.35 sys=0.00, real=0.35 secs]

从GC日志中可以看到，在整个的阶段中新生代的GC操作是比较频繁的，但是每一次执行GC操作耗时都比较少，老年代GC发生的次数比较少并且发生之后会直接影响到heap的使用结构，对于未使用的与已使用的影响较大。每一次GC操作消耗的时间要比新生代的GC操作要长。这种现象和虚拟机的参数设置有关。下面就来看看其他参数设置的效果。

-Xmx1g -Xms1g -Xmn900m -XX:+UseSerialGC -Xloggc:gc.log -XX:+PrintGCDetails

整个的内存GC都有所下降，并且全部是耗时比较长的GC操作，与之前的无法相比。

总结

在使用JVM内存调优的时候一定要考虑到内存的合理分配，给整个程序运行过程中的每个使用的对象都要分配合理的内存结构，不然就会出现上面的内存溢出的异常，导致程序处于假死不能提供服务的状态。对于其他的测试只需要调整上面的对应的参数来看看不同内存区域对于应用程序的影响。