jvm gc停顿
不同的事件可能导致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
jvm gc停顿