JVM调优日志解析分析与性能监控工具

Posted 2020-12-29 gxyandwmm

tags:

篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了JVM调优日志解析分析与性能监控工具相关的知识，希望对你有一定的参考价值。

一、调优参数设置

JVM的GC日志的主要参数包括如下几个：

-XX:+PrintGC 输出GC日志

-XX:+PrintGCDetails 输出GC的详细日志

-XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式）

-XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式，如 2013-05-04T21:53:59.234+0800）

-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息

-XX:+PrintGCApplicationStoppedTime // 输出GC造成应用暂停的时间

-Xloggc:../logs/gc.log 日志文件的输出路径

分析gc日志后，经常需要调整jvm内存相关参数，常用参数如下：

-Xms：初始堆大小，默认为物理内存的1/64(<1GB)；默认(MinHeapFreeRatio参数可以调整)空余堆内存小于40%时，JVM就会增大堆直到-Xmx的最大限制
-Xmx：最大堆大小，默认(MaxHeapFreeRatio参数可以调整)空余堆内存大于70%时，JVM会减少堆直到 -Xms的最小限制
-Xmn：新生代的内存空间大小，注意：此处的大小是（eden+ 2 survivor space)。与jmap -heap中显示的New gen是不同的。整个堆大小=新生代大小 + 老生代大小 + 永久代大小。
在保证堆大小不变的情况下，增大新生代后,将会减小老生代大小。此值对系统性能影响较大,Sun官方推荐配置为整个堆的3/8。
-XX:SurvivorRatio：新生代中Eden区域与Survivor区域的容量比值，默认值为8。两个Survivor区与一个Eden区的比值为2:8,一个Survivor区占整个年轻代的1/10。
-Xss：每个线程的堆栈大小。JDK5.0以后每个线程堆栈大小为1M,以前每个线程堆栈大小为256K。应根据应用的线程所需内存大小进行适当调整。在相同物理内存下,减小这个值能生成更多的线程。但是操作系统对一个进程内的线程数还是有限制的，不能无限生成，经验值在3000~5000左右。一般小的应用，如果栈不是很深，应该是128k够用的，大的应用建议使用256k。这个选项对性能影响比较大，需要严格的测试。和threadstacksize选项解释很类似,官方文档似乎没有解释,在论坛中有这样一句话:"-Xss is translated in a VM flag named ThreadStackSize”一般设置这个值就可以了。
-XX:PermSize：设置永久代(perm gen)初始值。默认值为物理内存的1/64。
-XX:MaxPermSize：设置持久代最大值。物理内存的1/4。

在我做了如下的设置

-XX:+PrintGCDetails -Xloggc:../logs/gc.log -XX:+PrintGCTimeStamps

以后打印出来的日志为：

 

 
0.756: [Full GC (System) 0.756: [CMS: 0K->1696K(204800K), 0.0347096 secs] 11488K->1696K(252608K), [CMS Perm : 10328K->10320K(131072K)], 0.0347949 secs] [Times: user=0.06 sys=0.00, real=0.05 secs]
 
