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

jvm优化