[Rescan (parallel) , 0.0291598 secs]14
.395:
[weak refs processing, 0.0000232 secs]14
.395:
[class unloading, 0.0117661 secs]14
.407:
[scrub symbol table, 0.0015323 secs]14
.409:
[scrub string table, 0.0003221 secs][1 CMS-remark: 976591K(1756416K)] 1159184
K(2063104
K), 0
.0462010 secs]
[Times: user=0.14 sys=0.00, real=0.05 secs]14
.412:
[CMS-concurrent-sweep-start]14
.633:
[CMS-concurrent-sweep: 0.221/0.221 secs] [Times: user=0.37 sys=0.00, real=0.22 secs]14
.633:
[CMS-concurrent-reset-start]14
.636:
[CMS-concurrent-reset: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]从以上能够看出，在运行了12次新生代GC后的确出现了一些“不太寻常”的事情。但并不是执行了两次Full GC，这个“不寻常”的事情其实只是在年老代中执行了一次包含了数个阶段的GC而已：
- 初始标记阶段，从0.0041705 秒或者说4ms的时候开始。这一阶段是一次“stop-the-world”事件，所有的应用线程都被暂停以便进行初始标记。
- 并发地执行标记和预清理(Preclean)的阶段。这是和应用线程一起并发执行的。
- 最终标记阶段，从0.0462010秒或者说46毫秒的时候开始。这一阶段也同样是“stop-the-world”的。
- 并发地进行清除操作。正如名字所说的，这一阶段也无需中断应用线程，可以并发地执行。
因此我们从实际的GC日志中所看到的是这样——其实没有什么两次所谓的Full GC,只有一次清理年老代空间的Major GC而已。
如果你再看下jstat输出的结果，就不难得出结论了。它确切地指出了两次stop-the-world事件，总耗时50ms，这段时间内所有活跃线程都会出现延迟响应。不过如果你想据此来优化吞吐量的话，很可能会徒劳无功——jstat只列出了两次stop-the-world的初始标记及最终标记的部分，而并发执行的那部分工作却被它给隐藏掉了。
12/12 首页 上一页 10 11 12
