jvm的stop the world时间过长优化

现象：小米有一个比较大的公共离线HBase集群，用户很多，每天有大量的MapReduce或Spark离线分析任务在进行访问，同时有很多其他在线集群Replication过来的数据写入，集群因为读写压力较大，且离线分析任务对延迟不敏感，所以其G1GC的MaxGCPauseMillis设置是500ms。

但是随着时间的推移，我们发现了一个新的现象，线程的STW时间可以到3秒以上，但是实际GC的STW时间却只有几百毫秒！

打印GC日志

• -XX:+PrintGC

• -XX:+PrintGCDetails

• -XX:+PrintGCApplicationStoppedTime

• -XX:+PrintHeapAtGC

• -XX:+PrintGCDateStamps

• -XX:+PrintAdaptiveSizePolicy

• -XX:+PrintTenuringDistribution

具体的日志log示例如下：[Times: user=1.51 sys=0.67, real=0.14 secs]

2019-06-25T12:12:43.376+0800: 3448319.277: Total time for which application threads were stopped: 2.2645818 seconds, Stopping threads took: xxx seconds

-XX:+PrintGCApplicationStoppedTime会打出类似上面的日志，这个stopped时间是JVM里所有STW的时间，不止GC。我们遇到的现象就是stopped时间远大于上面的GC real耗时，比如GC只耗时0.14秒，但是线程却stopped了2秒多。这个时候大概率就是GC时线程进入Safepoint耗时过长，所以需要2个新的GC参数来打印出Safepoint的情况。

打印Safepoint相关日志

• -XX:+PrintSafepointStatistics

• -XX:PrintSafepointStatisticsCount=1

需要注意的是Safepoint的情况是打印到标准输出里的，具体的日志log示例如下：

vmop    [threads: total initially_running wait_to_block] 65968.203: ForceAsyncSafepoint [931   1   2]

这部分日志是时间戳，VM Operation的类型，以及线程