在JVM中记录世界停顿

不同的事件可能导致JVM暂停所有应用程序线程。 这种暂停称为世界停止（STW）暂停。 触发STW暂停的最常见原因是垃圾回收（ 例如github中的示例 ），但是不同的JIT操作（ 示例 ），偏向锁吊销（ 示例 ），某些JVMTI操作以及更多其他 操作也需要停止应用程序。

可以安全停止应用程序线程的点称为“意外点”。 该术语也经常用于指代所有STW暂停。

启用GC日志或多或少是常见的。 但是，这不会捕获所有安全点上的信息。 要获得全部信息，请使用以下JVM选项：

-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime

如果您想知道显式引用GC的命名，请不要惊慌-启用这些选项会记录所有安全点，而不仅仅是垃圾收集暂停。 如果您运行下面的示例（ github中的源代码），并带有上面指定的标志

public class FullGc {
  private static final Collection<Object> leak = new ArrayList<>();
  private static volatile Object sink;

  public static void main(String[] args) {
    while (true) {
      try {
        leak.add(new byte[1024 * 1024]);
        sink = new byte[1024 * 1024];
      } catch (OutOfMemoryError e) {
        leak.clear();
      }
    }
  }
}

您应该在标准输出中看到类似于以下内容的条目：

Application time: 0.3440086 seconds
Total time for which application threads were stopped: 0.0620105 seconds
Application time: 0.2100691 seconds
Total time for which application threads were stopped: 0.0890223 seconds

读取起来很容易（尤其是与GC日志进行比较）–从上面您可以看到应用程序在前344毫秒内成功完成了有用的工作，将所有线程暂停了62毫秒，接着是210毫秒的有用工作和另外89毫秒的暂停。

您可以将这些标志与GC标志结合使用，例如，当再次运行同一程序并添加-XX：+ PrintGCDetails时 ，输出将类似于以下内容：

[Full GC (Ergonomics) [PSYoungGen: 1375253K->0K(1387008K)] [ParOldGen: 2796146K->2049K(1784832K)] 4171400K->2049K(3171840K), [Metaspace: 3134K->3134K(1056768K)], 0.0571841 secs] [Times: user=0.02 sys=0.04, real=0.06 secs] 
Total time for which application threads were stopped: 0.0572646 seconds, Stopping threads took: 0.0000088 seconds

基于以上内容，我们看到应用程序线程被迫停止57毫秒以进行垃圾回收。 等待所有应用程序线程到达安全点所花的时间为8微秒。 但是，如果我们再举一个示例（ github中的源代码 ）并使用相同的选项运行它，我们可能会看到以下输出：

Total time for which application threads were stopped: 0.0001273 seconds, Stopping threads took: 0.0000196 seconds
Total time for which application threads were stopped: 0.0000648 seconds, Stopping threads took: 0.0000174 seconds

由此，我们实际上无法推断出导致暂停的原因，因为没有垃圾收集活动。 如果您想更详细地了解其他安全点，这里有几个JVM参数供您选择：

-XX:+PrintSafepointStatistics  -XX:PrintSafepointStatisticsCount=1

启用它们会使JVM将其他信息记录到标准输出中，类似于以下内容：

5.141: RevokeBias                       [      13          0              2    ]      [     0     0     0     0     0    ]  0  
Total time for which application threads were stopped: 0.0000782 seconds, Stopping threads took: 0.0000269 seconds

根据以下顺序显示有关安全点的信息：

• 自JVM启动以来的时间戳（以毫秒为单位）（上例中为5.141）
• 触发暂停的操作的名称（ RevokeBias ）。
  • 如果看到“无虚拟机操作”，则意味着这是所谓的“保证安全点”。
• 在安全点停止的线程数（13）
• 在安全点开始时运行的线程数（0）
• vm操作开始执行时被阻塞的线程数（2）
• 到达安全点和执行操作的各个阶段的时间（全零）

因此，现在我们看到，使用偏向锁可能会导致许多STW暂停发生，即使它们仅花费数十微秒的时间。 在大规模并行的日子里立即禁用它们并不罕见。

总而言之，通过随时记录这些数据，您确实可以为自己省去一些麻烦。 为此，请指定以下JVM选项：

-XX:+LogVMOutput -XX:LogFile=vm.log

并且所有JVM的输出都将存储到vm.log文件中。 但是，基于这些日志进行解释和执行是一个非常广泛的话题，不在本文的讨论范围之内，但是将来我可能会写一两篇有关它的文章，因此，如有兴趣，请随时关注–通过我们的Twitter订阅或通过RSS feed 。

如果您想立即阅读更多内容，请阅读Nitsan Wakart的精彩博客文章 ：当然还有OpenJDK源代码 。

翻译自: https://www.javacodegeeks.com/2015/04/logging-stop-the-world-pauses-in-jvm.html