jvm gc停顿_在JVM中记录世界停顿

古城微笑少年丶 2023-02-25 03:45 11阅读 0赞

jvm gc停顿

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

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

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

-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime

如果您想知道显式引用GC的命名，请不要惊慌-启用这些选项会记录所有安全点，而不仅仅是垃圾收集暂停。 如果您运行下面的示例（ [github中的源代码），][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中的源代码][Link 2] ）并使用相同的选项运行它，我们可能会看到以下输出：

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）
 *  到达安全点和执行操作的各个阶段的时间（全零）

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

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

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

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

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

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

jvm gc停顿

[format_png]: http://imgconvert.csdnimg.cn/aHR0cHM6Ly93d3cuamF2YWNvZGVnZWVrcy5jb20vd3AtY29udGVudC91cGxvYWRzLzIwMTUvMDQvc3RvcC10aGUtd29ybGQtcGF1c2VzLTE1MHgxNTAuanBlZw?x-oss-process=image/format,png
[github]: https://github.com/gvsmirnov/java-perv/blob/master/labs-8/src/main/java/ru/gvsmirnov/perv/labs/safepoints/FullGc.java
[Link 1]: https://github.com/gvsmirnov/java-perv/blob/master/labs-8/src/main/java/ru/gvsmirnov/perv/labs/safepoints/Deoptimization.java
[Link 2]: https://github.com/gvsmirnov/java-perv/blob/master/labs-8/src/main/java/ru/gvsmirnov/perv/labs/safepoints/BiasedLocks.java
[JVMTI]: /images/20230209/bfe417308dab46d68dd39995a4342da7.png
[Link 3]: http://hg.openjdk.java.net/jdk9/jdk9/hotspot/file/0e31ab6e8375/src/share/vm/runtime/vm_operations.hpp
[Link 4]: https://blogs.oracle.com/dave/entry/biased_locking_in_hotspot
[Twitter]: https://twitter.com/intent/follow?region=follow_link&screen_name=javaplumbr
[RSS feed]: https://plumbr.eu/blog/feed
[Nitsan Wakart]: https://psy-lob-saw.blogspot.com/2014/03/where-is-my-safepoint.html
[OpenJDK]: http://hg.openjdk.java.net/jdk9/jdk9/hotspot/file/tip/src/share/vm/runtime/safepoint.cpp
[https_www.javacodegeeks.com_2015_04_logging-stop-the-world-pauses-in-jvm.html]: https://www.javacodegeeks.com/2015/04/logging-stop-the-world-pauses-in-jvm.html