java performance读书笔记——（四）jvm performance monitoring

最新推荐文章于 2024-07-04 22:12:02 发布

原创最新推荐文章于 2024-07-04 22:12:02 发布 · 541 阅读

0 ·

CC 4.0 BY-SA版权

本文深入探讨了Java垃圾回收的关键指标，包括不同类型的垃圾回收器及其工作原理，如何通过命令行参数获取详细的垃圾回收报告，以及如何解读这些报告来优化应用程序性能。

Garbage Collection Data of Interest

The data of interest in garbage collection statistics are
1.The garbage collector in use
2.The size of the Java heap
3.The size of the young generation and old generation spaces
4.The size of the permanent generation space
5.The duration of minor garbage collections
6.The frequency of minor garbage collections
7.The amount of space reclaimed in minor garbage collections
8.The duration of full garbage collections
9.The frequency of full garbage collections
10.The amount of space reclaimed in a concurrent garbage collection cycle
11.The occupancy of the Java heap before and after garbage collections
12.The occupancy of the young generation and old generation spaces before and
after garbage collections
13.The occupancy of the permanent generation space before and after garbage
collections
14.Whether it is the occupancy of the old generation space or the occupancy of the
permanent generation space that triggers a full garbage collection

15.Whether the application is making use of explicit calls to System.gc()

Garbage Collection Reporting

minor gc收集young generation，full gc收集清理并压缩old generation和permanent generation。也有一些例外，Hotspot 中full gc 的默认行为是清理young，old，permanent 三代，并且将从young generation提到old generation的存活对象与原old generation，permanent generation一起做压缩整理。因此在full gc之后，young generation为空，old generation和permanent generation是紧密排放的。

-XX:-ScavengeBeforeFullGC 可以用来取消full gc中对young generation的清理，Hotspot默认行为是开启这项功能，一般也不建议将其关闭，因为先回收young generation可能会收集更多的对象，提高工作效率。因为old generation中的对象可能有young generation中对象的引用，如果这些引用没被回收，old generation中的那些对象也不能被回收。

-XX:+PrintGCDetails

虽然-verbose：gc 是最常用的gc采集报告的命令行参数， -XX:+PrintGCDetails 能打印更多有价值的gc 信息。

一个java 6update25中开启 -XX:+PrintGCDetails选项并且用了 -XX:+UseParallelGC or -XX:+UseParallelOldGC 参数的输出如下：

[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说明young generation GCor 是用了多线程吞吐collector，使用了-XX:+UseParallelGC or -XX:+UseParallelOldGC。其他可能的GCor有 ParNew，指的是多线程young generation GCor 使用了concurrent old generation GCor 如CMS。或者是DefNew，表明是单线程串行 GCor，用命令参数 –XX:+UseSerialGC 。-XX:+UseSerialGC同样可以和CMS一起使用，这样用单线程串行回收young gen 其他代使用CMS。

->符号左边的99952K是gc之前young gen占用的空间，右边的14688K是gc后占用的空间，而young gen为eden 和两个survivor空间，gc后eden为空那么14688K全是survivor中占用的空间。圆括号中的109312K则是整个young gen的空间，包括eden和两个survivor。

下一行422212K->341136K(764672K)显示的是java 堆的使用情况（young和old gen的总占用空间），从gc前到gc后，括号中是java堆总空间。

从young gen和堆总大小可以算出old gen的大小即 764672K - 109312K = 655360K. 0.0631991 secs说明gc经历的时间。

[Times: user=0.06 sys=0.00, real=0.06 secs]提供了cpu使用率和经历的时间信息，user数值显示的是gc执行的操作系统以外指令的cpu时间，sys指的是gc中操作系统用的cpu时间，在这个例子中gc仅执行了user级别的指令，没有操作系统指令。real指的是gc的实际经过时间。 user, sys, 和real四舍五入精确到0.01秒。

下面是一个full gc 输出的例子

[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 标记说明这是一次full gc。[PSYoungGen: 11456K->0K(110400K)]是minor gc前面说过了，[PSOldGen: 651536K->58466K(655360K)]说明了old gen GCor 设置了XX:+UseParallelOldGC 命令选项，使用了多线程GCor。 ->号左边是gc前右边是gc后括号是old gen 总量。

662992K->58466K(765760K)是young gen和old gen总量。[PSPermGen: 10191K->10191K(22528K)]显示的是permanent gen的信息，PSPermGen说明permanent GCor使用的是通过 -XX:+UseParallelGC 或 -XX:+UseParallelOldGC 设置的多线程GCor，->左右的数分别是gc前后的占用空间，括号里是permanent gen总大小。

一个值得关注的地方是，full gc 前的old 和permanent占用的空间。这是因为old或permanent 其中之一达到了限额容量都会触发full gc。在输出中可以看出old gen占用651536K非常接近总容量655360K，而相反的permanent的10191K占用离总量22528K还很远。因此，这次full gc是由于old gen快被填满引起的。

1.1178951 secs 显示gc的运行时间，[Times: user=1.01 sys=0.00, real=1.12 secs]与之前相同。

当用到CMS时输出就不一样了，特别是关于old gen的mostly concurrent gc的数据。CMS可以用 -XX:+UseConcMarkSweepGC 命令行选项. 同时也自动打开了-XX:+UseParNewGC选项，使用并发多线程的young gen GCor，禁用串行收集模式。一个例子如下：

[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]

如上所述这是minor gc 各项数据与前所表示相同ParNew 说明young gen GCor用的是多线程GCor 与CMS，若是串行与CMS则是DefNew。

第三章介绍CMS时提到过它在回收old gen时是mostly concurrent gc，以下例子展示了整个concurrent gc 周期，minor gc 散布在整个周期中说明了minor gc可以发生在一个concurrent gc周期中。以下输出调整过格式以方便阅读，对concurrent gc 的数据加粗。

[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周期从initial mark pause开始，到一个concurrent reset 阶段的完成而结束。每个CMS周期从 CMS-initial-mark输出处开始到 CMS-
concurrent-reset结束。CMS-concurrent-mark标志指明concurrent marking阶段的结束，CMS-concurrent-sweep 标识concurrent sweeping阶段结束，CMS-concurrent-preclean and CMS-concurrent-abortable-preclean 表示可以并行处理的任务，也是为remark阶段做准备。标识着CMS-concurrent-sweep的sweeping阶段，作用是释放被标记为不可达对象占用的空间。最后阶段 CMS-concurrent-reset是为下一个concurrent gc周期做准备。

initial mark通常有个与minor gc 时间相关的短暂停顿，之后的并发执行阶段要相比minor gc停顿要更长，但不会暂停java应用程序线程。remark阶段的停顿会受到应用程序的特点（比如对象修改比例较大会增加暂停时间）和距离上一次minor gc的时间影响（young gen 有大量的对象可能增加停顿时间）。

-XX:+PrintTenuringDistribution 查看survivor spaces 对象的年龄分布。

-XX:+PrintGCTimeStamps 记录中加入时间戳

-Xloggc:<filename> 记录导入文件

-XX:+PrintGCApplicationConcurrentTime
-XX:+PrintGCApplicationStoppedTime 打印safepoint 操作间的运行时间和VM阻止java线程的时间。观察safepoint操作停止时间能帮助分析影响延迟的原因

显式调用system.gc()的日志打印如下，（System）表示system.gc()调用的是full gc

[Full GC (System)

离线图形分析工具：GCHisto

garbage collection overhead，一般来说overhead 不大于10%，在1%-3%之间，高于3%需要调节。java heap与overhead是有关联的，一般heap越大overhead越小