JVM GC中Stop the world案例实战

GC中Stop the world案例实战

为了更好的理解GC中的Stop the world案例，就必须先了解何为Stop the World方式。所谓的Stop the World机制，简称STW，即在执行垃圾收集算法时,Java应用程序的其他所有除了垃圾收集收集器线程之外的线程都被挂起(具体运行机制见图4-1)。此时，系统只能允许GC线程进行运行，其他线程则会全部暂停，等待GC线程执行完毕后才能再次运行。这些工作都是由虚拟机在后台自动发起和自动完成的，是在用户不可见的情况下把用户正常工作的线程全部停下来，这对于很多的应用程序，尤其是那些对于实时性要求很高的程序来说是难以接受的。但是有些时候对于虚拟机来说采用Stop
the world机制是无法避免的，例如采用复制算法时，为了保证在复制存活的对象的时候，对象的一致性，不然要使应用程序被挂起。但是随着java虚拟机的发展，HotSpot虚拟机团队为达到更好用户体验而一直进行着努力，不断的对垃圾收集器进行着改进，随着JDK的版本的不断更新，更好的垃圾收集器的出现，用户线程的停顿时间也在不断缩短，虽然这一时间现阶段仍然不能消除，但相信不久的未来一定会有更好的垃圾收集器被发现，从而完全达到用户对于虚拟机垃圾回收的性能要求。



图4-1Stop the World机制的GC
         对于很多的垃圾收集器来说，都会采用Stop the World机制来进行垃圾回收。具体来讲，在Java虚拟机的Serial, ParNew, Parallel Scanvange, ParallelOld, Serial Old全程都会Stop the world，JVM这时候只运行GC线程，不运行用户线程。而CMS主要分为 initial Mark, Concurrent Mark, ReMark,Concurrent Sweep等阶段，initial Mark和Remark占整体的时间比较较小，它们会Stop
the world. Concurrent Mark和Concurrent Sweep会和用户线程一起运行。虽然CMS减少了stop the world的次数，不可避免地让整体GC的时间拉长了。各个垃圾收集器GC采用的方式见图4-2。
                                               


图4-2各个垃圾收集器GC采用的方式
 

了解了Stop the world机制，接下来将展示一个案例来讲解GC中Stop the World机制具体的运行机制，让读者有一个更直观的印象。

/**
*案例4.1 测试的SWT机制的GC
**/
package ErrorType;
import java.util.ArrayList;
import java.util.List;
/**
*
**/
class Person{
private String name;
private String age;
public String getName() {
return name;
}
public void setName(String name) {
this.name = name;
}
public String getAge() {
return age;
}
public void setAge(String age) {
this.age = age;
}
}

public class Test {
public static void main(String[] args) {
List<Person> persons = new ArrayList<Person>();
long start = 0L;
long end = 0L;
long runtime = 0L;
int count = 0;
while(true) {
start = System.currentTimeMillis();
persons.add(new Person());
count++;
end = System.currentTimeMillis();
runtime = end - start;
System.out.println(count + " : Use time in one operation:" + runtime + "ms");
start = end;
}
}

}

Eclipse参数设置：

-Xms100M -Xmx100M -Xss128k -XX:+PrintGCDetails
-XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:./gclogs

参数解释：

-Xms和-Xmx分别设置了堆的初始大小为10M和最大大小也为10M，这两个参数一般配合使用，且设置为同一值。-Xss参数设定了每个线程堆栈大小为128k  -XX:+PrintGCDetails 表示打印GC的信息，这里通过-Xloggc:./gclogs将GC信息输出到gclogs文件中。-XX:+PrintGCDateStamps则表示在GC信息里显示当前时间。-XX:+PrintHeapAtGC表示在每次GC前显示当前堆中的状态。

这里截取部分输出：

38503 : Use time in one operation:0ms
38504 : Use time in one operation:0ms
38505 : Use time in one operation:1ms
38506 : Use time in one operation:0ms
38507 : Use time in one operation:0ms
38508 : Use time in one operation:0ms
38509 : Use time in one operation:0ms

可以看出，正常进行一次persons.add(newPerson())操作耗时是不到1ms的，但是在将第38505个对象进行persons.add(new Person())操作时，耗时将达到1ms，这说明这时系统进行了GC，且使用了STW机制。

另一方面，从GC日志文件gclogs中，可以看到如下内容：
Java HotSpot(TM) 64-Bit Server VM (25.73-b02) for windows-amd64 JRE (1.8.0_73-b02), built on Jan 29 2016 17:38:49 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 12034908k(8867180k free), swap 13345628k(8226180k free)
CommandLine flags: -XX:InitialHeapSize=104857600 -XX:MaxHeapSize=104857600 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:SurvivorRatio=1 -XX:ThreadStackSize=128 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC
{Heap before GC invocations=1 (full 0):
PSYoungGen total 22528K, used 11264K [0x00000000fdf00000, 0x0000000100000000, 0x0000000100000000)
eden space 11264K, 100% used [0x00000000fdf00000,0x00000000fea00000,0x00000000fea00000)
from space 11264K, 0% used [0x00000000ff500000,0x00000000ff500000,0x0000000100000000)
to space 11264K, 0% used [0x00000000fea00000,0x00000000fea00000,0x00000000ff500000)
ParOldGen total 68608K, used 0K [0x00000000f9c00000, 0x00000000fdf00000, 0x00000000fdf00000)
object space 68608K, 0% used [0x00000000f9c00000,0x00000000f9c00000,0x00000000fdf00000)
Metaspace used 2750K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 301K, capacity 386K, committed 512K, reserved 1048576K
2016-05-15T12:59:45.962+0800: 0.988: [GC (Allocation Failure) [PSYoungGen: 11264K->1226K(22528K)] 11264K->1234K(91136K), 0.0047652 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]


可以看到在GC前，新生代eden区域使用已经达到100%，从而导致新对象的内存分配失败引发了Minor GC,日志里显示了PSYoungGen、ParOldGen以及Metaspace等区域的使用情况，这里不做详细解释。

下面，主要讲解下最后的GC输出信息。

         YGC发生于2016-05-15T12:59:45.962+0800，YGC前新生代占用大小为11264K，约为12M，YGC后新生代占用内存大小为1226K，约为1M，而新生代总大小为22528K，约为22M。YGC前JVM堆内存占用为11264K，YGC后堆内存占用为1234K，JVM对总大小为91136K，约91M。期间用户态耗时小于0.01s,内核态耗时小于0.01s，实际耗时为0.01s。

         同样JVM中给开发者提供了一个参数，-XX:+PrintGCApplicationStoppedTime，来显示应用程序在Java虚拟机进行所有GC暂停的总耗时。

         到这里，STW的例子就讲完了，相信对着对GC过程又有了新一层的认识了。