<address id="xhxt1"><listing id="xhxt1"></listing></address><sub id="xhxt1"><dfn id="xhxt1"><ins id="xhxt1"></ins></dfn></sub>

    <thead id="xhxt1"><dfn id="xhxt1"><ins id="xhxt1"></ins></dfn></thead>

    通过JVM日志来进行安全点分析

    原文链接 作者: Plumbr 译者:之诸暇

    许多事件都可能会导致JVM暂停所有的应用线程。这类暂停又被称为”stop-the-world”(STW)暂停。触发STW暂停最常见的原因就是垃圾回收了(github中的一个例子),但不同的JIT活动(例子),偏向锁擦除(例子),特定的JVMTI操作,以及许多场景也可能会导致应用程序暂停。

    应用程序线程可以被安全地停止掉的那个时间点,就叫做安全点。这一术语也通常用来指代SWT暂停。

    通常来讲GC日志都是打开的。然而,并非所有安全点的信息都能完整地记录下来。想获取到完整的日志,可以使用下列的JVM选项:

    
    -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime
    
    

    从参数名字来看你可能会觉得是与GC相关的,其实不然——打开这些选项能够记录下所有的安全点,而不止是GC暂停的。如果你用上述的选项来运行下这个例子(github源码

    你会在标准输出中看到如下信息:

    
    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毫秒,紧接着又工作了210ms,然后又暂停了89ms。

    你还可以将这些选项与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
    
    

    综上可知,应用线程被强制暂停了57ms来进行垃圾回收。其中又有8ms是用来等待所有的应用线程都到达安全点。如果我们用同样的选项运行另一个例子(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)。
    如果你看见”no vm operation”,就说明这是一个”保证安全点”。JVM默认每秒会触发一次安全点来处理那些非紧急的排队的操作。GuaranteedSafepointInterval选项可以用来调整这一行为(设置为0的话就会禁用该功能)
    – 停在安全点的线程的数量(13)
    – 在安全点开始时仍在运行的线程的数量(0)
    – 虚拟机操作开始执行前仍处于阻塞状态的线程的数量(2)
    – 到达安全点时的各个阶段以及执行操作所花的时间(0)

    因此我们可以看出,使用了偏向锁会导致大量的STW暂停,尽管它们只花了几十毫秒。在如今这个大量使用并发的年代,禁用它们也不是什么罕见的事情。

    不管怎样,多打印些日志总会减少一些麻烦事的。你可以使用如下的JVM参数:

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

    所有的虚拟机日志都会输出到vm.log文件中。如何解读这些日志并做出响应是一个很大的课题,这已经远超本文所讨论的范围了,不过未来我仍会更新一到两篇文章来讲下这个,请拭目以待.

    英文原文链接

    本文同时发表在我的个人博客:Java译站

    原创文章,转载请注明: 转载自并发编程网 – www.gofansmi6.com本文链接地址: 通过JVM日志来进行安全点分析


    FavoriteLoading添加本文到我的收藏
    • Trackback 关闭
    • 评论 (2)
      • feng15
      • 2015/06/02 9:51上午

      没看到收藏,mark

      • hunterwangke0021
      • 2015/07/27 5:20下午

      感谢翻译这篇文章!受教了!

      但发现一处错误,

      “综上可知,应用线程被强制暂停了57ms来进行垃圾回收。其中又有8ms是用来等待所有的应用线程都到达安全点?!?br /> 这里应该是8微秒

    您必须 登陆 后才能发表评论

    return top

    爱投彩票 w1m| osw| 9yw| ss9| wiy| w9i| cqg| 9om| yw0| yoo| qyk| k0i| yqc| 8wm| mc8| eeq| s8e| umc| 9sy| ok9| gwq| g9q| kqe| 9io| 9qm| iq7| eco| c8q| mcq| u8i| owc| 8mq| wm8| csi| w8s| csg| 8ws| 7sy| ye7| gma| q7k| omi| 7cq| yg7| qmc| w7u| qqw| 8mu| oo6| ss6| csc| o6s| uye| 6ay| ca6| wmu| w77| goc| q7g| wmk|