1.728: [GC 1.728: [ParNew: 38272K->2323K(47808K), 0.0092276 secs] 39968K->4019K(252608K), 0.0093169 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
 
2.642: [GC 2.643: [ParNew: 40595K->3685K(47808K), 0.0075343 secs] 42291K->5381K(252608K), 0.0075972 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
 
4.349: [GC 4.349: [ParNew: 41957K->5024K(47808K), 0.0106558 secs] 43653K->6720K(252608K), 0.0107390 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
 
5.617: [GC 5.617: [ParNew: 43296K->7006K(47808K), 0.0136826 secs] 44992K->8702K(252608K), 0.0137904 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
 
7.429: [GC 7.429: [ParNew: 45278K->6723K(47808K), 0.0251993 secs] 46974K->10551K(252608K), 0.0252421 secs]

我们取倒数第二条记录分析一下各个字段都代表了什么含义

5.617（时间戳）: [GC（Young GC） 5.617（时间戳）: [ParNew（GC的区域）: 43296K（垃圾回收前的大小）->7006K（垃圾回收以后的大小）(47808K)（该区域总大小）, 0.0136826 secs（回收时间）] 44992K（堆区垃圾回收前的大小）->8702K（堆区垃圾回收后的大小）(252608K)（堆区总大小）, 0.0137904 secs（回收时间）] [Times: user=0.03（GC用户耗时） sys=0.00（GC系统耗时）, real=0.02 secs（GC实际耗时）]

我们再对数据做一个简单的分析

从最后一条GC记录中我们可以看到 Young GC回收了 45278-6723=38555K的内存

Heap区通过这次回收总共减少了 46974-10551=36423K的内存。

38555-36423=2132K说明通过该次Young GC有2132K的内存被移动到了Old Gen，

我们来验证一下

在最后一次Young GC的回收以前 Old Gen的大小为8702-7006=1696

回收以后Old Gen的内存使用为10551-6723=3828

Old Gen在该次Young GC以后内存增加了3828-1696=2132K 与预计的相符

4.231: [GC 4.231: [DefNew: 4928K->512K(4928K), 0.0044047 secs] 6835K->3468K(15872K), 0.0045291 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
 
4.445: [Full GC (System) 4.445: [Tenured: 2956K->3043K(10944K), 0.1869806 secs] 4034K->3043K(15872K), [Perm : 3400K->3400K(12288K)], 0.1870847 secs] [Times: user=0.05 sys=0.00, real=0.19 secs]

最前面的数字 4.231 和 4.445 代表虚拟机启动以来的秒数。

[GC 和 [Full GC 是垃圾回收的停顿类型，而不是区分是新生代还是年老代，如果有 Full 说明发生了Stop-The-World 。如果是调用 System.gc() 触发的，那么将显示的是 [Full GC (System) 。

接下来的 [DefNew, [Tenured, [Perm 表示 GC 发生的区域，区域的名称与使用的 GC 收集器相关。
Serial 收集器中新生代名为 “Default New Generation”，显示的名字为 “[DefNew”。对于ParNew收集器，显示的是 “[ParNew”，表示 “Parallel New Generation”。对于 Parallel Scavenge 收集器，新生代名为 “PSYoungGen”。年老代和永久代也相同，名称都由收集器决定。

方括号内部显示的 “4928K->512K(4928K)” 表示 “GC 前该区域已使用容量 -> GC 后该区域已使用容量 (该区域内存总容量) ”。

再往后的 “0.0044047 secs” 表示该区域GC所用时间，单位是秒。

再往后的 “6835K->3468K(15872K)” 表示 “GC 前Java堆已使用容量 -> GC后Java堆已使用容量（Java堆总容量）”。

再往后的 “0.0045291 secs” 是Java堆GC所用的总时间。

最后的 “[Times: user=0.00 sys=0.00, real=0.00 secs]” 分别代表用户态消耗的CPU时间、内核态消耗的CPU时间和操作从开始到结束所经过的墙钟时间。墙钟时间包括各种非运算的等待耗时，如IO等待、线程阻塞。CPU时间不包括等待时间，当系统有多核时，多线程操作会叠加这些CPU时间，所以user或sys时间会超过real时间。

堆的分代机制

young区域就是新生代，存放新创建对象；
tenured是年老代，存放在新生代经历多次垃圾回收后仍存活的对象；
perm是永生代，存放类定义信息、元数据等信息。

当GC发生在新生代时，称为Minor GC，次收集；当GC发生在年老代时，称为Major GC，主收集。一般的，Minor GC的发生频率要比Major GC高很多。

重新设置GC日志的输出

 
-XX:+PrintGCDetails
 
-XX:+PrintHeapAtGC
 
-XX:+PrintGCDateStamps
 
-XX:+PrintTenuringDistribution
 
-verbose:gc
 
-Xloggc:gc.log

后可以看到进行GC前后的堆内存信息

{
Heap before GC invocations=1 (full 0):
 
PSYoungGen total 152896K, used 131072K [0x00000000f5560000, 0x0000000100000000, 0x0000000100000000)
 
eden space 131072K, 100% used [0x00000000f5560000,0x00000000fd560000,0x00000000fd560000)
 
from space 21824K, 0% used [0x00000000feab0000,0x00000000feab0000,0x0000000100000000)
 
to space 21824K, 0% used [0x00000000fd560000,0x00000000fd560000,0x00000000feab0000)
 
PSOldGen total 349568K, used 0K [0x00000000e0000000, 0x00000000f5560000, 0x00000000f5560000)
 
object space 349568K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000f5560000)
 
PSPermGen total 26432K, used 26393K [0x00000000d0000000, 0x00000000d19d0000, 0x00000000e0000000)
 
object space 26432K, 99% used [0x00000000d0000000,0x00000000d19c64a0,0x00000000d19d0000)
 
2013-05-05T23:16:10.480+0800: 5.228: [GC Desired survivor size 22347776 bytes, new threshold 7 (max 15)
 
[PSYoungGen: 131072K->8319K(152896K)] 131072K->8319K(502464K), 0.0176346 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
 
Heap after GC invocations=1 (full 0):
 
PSYoungGen total 152896K, used 8319K [0x00000000f5560000, 0x0000000100000000, 0x0000000100000000)
 
eden space 131072K, 0% used [0x00000000f5560000,0x00000000f5560000,0x00000000fd560000)
 
from space 21824K, 38% used [0x00000000fd560000,0x00000000fdd7ff78,0x00000000feab0000)
 
to space 21824K, 0% used [0x00000000feab0000,0x00000000feab0000,0x0000000100000000)
 
PSOldGen total 349568K, used 0K [0x00000000e0000000, 0x00000000f5560000, 0x00000000f5560000)
 
object space 349568K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000f5560000)
 
PSPermGen total 26432K, used 26393K [0x00000000d0000000, 0x00000000d19d0000, 0x00000000e0000000)
 
object space 26432K, 99% used [0x00000000d0000000,0x00000000d19c64a0,0x00000000d19d0000)
 
}

可以看出前后回收掉了 131072K - 21824K*0.38 = 122778K 内存

示例代码

/**
 * VM agrs: -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails
 * -XX:SurvivorRatio=8 -XX:+UseSerialGC
 */

public class MinorGCTest {
    private static final int _1MB = 1024 * 1024;

    public static void testAllocation() {
        byte[] allocation1, allocation2, allocation3, allocation4;
        allocation1 = new byte[2 * _1MB];
        allocation2 = new byte[2 * _1MB];
        allocation3 = new byte[2 * _1MB];
        allocation4 = new byte[4 * _1MB];
    }

    public static void main(String[] agrs) {
        testAllocation();
    }
}

VM参数说明

Option	Description
-verbose:gc	显示GC的操作内容
-Xms20M -Xmx20M	设置堆大小为20M
-Xmn10M	设置新生代的内存空间大小为10M
-XX:+PrintGCDetails	打印GC中的变化
-XX:SurvivorRatio=8	新生代中Eden区域与Survivor区域的大小比值
-XX:+UseSerialGC	在新生代和老年代中使用串行收集器，由于-verbose:gc参数对Parallel Scavenge收集器不起作用，无法显示显示GC的操作内容，因此采用串行收集器

示例代码说明
该段代码一共创建了4个数组对象，在给allocation4分配空间前的内存空间使用情况如下： eden区为8M 两个Survivor为各占1M，年老代占10M。

需要执行一次MinorGC才能给allocation4分配空间（Eden区满时），分配成功以后内存空间使用情况如下：

2. GC日志

[GC [DefNew ... ...]
GC日志开头的信息通过设置-verbose:gc参数后才能输出。
"[GC"和"[Full GC"说明这次垃圾收集的停顿类型，如果这次GC发生了Stop-The-World，则为"[Full GC"，否则为"[GC"
"[DefNew "表示GC发生的区域为Serial收集器的新生代中，DefNew是"Default New Generation"的缩写。Serial收集器的老年代和永久代分别表示为"Tenured"、"Perm"
** eden space 8192K, 52% used**
新生代的Eden区总共大小为8MB，使用掉的4MB是用来存放allocation4对象
tenured generation total 10240K, used 6144K
老年代大小为10MB，使用掉的6MB是用来存放allocation1、allocation2和allocation3这3个对象

　　中间的Survivor区域占用了19%的内存此处笔者不是很明白，如果有知道的网友可以给我留言，帮助讲解一下，谢谢！

三、内存分配的原则

对象优先分配在Eden区上

虚拟机参数为“-verbose:gc -XX:+PrintGCDetails -Xms20M -Xmx20M -Xmn10M -XX:SurvivorRatio=8”，即10M新生代，10M老年代，10M新生代中8M的Eden区，两个Survivor区各1M。代码都是同一段

public class EdenAllocationTest
{
    private static final int _1MB = 1024 * 1024;
    
    public static void main(String[] args)
    {
        byte[] allocation1 = new byte[2 * _1MB];
        byte[] allocation2 = new byte[2 * _1MB];
        byte[] allocation3 = new byte[2 * _1MB];
        byte[] allocation4 = new byte[4 * _1MB];
    }
}

Client模式下

[GC [DefNew: 6487K->194K(9216K), 0.0042856 secs] 6487K->6338K(19456K), 0.0043281 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 def new generation   total 9216K, used 4454K [0x0000000005180000, 0x0000000005b80000, 0x0000000005b80000)
  eden space 8192K,  52% used [0x0000000005180000, 0x00000000055a9018, 0x0000000005980000)
  from space 1024K,  18% used [0x0000000005a80000, 0x0000000005ab0810, 0x0000000005b80000)
  to   space 1024K,   0% used [0x0000000005980000, 0x0000000005980000, 0x0000000005a80000)
 tenured generation   total 10240K, used 6144K [0x0000000005b80000, 0x0000000006580000, 0x0000000006580000)
   the space 10240K,  60% used [0x0000000005b80000, 0x0000000006180048, 0x0000000006180200, 0x0000000006580000)
 compacting perm gen  total 21248K, used 2982K [0x0000000006580000, 0x0000000007a40000, 0x000000000b980000)
   the space 21248K,  14% used [0x0000000006580000, 0x0000000006869890, 0x0000000006869a00, 0x0000000007a40000)
No shared spaces configured.

Server模式下

Heap
 PSYoungGen      total 9216K, used 6651K [0x000000000af20000, 0x000000000b920000, 0x000000000b920000)
  eden space 8192K, 81% used [0x000000000af20000,0x000000000b59ef70,0x000000000b720000)
  from space 1024K, 0% used [0x000000000b820000,0x000000000b820000,0x000000000b920000)
  to   space 1024K, 0% used [0x000000000b720000,0x000000000b720000,0x000000000b820000)
 PSOldGen        total 10240K, used 4096K [0x000000000a520000, 0x000000000af20000, 0x000000000af20000)
  object space 10240K, 40% used [0x000000000a520000,0x000000000a920018,0x000000000af20000)
 PSPermGen       total 21248K, used 2972K [0x0000000005120000, 0x00000000065e0000, 0x000000000a520000)
  object space 21248K, 13% used [0x0000000005120000,0x0000000005407388,0x00000000065e0000)

看到在Client模式下，最后分配的4M在新生代中，先分配的6M在老年代中；

在Server模式下，最后分配的4M在老年代中，先分配的6M在新生代中。说明不同的垃圾收集器组合对于对象的分配是有影响的。

讲下两者差别的原因：

1、Client模式下，新生代分配了6M，虚拟机在GC前有6487K，比6M也就是6144K多，多主要是因为TLAB和EdenAllocationTest这个对象占的空间，TLAB可以通过“-XX:+PrintTLAB”这个虚拟机参数来查看大小。

OK，6M多了，然后来了一个4M的，Eden+一个Survivor总共就9M不够分配了【感觉这个地方说的有点不对，因为触发一次Minor GC的情况是是Eden内存满，这里不应该把Survivor算进去】，这时候就会触发一次Minor GC。但是触发Minor GC也没用，因为allocation1、allocation2、allocation3三个引用还存在，另一块1M的Survivor也不够放下这6M，那么这次Minor GC的效果其实是通过分配担保机制将这6M的内容转入老年代中。然后再来一个4M的，此时Minor GC之后新生代只剩下了194K了，够分配了，所以4M顺利进入新生代。

2、Server模式下，前面都一样，但是在GC的时候有一点区别。在GC前还会进行一次判断，如果要分配的内存>=Eden区大小的一半，那么会直接把要分配的内存放入老年代中。要分配4M，Eden区8M，刚好一半，而且老年代10M，够分配，所以4M就直接进入老年代去了。为了验证一下结论，我们把3个2M之后分配的4M改为3M看一下。

public class EdenAllocationTest
{
    private static final int _1MB = 1024 * 1024;
    
    public static void main(String[] args)
    {
        byte[] allocation1 = new byte[2 * _1MB];
        byte[] allocation2 = new byte[2 * _1MB];
        byte[] allocation3 = new byte[2 * _1MB];
        byte[] allocation4 = new byte[3 * _1MB];
    }
}

运行结果为

[GC [PSYoungGen: 6487K->352K(9216K)] 6487K->6496K(19456K), 0.0035661 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC [PSYoungGen: 352K->0K(9216K)] [PSOldGen: 6144K->6338K(10240K)] 6496K->6338K(19456K) [PSPermGen: 2941K->2941K(21248K)], 0.0035258 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
Heap
 PSYoungGen      total 9216K, used 3236K [0x000000000af40000, 0x000000000b940000, 0x000000000b940000)
  eden space 8192K, 39% used [0x000000000af40000,0x000000000b269018,0x000000000b740000)
  from space 1024K, 0% used [0x000000000b740000,0x000000000b740000,0x000000000b840000)
  to   space 1024K, 0% used [0x000000000b840000,0x000000000b840000,0x000000000b940000)
 PSOldGen        total 10240K, used 6338K [0x000000000a540000, 0x000000000af40000, 0x000000000af40000)
  object space 10240K, 61% used [0x000000000a540000,0x000000000ab70858,0x000000000af40000)
 PSPermGen       total 21248K, used 2982K [0x0000000005140000, 0x0000000006600000, 0x000000000a540000)
  object space 21248K, 14% used [0x0000000005140000,0x0000000005429890,0x0000000006600000)

看到3M在新生代中，6M通过分配担保机制进入老年代了。

大对象直接进入老年代

虚拟机参数为“-XX:+PrintGCDetails -Xms20M -Xmx20M -Xmn10M -XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=3145728”，最后那个参数表示大于这个设置值的对象直接在老年代中分配，这样做的目的是为了避免在Eden区和两个Survivor区之间发生大量的内存复制。测试代码为

public class OldTest
{
    private static final int _1MB = 1024 * 1024;
    
    public static void main(String[] args)
    {
         byte[] allocation = new byte[4 * _1MB];
    }
}

Client模式下

Heap
 def new generation   total 9216K, used 507K [0x0000000005140000, 0x0000000005b40000, 0x0000000005b40000)
  eden space 8192K,   6% used [0x0000000005140000, 0x00000000051bef28, 0x0000000005940000)
  from space 1024K,   0% used [0x0000000005940000, 0x0000000005940000, 0x0000000005a40000)
  to   space 1024K,   0% used [0x0000000005a40000, 0x0000000005a40000, 0x0000000005b40000)
 tenured generation   total 10240K, used 4096K [0x0000000005b40000, 0x0000000006540000, 0x0000000006540000)
   the space 10240K,  40% used [0x0000000005b40000, 0x0000000005f40018, 0x0000000005f40200, 0x0000000006540000)
 compacting perm gen  total 21248K, used 2972K [0x0000000006540000, 0x0000000007a00000, 0x000000000b940000)
   the space 21248K,  13% used [0x0000000006540000, 0x00000000068272a0, 0x0000000006827400, 0x0000000007a00000)
No shared spaces configured.

Server模式下

Heap
 PSYoungGen      total 9216K, used 4603K [0x000000000afc0000, 0x000000000b9c0000, 0x000000000b9c0000)
  eden space 8192K, 56% used [0x000000000afc0000,0x000000000b43ef40,0x000000000b7c0000)
  from space 1024K, 0% used [0x000000000b8c0000,0x000000000b8c0000,0x000000000b9c0000)
  to   space 1024K, 0% used [0x000000000b7c0000,0x000000000b7c0000,0x000000000b8c0000)
 PSOldGen        total 10240K, used 0K [0x000000000a5c0000, 0x000000000afc0000, 0x000000000afc0000)
  object space 10240K, 0% used [0x000000000a5c0000,0x000000000a5c0000,0x000000000afc0000)
 PSPermGen       total 21248K, used 2972K [0x00000000051c0000, 0x0000000006680000, 0x000000000a5c0000)
  object space 21248K, 13% used [0x00000000051c0000,0x00000000054a72a0,0x0000000006680000)

看到Client模式下4M直接进入了老年代，Server模式下4M还在新生代中。产生这个差别的原因是“-XX:PretenureSizeThreshold”这个参数对Serial+Serial Old垃圾收集器组合有效而对Parallel+Serial Old垃圾收集器组合无效。

其他几条原则

上面列举的原则其实不重要，只是演示罢了，也不需要记住，因为实际过程中我们可能使用的并不是上面的垃圾收集器的组合，可能使用ParNew垃圾收集器，可能使用G1垃圾收集器。场景很多，重要的是要在实际使用的时候有办法知道使用的垃圾收集器对于对象分配有哪些原则，因为理解这些原则才是调优的第一步。下面列举一下对象分配的另外两条原则：

1、长期存活的对象将进入老年代。Eden区中的对象在一次Minor GC后没有被回收，则对象年龄+1，当对象年龄达到“-XX:MaxTenuringThreshold”设置的值的时候，对象就会被晋升到老年代中

2、Survivor空间中相同年龄的所有对象大小总和大于Survivor空间的一半，年龄大于或等于该年龄的对象就可以直接进入老年代，无须等到“-XX:MaxTenuringThreshold”设置要求的年龄

以上是关于JVM调优日志解析分析与性能监控工具的主要内容，如果未能解决你的问题，请参考以下文章

JVM性能调优监控工具专题一：JVM自带性能调优工具

jvm性能监控与GC调优

JVM性能调优监控工具jpsjstackjmapjhatjstathprof使用详解 - 实例分析

转 Java GC - 监控回收行为与日志分析

JVM性能分析工具jstack介绍

JVM调优-工具篇