拥有多年互联网和银行系统性能测试开发经验,对性能瓶颈诊断定位和优化领域有较多研究。 重回互联网行业,性能测试开发、自动化测试开发、Java开发

发布新日志

  • java performance读书笔记之垃圾回收监控分析

    2013-01-05 16:11:37

    当需要jvm调优时就预示着需要分析jvm监控的信息。当jvm版本变化、操作系统变化、应用升级等任何一个变化时,都需要进行jvm调优。
    jvm监控包括了垃圾回收、JIT编译行为、类加载等区块。
    性能监控可能是当发现了一个系统的性能瓶颈但又没有充足的信息和证据来指明瓶颈的根源所在时第一步要做的事情。

    相反得,性能profiling是一项从运行时系统中侵入式得收集性能数据的行为,profiling倾向于对交互性的行为进行分析,它通常基于性能监控数据的基础之上,并且比性能监控的范围更小一些,它很少用在生产环境当中,而更多得会在测试、开发环境中进行。

    性能调优,和监控和profiling又不同,它是一项通过改变一些可调优项来达到调优目的的动作,比如修改源代码、修改配置属性。调优通常又跟在监控和profiling之后。

    接下来开始介绍一些监控jvm垃圾回收的相关知识,监控需要使用的jvm参数,使用参数时输出结果的含义等。

    首先,对于jvm垃圾回收,主要应该关注的点有:
    1.当前使用的垃圾回收器
    2.java堆的大小
    3.年轻代和年老代的大小
    4.永久带的大小
    5.minor gc的持续时间
    6.minor gc的频率
    7.minor gc时回收的内存大小
    8.fgc持续时间
    9.fgc的频率
    10.fgc回收的内存大小
    11.回收前后java堆的使用率
    12.年轻代和年老代回收前后分别的使用率
    13.永久带在回收前后的使用率
    14.年老代的使用率过高还是永久带的使用率过高触发了垃圾回收
    15.系统是否自己出发了System.gc的调用
    默认情况下,fgc会回收年轻代、年老代、永久代的数据,但是如果想让jvm在fgc时不回收年轻代,可以使用-XX:-ScavengeBeforeFullGC这个jvm参数。
    在jvm中,gc分为minor gc和full gc。minor gc回收年轻代的垃圾对象,而major gc则会回收年轻代、年老代、永久代的gc,并且对年老代和永久代进行整理操作,所以,fgc之后堆内存的结果应该要是年轻代被清空,年老代和永久代被清理并整理。
    使用-XX:-ScavengeBeforeFullGC可以让垃圾回收器在进行fgc时不回收年轻代的内容,默认的参数是开启的,即会进行年轻代的gc。在进行fgc之前先进行年轻代的回收可以减少垃圾回收器的工作量并且尽可能多得回收垃圾对象,因为年老代的对象有可能持有年轻代中对象中的引用,如果年轻代的内存不先被回收,年老代中持有年轻代引用的对象将不能被回收。所以建议不要使用-XX:-ScavengeBeforeFullGC参数。

    以下是gc日志的查看部分,主要介绍-verbose:gc -Xloggc:/home/admin/logs/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps等参数的作用和使用。

    使用-verbose:gc指示jvm在发生gc时输出gc的相关信息,-verbose:gc可能是用来观察gc数据的最常用jvm参数了,但是-XX:+PrintGCDetails打印出了更多有价值的垃圾回收的信息,这两个参数通常会同时使用来查监控gc的情况。在不同的jdk版本中,这个参数输出的垃圾回收信息可能是不一样的.

    例如在jdk6的update25版本中,使用-XX:+UseParallelGC or -XX:+UseParallelOldGC这两个参数指定的gc方式,当ygc发生时,输出来的ygc信息为(这里的输出在真实的gc.log中会被输出正一行,这里为了易于解读,分成了多行):
    [GC
    [PSYoungGen: 99952K->14688K(109312K)]
    422212K->341136K(764672K), 0.0631991 secs]
    [Times: user=0.83 sys=0.00, real=0.06 secs]
    第一行的GC表明这是一次minor gc。
    第二行打印出了年轻代的一些数据统计,PSYoungGen表明minor gc的方式是多线程的并行gc方式.其他可选的ygc方式有:ParNew,它表示ygc的方式是并行gc,而此时jvm系统fgc的方式是cms gc;以及DefNew,它表示ygc的方式是串行gc,也就是使用了–XX:+UseSerialGC参数.G1 gc方式不使用这种标记来标识gc的方式。->左边的值是ygc之前年轻代使用的堆大小(包括eden和两个s区),->右边的值是ygc之后年轻代的大小,因为ygc之后eden区为空,也就是说,这个值就是s区的大小了,括号中的109312则是年轻代的总大小,即eden区加上两个s区的总大小。
    第三行显示了垃圾回收前后java堆的大小,->左边是垃圾回收前java堆使用的总大小,右边则是垃圾回收后java堆使用的总大小,括号中是java堆的总大小(包括年轻代和年老代)。
    有了这些数据,结合前一次垃圾回收的统计,你就可以计算出本次垃圾回收前后java堆中每个区块的大小了。例如本次垃圾回收后,old区的内存使用数为341136-14688k。最后的0.0631991则表示本次垃圾回收的时间消耗。
    第四行的数据提供了cpu使用和时间消耗的统计,user=0.83标识使用的用户态cpu在这次gc中的消耗,sys=0则标识操作系统态在这次gc中的消耗,最后一个real=0.06则是指本次gc消耗的时间。
    使用-XX:PrintGCDetails这个参数时在fgc发生时的输出为:
    [Full GC
    [PSYoungGen: 11456K->0K(110400K)]
    [PSOldGen: 651536K->58466K(655360K)]
    662992K->58466K(765760K)
    [PSPermGen: 10191K->10191K(22528K)],
    1.1178951 secs]
    [Times: user=1.01 sys=0.00, real=1.12 secs]
    第一行的Full GC标识了这是一次fgc。
    第二行的输出则和上面ygc时输出的是同样的意思。
    第三行打印出来fgc前后old区的内存使用情况,PSOldGen告诉我们年老代的gc方式是多线程并行gc,即XX:+UseParallelOldGC这个参数的结果。->左边的数值是年老代gc前的old使用数,右边则是年老代gc后old区的使用数。
    第四行跟ygc时输出的第三行类似,标识fgc前后java堆(包括年轻代和年老代)的大小。
    第五行则给出来永久代在垃圾回收前后的大小和总大小。
    第六行给出来本次fgc耗费的时间。
    这里要观察的一项重要的内容是垃圾回收前后年老代和永久代的大小,因为年老代和永久代内存不足都可能会触发fg,我们可以通过观察这两个数据的情况来判别一些情况。比如在这个例子中,fgc前年老代的使用大小已经很接近年老代的总大小,而永久代的使用数则还远没有达到永久代的总大小。根据这个数据统计可以推测这次fgc的触发是由于old区的内存不足造成的。
    第七行的时间则标识了这次fgc占用的时间。
    第八行则类似ygc时打出来的最后一行,给出来本次gc的cpu消耗情况和总消耗时间。
    当使用了参数-XX:+UseConcMarkSweepGC参数后,jvm会自动开启-XX:+UseParNewGC这个参数指定ygc的方式,使用-XX:PrintGCDetails参数在ygc时打出来的统计为:
    [GC
    [ParNew: 2112K->64K(2112K), 0.0837052 secs]
    16103K->15476K(773376K), 0.0838519 secs]
    [Times: user=0.02 sys=0.00, real=0.08 secs]
    上面的数据和+XX:UseParallelOldGC方式的并行gc在ygc时打出来的数据类似。
    cms的gc方式下,fgc时,使用-XX:PrintGCDetails参数打出来的数据为:
    [GC
    [1 CMS-initial-mark: 13991K(773376K)]
    14103K(773376K), 0.0023781 secs]
    [Times: user=0.00 sys=0.00, real=0.00 secs]
    [CMS-concurrent-mark-start]
    [GC
    [ParNew: 2077K->63K(2112K), 0.0126205 secs]
    17552K->15855K(773376K), 0.0127482 secs]
    [Times: user=0.01 sys=0.00, real=0.01 secs]
    [CMS-concurrent-mark: 0.267/0.374 secs]
    [Times: user=4.72 sys=0.01, real=0.37 secs]
    [GC
    [ParNew: 2111K->64K(2112K), 0.0190851 secs]
    17903K->16154K(773376K), 0.0191903 secs]
    [Times: user=0.01 sys=0.00, real=0.02 secs]
    [CMS-concurrent-preclean-start]
    [CMS-concurrent-preclean: 0.044/0.064 secs]
    [Times: user=0.11 sys=0.00, real=0.06 secs]
    [CMS-concurrent-abortable-preclean-start]
    [CMS-concurrent-abortable-clean] 0.031/0.044 secs]
    [Times: user=0.09 sys=0.00, real=0.04 secs]
    [GC
    [YG occupancy: 1515 K (2112K)
    [Rescan (parallel) , 0.0108373 secs]
    [weak refs processing, 0.0000186 secs]
    [1 CMS-remark: 16090K(20288K)]
    17242K(773376K), 0.0210460 secs]
    [Times: user=0.01 sys=0.00, real=0.02 secs]
    [GC
    [ParNew: 2112K->63K(2112K), 0.0716116 secs]
    18177K->17382K(773376K), 0.0718204 secs]
    [Times: user=0.02 sys=0.00, real=0.07 secs]
    [CMS-concurrent-sweep-start]
    [GC
    [ParNew: 2111K->63K(2112K), 0.0830392 secs]
    19363K->18757K(773376K), 0.0832943 secs]
    [Times: user=0.02 sys=0.00, real=0.08 secs]
    [GC
    [ParNew: 2111K->0K(2112K), 0.0035190 secs]
    17527K->15479K(773376K), 0.0036052 secs]
    [Times: user=0.00 sys=0.00, real=0.00 secs]
    [CMS-concurrent-sweep: 0.291/0.662 secs]
    [Times: user=0.28 sys=0.01, real=0.66 secs]
    [GC
    [ParNew: 2048K->0K(2112K), 0.0013347 secs]
    17527K->15479K(773376K), 0.0014231 secs]
    [Times: user=0.00 sys=0.00, real=0.00 secs]
    [CMS-concurrent-reset-start]
    [CMS-concurrent-reset: 0.016/0.016 secs]
    [Times: user=0.01 sys=0.00, real=0.02 secs]
    [GC
    [ParNew: 2048K->1K(2112K), 0.0013936 secs]
    17527K->15479K(773376K), 0.0014814 secs]
    [Times: user=0.00 sys=0.00, real=0.00 secs]
    一个需要特别关注的结果是年老代内存在CMS周期中的变化情况。cms需要关注cms周期中年老代的占用率变化。特别是从CMS-concurrent-sweep-start 到CMS-concurrent-sweep这两阶段。
    排查cmsgc的另外一个方式是采用-XX:+PrintTenuringDistribution参数,tenuringdistribution是一个查看年轻代中s区年龄的命令行参数。
    当对象的年龄到达虚拟机设定的对象的阈值,jvm就会把这个对象晋升到年老代,年轻代向年老代晋升过快并且垃圾回收器没法给这些对象清理出足够的空间的情况,叫做concurrent mode failure。这种情况也发生在年老代中由于碎片太多导致无法为晋升的对象分配足够的内存。
    引用原文:-XX:+PrintGCDetails reports a concurrent mode failure in the garbage collection output with the text (concurrent mode failure). When a concurrent mode failure occurs, the old generation space is garbage collected to free available space,and it is compacted to eliminate fragmentation. This operation requires all Java application threads be stopped, and it can take a noticeably lengthy duration of time to execute. Therefore, if you observe concurrent mode failures, you should tune the JVM.
    当并发模式失败时,年老代会进行fgc来回收对象并清理内存碎片,这会导致所有线程暂停,java应用暂停相当可观的一段时间。因此,当这个情况发生时,jvm调优就必须要做了。
    -XX:+PrintGCTimeStamps参数可以在打印GC信息时打印出时间戳,77.233: [GC
    [PSYoungGen: 99952K->14688K(109312K)]
    422212K->341136K(764672K), 0.0631991 secs]
    [Times: user=0.83 sys=0.00, real=0.06 secs]
    在GC信息之前会输出从虚拟机启动到垃圾回收时刻的秒数。在fgc和cms gc时都会输出时间戳信息。在gc日志中使用时间戳可以查看到minor gc和full gc的频繁程度。
    -XX:+PrintGCDateStamps可以输出的GC时的绝对时刻。
    -XX:+PrintGCApplicationConcurrentTime and -XX:+PrintGCApplicationStoppedTime这两个参数可以用来输出进行CMS GC时应用并发运行的时间和应用全部暂停的时间。
    使用这两个参数结合-XX:+PrintGCDetail输出的信息为:
    Application time: 0.5291524 seconds
    [GC
    [ParNew: 3968K->64K(4032K), 0.0460948 secs]
    7451K->6186K(32704K), 0.0462350 secs]
    [Times: user=0.01 sys=0.00, real=0.05 secs]
    Total time for which application threads were stopped: 0.0468229 seconds
    Application time: 0.5279058 seconds
    [GC
    [ParNew: 4032K->64K(4032K), 0.0447854 secs]
    10154K->8648K(32704K), 0.0449156 secs]
    [Times: user=0.01 sys=0.00, real=0.04 secs]
    Total time for which application threads were stopped: 0.0453124 seconds
    Application time: 0.9063706 seconds
    [GC
    [ParNew: 4032K->64K(4032K), 0.0464574 secs]
    12616K->11187K(32704K), 0.0465921 secs]
    [Times: user=0.01 sys=0.00, real=0.05 secs]
    Total time for which application threads were stopped: 0.0470484 seconds
    从上图可以看到minor时应用线程并发运行的时间在0.5-0.9s之间,应用暂停的时间在0.04-0.05之间。
    如何查看应用中显式得调用了System.gc():
    应用代码中显示得调用了System.gc导致的full gc可以很容易从gc日志中查看得到:
    [Full GC (System)
    [PSYoungGen: 99608K->0K(114688K)]
    [PSOldGen: 317110K->191711K(655360K)]
    416718K->191711K(770048K)
    [PSPermGen: 15639K->15639K(22528K)],
    0.0279619 secs]
    [Times: user=0.02 sys=0.00, real=0.02 secs]
    如上的gc输出中,Full GC (System)表明了这是由系统显示得调用导致的full gc,这时候就要查看系统是由于什么原因调用了显示的full gc,然后排查为什么会调用。。
Open Toolbar