阅读 481

心心念念的JVM调优:jmap、jstack、jstat在真实业务场景下的使用

本篇大纲

journey
title JVM调优策略
section JVM基本工具介绍
jmap: 5
jstack: 5
jstat: 5
section JVM的优化思路
JVM的优化思路: 5
section JVM调优案例
调优案例: 5
  • 第一阶段:JVM基本工具介绍的详细介绍
  • 第二阶段:JVM的优化思路
  • 第三阶段:JVM的真实调优案例

第一阶段:JVM基本工具介绍

jmap--->Java内存映像工具

jmapMemory Map for Java用于生成堆转储快照一般称为heapdump或dump文件。同时它还可以查询finalize执行队列、Java堆和方法区的 详细信息,如空间使用率、当前用的是哪种收集器等。

说简单点就是它能用来查看堆内存信息

jmap命令格式

jmap option vmid

option选项

image.png

jmap使用demo例子

例子:大家在随便创建一个spring-boot项目然后加上web模块启动就可以了,这里不展开详细的步骤

第一步:启动创建的spring-boot项目

image.png

第二步:在终端输入jps命令

jpsJava Virtual Machine Process Status Tool是Java提供的一个显示当前所有Java进程pid的命令

找到对应的Java进程号:49150

image.png

第三步:在终端根据jmap命令格式输入命令查看

第一个命令:jmap -histo 进程号

输入jmap -histo 49150来看下结果:

image.png

发现在终端显示不下,打印的东西太多,所以我们把打印的内容输出到文件中

输入jmap -histo 49150 > ./jmapLog.txt来看下结果:

image.png

我们发现在对应的文件路径下就生成了这么一个jmapLog.txt文件,打开来看下:

image.png

可以看到三块内容最左边的编号可以不管,从右往左看分别是

  1. class name:类名
  2. bytes:字节数
  3. instances:实例数

说白了就是打印每个类的实例数有多少,总共占用了多少字节或者说是内存大小

第二个命令:jmap -heap 进程号

根据上方的表格可知:这个命令是用来显示Java堆的详细信息,如使用哪种垃圾收集器、参数配置、分代状况等等,我们来打印一下看一下

输入jmap -heap 49150来看下结果:

image.png

大家如果和我有一样问题的,可以看下这篇文章,应该就能解决你的问题,没有当然最好:

使用 jmap 打印 Java 堆信息时报错:Can't attach symbolicator to the process

经过上面文章中的调整,最终输入jhsdb jmap --heap --pid 49150命令后打印:

$ jhsdb jmap --heap --pid 49150
Attaching to process ID 49150, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 11.0.11+9-LTS-194

using thread-local object allocation.
Garbage-First (G1) GC with 4 thread(s)

Heap Configuration:
   MinHeapFreeRatio         = 40
   MaxHeapFreeRatio         = 70
   MaxHeapSize              = 2147483648 (2048.0MB)
   NewSize                  = 1363144 (1.2999954223632812MB)
   MaxNewSize               = 1287651328 (1228.0MB)
   OldSize                  = 5452592 (5.1999969482421875MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 1048576 (1.0MB)

Heap Usage:
G1 Heap:
   regions  = 2048
   capacity = 2147483648 (2048.0MB)
   used     = 14274048 (13.61279296875MB)
   free     = 2133209600 (2034.38720703125MB)
   0.6646871566772461% used
G1 Young Generation:
Eden Space:
   regions  = 2
   capacity = 69206016 (66.0MB)
   used     = 2097152 (2.0MB)
   free     = 67108864 (64.0MB)
   3.0303030303030303% used
Survivor Space:
   regions  = 7
   capacity = 7340032 (7.0MB)
   used     = 7340032 (7.0MB)
   free     = 0 (0.0MB)
   100.0% used
G1 Old Generation:
   regions  = 5
   capacity = 57671680 (55.0MB)
   used     = 4836864 (4.61279296875MB)
   free     = 52834816 (50.38720703125MB)
   8.386896306818182% used
复制代码
第一块内容:堆的配置信息

image.png

  • MinHeapFreeRatio: 空闲堆空间的最小百分比,计算公式为:HeapFreeRatio =(CurrentFreeHeapSize/CurrentTotalHeapSize) * 100,值的区间为0到100,默认值为 40。如果HeapFreeRatio < MinHeapFreeRatio,则需要进行堆扩容,扩容的时机应该在每次垃圾回收之后。

  • MaxHeapFreeRatio: 空闲堆空间的最大百分比,计算公式为:HeapFreeRatio =(CurrentFreeHeapSize/CurrentTotalHeapSize) * 100,值的区间为0到100,默认值为 70。如果HeapFreeRatio > MaxHeapFreeRatio,则需要进行堆缩容,缩容的时机应该在每次垃圾回收之后。

  • MaxHeapSize: 最大堆内存

  • NewSize: 新生代占用的空间

  • MaxNewSize: 最大新生代可用空间

  • OldSize: 老年代占用空间

  • NewRatio: 新生代占的比例,2表示1:2,占三分之一

  • SurvivorRatio: 两个Survivor区和eden区的比例,8表示2个Survivor:Eden = 2:8,意味着一个Survivor区占年轻代的1/10

  • MetaspaceSize:元空间大小

  • CompressedClassSpaceSize:指针压缩空间大小

  • MaxMetaspaceSize: 最大元空间大小

  • G1HeapRegionSize: G1垃圾收集器中的一个Region大小

第二块内容:正在使用的堆信息

image.png

因为我用的是jdk 11,默认使用是G1的垃圾收集器,所以打印的堆内存结构和jdk 8不同,大家根据自己真实的场景去分析,没必要和我保持一致

  • G1 Heap:总的堆空间,regions就是region的个数,默认2048个capacity是总的堆的大小used是已经使用的堆空间free是没有使用的堆空间,最后是使用比例

  • G1 Young Generation:Young空间部分/年轻代大小,其中又分为Eden区和Survivor区,这里就不再详细介绍每块区域大小,大家直接看图就好

  • G1 Old Generation:Old空间部分/老年代大小

第三个命令:jmap -dump 进程号

image.png

举个例子: 执行一下jmap -dump:format=b,file=jmapDump 49150

image.png

发现就会在对应的目录下生成名称为jmapDump的堆快照信息文件

设置自动下载

我们还可以设置自动下载,当内存溢出的时候自动dump文件

小贴士:内存很大的时候,可能会导不出来

  1. -XX:+HeapDumpOnOutOfMemoryError设置自动导出
  2. -XX:HeapDumpPath=./xxx/xxx/xxx路径
查看jmapDump例子

在test目录下新建测试类就是在死循环中创建对象,并且让这个对象一直被GC Roots引用,不会被回收

image.png

加上 -XX:+HeapDumpOnOutOfMemoryError、-XX:HeapDumpPath 这两个命令后运行,当内存溢出的时候自动dump


// 测试代码

public class DumpTest {

    public static void main(String[] args) {
        List<Object> list = new ArrayList<>();
        int i = 0;
        int j = 0;
        while (true) {
            list.add(new Teacher("teacher" + i++, i++));
            new Teacher("teacher" + j--, j--);
        }
    }

}
class Teacher {
    private String name;
    private Integer age;
    public Teacher(String name, Integer age) {
        this.name = name;
        this.age = age;
    }
}
复制代码

我们在idea的配置中加上JVM参数,没有的同学按照下方红框框中选择JVM参数那一栏

image.png

-Xms10M -Xmx10M -XX:+PrintGCDetails -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/dumpTest.log

-Xms10M -Xmx10M是为了尽早发生OOM,配置好参数之后执行一下,发现产生了OOM

image.png

然后去搜这个dumpTest.log文件,发现也已经自动生成了,那么问题来了,我们怎么分析这份文件呢?

image.png

jvisualvm

jdk自带的这个工具通过导入就可以查看这个文件

小贴士:亲测,jdk11不支持这个工具,由于我电脑的jdk是双版本,所以这里演示的时候是切换到jdk8 然后打开的jvisualvm

我们在终端输入jvisualvm,打开工具后,通过文件导入打开下载下来的dumpTest.log文件

image.png

就可以看到显示的有基本信息、环境、系统属性和堆快照上的线程信息

image.png

我们切换到类的窗口上

image.png

可以知道哪几个类的实例最多,占用的空间大小、比例是多少,我们可以通过这样的方式,很清楚的知道堆中类的实例分布,如果发现某一个类的实例特别多,我们就可以去定位创建这个类实例的地方,进行排查,我们可以通过这个方法找出JVM内存飙升的原因

剩下的jmap命令,剩下的还有三个jmap命令,由于平常不常用,这里就不再演示了

image.png

jstack--->Java堆栈跟踪工具

jstackStack Trace for Java命令用于生成JVM当前时刻的线程快照

线程快照

线程快照就是当前JVM内每一条线程正在执行的方法堆栈的集合,生成线程快照的 目的通常是定位线程出现长时间停顿的原因,如线程间死锁、死循环、请求外部资源导致的长时间挂起等,都是导致线程长时间停顿的常见原因

线程出现停顿时通过jstack来查看各个线程的调用堆栈, 就可以获知没有响应的线程到底在后台做些什么事情,或者等待着什么资源。

jstack命令格式

jstack option vmid

image.png

jstack例子

既然是用来定位线程出现长时间停顿的原因,如线程间死锁,那么我们就模拟一个线程的死锁,下面是一个简单的死锁类:

/**
 * 当DeadLock类的对象flag==1时(td1),先锁定o1,睡眠500毫秒
 * 而td1在睡眠的时候另一个flag==0的对象(td2)线程启动,先锁定o2,睡眠500毫秒
 * td1睡眠结束后需要锁定o2才能继续执行,而此时o2已被td2锁定;
 * td2睡眠结束后需要锁定o1才能继续执行,而此时o1已被td1锁定;
 * td1、td2相互等待,都需要得到对方锁定的资源才能继续执行,从而死锁。
 */
public class DeadLockTest implements Runnable{

    public int flag = 1;
    
    //静态对象是类的所有对象共享的
    private static Object o1 = new Object(), o2 = new Object();
    @Override
    public void run() {
        System.out.println("flag=" + flag);
        if (flag == 1) {
            synchronized (o1) {
                try {
                    Thread.sleep(500);
                } catch (Exception e) {
                    e.printStackTrace();
                }
                synchronized (o2) {
                    System.out.println("1");
                }
            }
        }
        if (flag == 0) {
            synchronized (o2) {
                try {
                    Thread.sleep(500);
                } catch (Exception e) {
                    e.printStackTrace();
                }
                synchronized (o1) {
                    System.out.println("0");
                }
            }
        }
    }

    public static void main(String[] args) {
        DeadLockTest td1 = new DeadLockTest();
        DeadLockTest td2 = new DeadLockTest();
        td1.flag = 1;
        td2.flag = 0;
        //td1,td2都处于可执行状态,但JVM线程调度先执行哪个线程是不确定的。
        //td2的run()可能在td1的run()之前运行
        new Thread(td1).start();
        new Thread(td2).start();
    }
}
复制代码

我们运行一下,发现程序一直卡在这里进行不下去

image.png

我们程序不终止,用jstack命令来看下怎么排查,首先通过jps命令找到java进程

image.png

然后用jstack 进程号来看下

2021-04-27 23:42:14
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.171-b11 mixed mode):

"Attach Listener" #15 daemon prio=9 os_prio=31 tid=0x00007fc476153800 nid=0x320b waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"DestroyJavaVM" #14 prio=5 os_prio=31 tid=0x00007fc4761b1800 nid=0x1003 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Thread-1" #13 prio=5 os_prio=31 tid=0x00007fc475108800 nid=0x3e03 waiting for monitor entry [0x0000700002560000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at com.project.mall.test.DeadLockTest.run(DeadLockTest.java:39)
	- waiting to lock <0x0000000795946928> (a java.lang.Object)
	- locked <0x0000000795946938> (a java.lang.Object)
	at java.lang.Thread.run(Thread.java:748)

"Thread-0" #12 prio=5 os_prio=31 tid=0x00007fc4768b8800 nid=0x3c03 waiting for monitor entry [0x000070000245d000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at com.project.mall.test.DeadLockTest.run(DeadLockTest.java:27)
	- waiting to lock <0x0000000795946938> (a java.lang.Object)
	- locked <0x0000000795946928> (a java.lang.Object)
	at java.lang.Thread.run(Thread.java:748)

"Service Thread" #11 daemon prio=9 os_prio=31 tid=0x00007fc476152800 nid=0x4203 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread2" #10 daemon prio=9 os_prio=31 tid=0x00007fc476152000 nid=0x4403 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #9 daemon prio=9 os_prio=31 tid=0x00007fc476151000 nid=0x3903 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #8 daemon prio=9 os_prio=31 tid=0x00007fc47687c800 nid=0x4503 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"JDWP Command Reader" #7 daemon prio=10 os_prio=31 tid=0x00007fc475032000 nid=0x4603 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"JDWP Event Helper Thread" #6 daemon prio=10 os_prio=31 tid=0x00007fc475031000 nid=0x4703 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"JDWP Transport Listener: dt_socket" #5 daemon prio=10 os_prio=31 tid=0x00007fc47582e800 nid=0x4807 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=31 tid=0x00007fc47582a000 nid=0x4903 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=31 tid=0x00007fc475022000 nid=0x5103 in Object.wait() [0x0000700001939000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x0000000795588ed0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
	- locked <0x0000000795588ed0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:212)

"Reference Handler" #2 daemon prio=10 os_prio=31 tid=0x00007fc476033800 nid=0x5203 in Object.wait() [0x0000700001836000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x0000000795586bf8> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:502)
	at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
	- locked <0x0000000795586bf8> (a java.lang.ref.Reference$Lock)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"VM Thread" os_prio=31 tid=0x00007fc476014800 nid=0x2b03 runnable

"GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007fc47501b800 nid=0x1f07 runnable

"GC task thread#1 (ParallelGC)" os_prio=31 tid=0x00007fc47501c000 nid=0x2103 runnable

"GC task thread#2 (ParallelGC)" os_prio=31 tid=0x00007fc47501c800 nid=0x2303 runnable

"GC task thread#3 (ParallelGC)" os_prio=31 tid=0x00007fc47501d800 nid=0x2a03 runnable

"VM Periodic Task Thread" os_prio=31 tid=0x00007fc475962000 nid=0x3b03 waiting on condition

JNI global references: 1579


Found one Java-level deadlock:
=============================
"Thread-1":
  waiting to lock monitor 0x00007fc4758254a8 (object 0x0000000795946928, a java.lang.Object),
  which is held by "Thread-0"
"Thread-0":
  waiting to lock monitor 0x00007fc475821408 (object 0x0000000795946938, a java.lang.Object),
  which is held by "Thread-1"

Java stack information for the threads listed above:
===================================================
"Thread-1":
	at com.project.mall.test.DeadLockTest.run(DeadLockTest.java:39)
	- waiting to lock <0x0000000795946928> (a java.lang.Object)
	- locked <0x0000000795946938> (a java.lang.Object)
	at java.lang.Thread.run(Thread.java:748)
"Thread-0":
	at com.project.mall.test.DeadLockTest.run(DeadLockTest.java:27)
	- waiting to lock <0x0000000795946938> (a java.lang.Object)
	- locked <0x0000000795946928> (a java.lang.Object)
	at java.lang.Thread.run(Thread.java:748)

Found 1 deadlock.
复制代码

打印的都是进程中的线程信息,例如下面的这两个线程:

image.png

  • Thread-1:线程名
  • prio:优先级
  • os_prio:操作系统级别的线程优先级
  • tid:线程id
  • nid:线程对应本地线程id
  • java.lang.Thread.State:线程状态

继续往下看,到打印信息的尾端,我们发现jstack帮我们已经发现了一个死锁,说发现了一个Java层面的一个死锁

image.png

不仅如此,jstack还帮我们打印了死锁产生的原因,比如下方,由于Thread-1等待获取0x00007fc4758254a8这把锁,但是这把锁,现在被Thread-0持有,Thread-0等待获取0x00007fc475821408这把锁,但是这把锁,现在被Thread-1持有

image.png

打印了死锁产生的原因之外,还帮我们定位到了java的代码行数:

image.png

jvisualvm检测死锁

我们通过jvisualvm也可以快速的检测死锁,如下图所示

image.png

旁边的线程Dump就是执行我们上面说的jstack 进程id

关于jvisualvm你一定要知道的事

虽然jvisualvm能监控远程,但是一般是不用的,因为如果要监控服务器,那么服务器启动的时候要启动JMX的端口配置

image.png

但是一般生产环境中是不可能把这么重要的端口开放出去的,所以一般不使用jvisualvm监控线上的JVM,所以具体的配置方式就不再展开,但是开发环境、测试环境可以根据需要使用比如压测的时候

jstack找出占用CPU最高的线程

准备:我直接拿开发环境的来模拟演示了,大家看下演示过程

使用top命令找出cpu最高的进程

输入top查看cpu占用率最高的进程

image.png

根据图中显示,占用cpu最高的java进程是18955

使用top -p 进程号命令

使用top -p 进程号命令查看进程的内存使用情况,我们输入top -p 18955来看下

image.png

按H进入进程的详情

按H查看进程内每个线程的内存使用情况

image.png

最左边的PID就是我们的线程ID

根据jstack命令找到线程ID对应的代码

  1. 首先把线程ID转化成16进制的因为jstack信息里打印的线程ID都是16进制的,所以要把24091转换成16进制就是5e1b

  2. 执行jstack 18955|grep -A 10 5e1b,匹配这个线程所在行的后面10行代码,从堆栈中可以找到导致cpu飙升的调用方法

  3. 分析堆栈中打印的代码,如下图所示这个只是例子,别在意里面的内容

"http-nio-8080-ClientPoller" #43 daemon prio=5 os_prio=31 cpu=24.76ms elapsed=327.74s tid=0x00007fd3f33d0800 nid=0x5e1b runnable  [0x000070000d58d000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.KQueue.poll(java.base@11.0.11/Native Method)
	at sun.nio.ch.KQueueSelectorImpl.doSelect(java.base@11.0.11/KQueueSelectorImpl.java:122)
	at sun.nio.ch.SelectorImpl.lockAndDoSelect(java.base@11.0.11/SelectorImpl.java:124)
	- locked <0x00000007843563e8> (a sun.nio.ch.Util$2)
	- locked <0x0000000784356290> (a sun.nio.ch.KQueueSelectorImpl)
	at sun.nio.ch.SelectorImpl.select(java.base@11.0.11/SelectorImpl.java:136)
	at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:816)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:834)
复制代码

jinfo--->Java配置信息工具

jinfoConfiguration Info for Java的作用是实时查看和调整JVM配置的各项参数

查看JVM参数

jinfo -flags 进程号

image.png

小贴士: jdk8的版本这个命令有问题和上面jmap命令失效的情况的一样,需要切换其他的jdk版本

查看系统参数

jinfo还可以使用-sysprops选项把虚拟机进程的System.getProperties()的内容打印出来,如下图所示,大家只要知道有这个命令就好,用的很少

VM Flags:
-XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:CICompilerCount=3 -XX:ConcGCThreads=1 -XX:G1ConcRefinementThreads=4 -XX:G1HeapRegionSize=1048576 -XX:GCDrainStackTargetSize=64 -XX:InitialHeapSize=134217728 -XX:+ManagementServer -XX:MarkStackSize=4194304 -XX:MaxHeapSize=2147483648 -XX:MaxNewSize=1287651328 -XX:MinHeapDeltaBytes=1048576 -XX:NonNMethodCodeHeapSize=6973028 -XX:NonProfiledCodeHeapSize=244685212 -XX:ProfiledCodeHeapSize=0 -XX:ReservedCodeCacheSize=251658240 -XX:+SegmentedCodeCache -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseFastUnorderedTimeStamps -XX:+UseG1GC
zhouxinzedeMacBook-Pro:~ zhouxinze$ jinfo -sysprops 84587
Java System Properties:
#Thu Apr 29 21:55:19 CST 2021
gopherProxySet=false
awt.toolkit=sun.lwawt.macosx.LWCToolkit
java.specification.version=11
sun.cpu.isalist=
sun.jnu.encoding=UTF-8
java.class.path=/Users/zhouxinze/IdeaProjects/mall/target/classes\:/Users/zhouxinze/.m2/repository/org/springframework/boot/spring-boot-starter-web/2.4.5/spring-boot-starter-web-2.4.5.jar\:/Users/zhouxinze/.m2/repository/org/springframework/boot/spring-boot-starter/2.4.5/spring-boot-starter-2.4.5.jar\:/Users/zhouxinze/.m2/repository/org/springframework/boot/spring-boot/2.4.5/spring-boot-2.4.5.jar\:/Users/zhouxinze/.m2/repository/org/springframework/boot/spring-boot-autoconfigure/2.4.5/spring-boot-autoconfigure-2.4.5.jar\:/Users/zhouxinze/.m2/repository/org/springframework/boot/spring-boot-starter-logging/2.4.5/spring-boot-starter-logging-2.4.5.jar\:/Users/zhouxinze/.m2/repository/ch/qos/logback/logback-classic/1.2.3/logback-classic-1.2.3.jar\:/Users/zhouxinze/.m2/repository/ch/qos/logback/logback-core/1.2.3/logback-core-1.2.3.jar\:/Users/zhouxinze/.m2/repository/org/apache/logging/log4j/log4j-to-slf4j/2.13.3/log4j-to-slf4j-2.13.3.jar\:/Users/zhouxinze/.m2/repository/org/apache/logging/log4j/log4j-api/2.13.3/log4j-api-2.13.3.jar\:/Users/zhouxinze/.m2/repository/org/slf4j/jul-to-slf4j/1.7.30/jul-to-slf4j-1.7.30.jar\:/Users/zhouxinze/.m2/repository/jakarta/annotation/jakarta.annotation-api/1.3.5/jakarta.annotation-api-1.3.5.jar\:/Users/zhouxinze/.m2/repository/org/yaml/snakeyaml/1.27/snakeyaml-1.27.jar\:/Users/zhouxinze/.m2/repository/org/springframework/boot/spring-boot-starter-json/2.4.5/spring-boot-starter-json-2.4.5.jar\:/Users/zhouxinze/.m2/repository/com/fasterxml/jackson/core/jackson-databind/2.11.4/jackson-databind-2.11.4.jar\:/Users/zhouxinze/.m2/repository/com/fasterxml/jackson/core/jackson-annotations/2.11.4/jackson-annotations-2.11.4.jar\:/Users/zhouxinze/.m2/repository/com/fasterxml/jackson/core/jackson-core/2.11.4/jackson-core-2.11.4.jar\:/Users/zhouxinze/.m2/repository/com/fasterxml/jackson/datatype/jackson-datatype-jdk8/2.11.4/jackson-datatype-jdk8-2.11.4.jar\:/Users/zhouxinze/.m2/repository/com/fasterxml/jackson/datatype/jackson-datatype-jsr310/2.11.4/jackson-datatype-jsr310-2.11.4.jar\:/Users/zhouxinze/.m2/repository/com/fasterxml/jackson/module/jackson-module-parameter-names/2.11.4/jackson-module-parameter-names-2.11.4.jar\:/Users/zhouxinze/.m2/repository/org/springframework/boot/spring-boot-starter-tomcat/2.4.5/spring-boot-starter-tomcat-2.4.5.jar\:/Users/zhouxinze/.m2/repository/org/apache/tomcat/embed/tomcat-embed-core/9.0.45/tomcat-embed-core-9.0.45.jar\:/Users/zhouxinze/.m2/repository/org/glassfish/jakarta.el/3.0.3/jakarta.el-3.0.3.jar\:/Users/zhouxinze/.m2/repository/org/apache/tomcat/embed/tomcat-embed-websocket/9.0.45/tomcat-embed-websocket-9.0.45.jar\:/Users/zhouxinze/.m2/repository/org/springframework/spring-web/5.3.6/spring-web-5.3.6.jar\:/Users/zhouxinze/.m2/repository/org/springframework/spring-beans/5.3.6/spring-beans-5.3.6.jar\:/Users/zhouxinze/.m2/repository/org/springframework/spring-webmvc/5.3.6/spring-webmvc-5.3.6.jar\:/Users/zhouxinze/.m2/repository/org/springframework/spring-aop/5.3.6/spring-aop-5.3.6.jar\:/Users/zhouxinze/.m2/repository/org/springframework/spring-context/5.3.6/spring-context-5.3.6.jar\:/Users/zhouxinze/.m2/repository/org/springframework/spring-expression/5.3.6/spring-expression-5.3.6.jar\:/Users/zhouxinze/.m2/repository/org/slf4j/slf4j-api/1.7.30/slf4j-api-1.7.30.jar\:/Users/zhouxinze/.m2/repository/org/springframework/spring-core/5.3.6/spring-core-5.3.6.jar\:/Users/zhouxinze/.m2/repository/org/springframework/spring-jcl/5.3.6/spring-jcl-5.3.6.jar
java.vm.vendor=Oracle Corporation
sun.arch.data.model=64
catalina.useNaming=false
java.vendor.url=https\://openjdk.java.net/
user.timezone=Asia/Shanghai
java.vm.specification.version=11
os.name=Mac OS X
sun.java.launcher=SUN_STANDARD
user.country=CN
sun.boot.library.path=/Library/Java/JavaVirtualMachines/jdk-11.0.11.jdk/Contents/Home/lib
spring.application.admin.enabled=true
sun.java.command=com.mall.MallApplication
com.sun.management.jmxremote=
jdk.debug=release
sun.cpu.endian=little
spring.liveBeansView.mbeanDomain=
user.home=/Users/zhouxinze
user.language=zh
java.specification.vendor=Oracle Corporation
java.version.date=2021-04-20
java.home=/Library/Java/JavaVirtualMachines/jdk-11.0.11.jdk/Contents/Home
file.separator=/
spring.output.ansi.enabled=always
java.vm.compressedOopsMode=Zero based
line.separator=\n
java.specification.name=Java Platform API Specification
java.vm.specification.vendor=Oracle Corporation
FILE_LOG_CHARSET=UTF-8
java.awt.graphicsenv=sun.awt.CGraphicsEnvironment
java.awt.headless=true
user.script=Hans
sun.management.compiler=HotSpot 64-Bit Tiered Compilers
java.runtime.version=11.0.11+9-LTS-194
spring.jmx.enabled=true
path.separator=\:
os.version=10.15.6
java.runtime.name=Java(TM) SE Runtime Environment
file.encoding=UTF-8
spring.beaninfo.ignore=true
java.vm.name=Java HotSpot(TM) 64-Bit Server VM
java.vendor.version=18.9
java.vendor.url.bug=https\://bugreport.java.com/bugreport/
java.io.tmpdir=/var/folders/qz/gl34hk1x5yv5wb0l6tsyq_x80000gp/T/
catalina.home=/private/var/folders/qz/gl34hk1x5yv5wb0l6tsyq_x80000gp/T/tomcat.8080.5214054096261208489
java.version=11.0.11
os.arch=x86_64
java.vm.specification.name=Java Virtual Machine Specification
PID=84587
java.awt.printerjob=sun.lwawt.macosx.CPrinterJob
sun.os.patch.level=unknown
CONSOLE_LOG_CHARSET=UTF-8
catalina.base=/private/var/folders/qz/gl34hk1x5yv5wb0l6tsyq_x80000gp/T/tomcat.8080.5214054096261208489
java.vendor=Oracle Corporation
java.vm.info=mixed mode
java.vm.version=11.0.11+9-LTS-194
java.rmi.server.randomIDs=true
sun.io.unicode.encoding=UnicodeBig
java.class.version=55.0
复制代码

重点:jstat--->JVM统计信息监视工具

jstatJVM Statistics Monitoring Tool是用于监视JVM各种运行状态信息的命令行工具这个命令很重要很重要

它可以显示本地或者远程JVM进程中的类加载、内存、垃圾收集、即时编译等运行时数据,在没有GUI图形界面、只提供了纯文本控制台环境的服务器上,它将是运行期定位虚拟机性能问题的常用工具。

jstat命令格式

jstat [-命令选项] [vmid] [间隔时间][查询次数]

image.png

命令选项清单

image.png

第一个功能: 垃圾回收统计

jstat -gc 进程号

image.png

  • S0C:当前survivor0区的大小
  • S1C:当前survivor1区的大小
  • S0U:survivor0区的已经使用大小
  • S1U:survivor1区的已经使用大小
  • EC:Eden区的大小
  • EU:Eden区的使用大小
  • OC:老年代的大小
  • MC:元空间的大小
  • MU:元空间的使用大小
  • CCSC:指针压缩空间的大小
  • CCSU:指针压缩空间的使用大小
  • YGC:程序运行以来共发生Minor GC的次数
  • YGCT:Minor GC消耗的时间根据案例可知:4次MinorGC总共花费0.021秒
  • FGC:程序运行以来共发生Full GC的次数
  • FGCT:总共Full GC消耗的时间
  • CGC:G1并发收集Mixed GC次数
  • CGCT:G1并发收集Mixed GC消耗的时间
  • GCT:总共垃圾回收消耗的时候

第二个功能: 堆内存统计

jstat -gccapacity 进程号

image.png

  • NGCMN:年轻代最小容量
  • NGCMX:年轻代最大容量
  • NGC:当前年轻代容量
  • S0C、S1C、EC和上面GC信息中一样
  • OGCMN:老年代最小容量
  • OGCMX:老年代最大容量
  • OGC:当前老年代大小
  • OC:和上面GC信息中一样
  • MCMN:元空间最小容量
  • MCMX:元空间最大容量
  • MC:当前元空间容量
  • CCSMN:最小压缩指针空间大小
  • CCSMX:最大压缩指针空间大小
  • CCSC:当前压缩指针空间大小
  • YGC、FGC、CGC和上面GC信息中一样

依次类推,如果想要查看专门的监视内容就下面这张图,注意点:不同垃圾收集器,打印出来的内容可能会不一样,这里就不一一带着大家去看了

image.png

JVM运行情况预估

我们还记得上面说的这个间隔时间吗,我们可以用这个间隔时间来预估JVM的运行情况

image.png

举个例子:想要每个1s执行一次jstat gc统计,总共统计10次,我们就可以这样执行jstat -gc 85164 1000 10,我们就能得到下方图中的统计信息本地随便启动了个Tomcat一直放在那里,所以没有发生变化,你们在写测试类的时候可以通过不断的new对象,来达到数据的变化监控

image.png

我们可以从这张图中看出哪些东西?

  1. 预测年轻代对象的增长速率
  2. Minor GC的触发频率和平均耗时平均耗时=YGCT/YGC,总的MinorGC耗时时间除MinorGC次数计算而出,得出系统间隔多久Minor GC频率会停顿多久Minor GC耗时
  3. 每次Minor GC之后有多少对象进入老年代,每次Minor GC之后观察EU、S0U、S1U和OU的变化情况,从而推断出每次Minor GC有多少对象进入老年代,再结合Minor GC频率判断老年代对象增长速率
  4. Full GC的触发频率和平均耗时FGCT/FGC

第二阶段: 常见的JVM优化思路

结合对象挪动到老年代的规则主要可以由以下优化思路:

  1. 简单来说就是尽量让每次Minor GC后的存活对象小于Survivor区的50%避免因为动态年龄判断机制而过早进入老年代,尽量都存活在年轻代中,尽量减少Full GC的频率,Full GC对JVM性能的影响很严重这种情况出现在高并发的系统,正常情况下每秒创建的对象都是很少的,但是某一时间段,并发量突然上升,导致新对象创建的过快,很容易因为动态年龄判断机制过早的进入老年代,所以这种情况下,要调整年轻代的大小,让这些对象都尽可能的留在年轻代,因为这些都是朝生夕死的对象

  2. 大对象需要大量连续内存空间的对象 比如字符串、数组要尽早进入老年代,因为年轻代用的是标记-复制算法,大对象在复制的时候会消耗大量的性能,所以要尽早的进入老年代使用-XX:PretenureSizeThreshold设置大小,超过这个大小的对象直接进入老年代,不会进入年轻代,这个参数只在Serial和ParNew两个GC收集器下有用

结合频繁发生Full GC的次数,主要由以下优化思路

  1. 除了正常的因为老年代空间不足而发生Full GC,还有老年代空间担保机制的存在,年轻代在每次Minor GC之前,JVM都会计算下老年代剩余可用空间,如果这个可用空间小于年轻代里现有的所有对象大小之和,就会看一个 -XX:-HandlePromotionFailure JDK 1.8默认设置参数是否设置,这个参数就是一个担保参数,担保一下如果老年代剩余空间小于历史每一次Minor GC后进入老年代的对象的平均值,就会先发生一次Full GC,再执行Minor GC,Minor GC后,老年代不够又会发生Full GC,这样一次完整的Minor GC就是两次Full GC,一次Minor GC

  2. 元空间不够会导致多余的Full GC,导致Full GC次数频繁

  3. 显示调用System.gc造成多余的Full GC,这种一般线上尽量通过 -XX:+DisableExplicitGC参数禁用,加上这个参数,System.gc就没有任何效果

第三阶段: JVM的调优案例

JVM的调优案例:线上发生频繁的Full GC

假设有这么一串JVM参数模拟真实场景下的JVM环境

-Xms1536M -Xmx1536M -Xmn512M -Xss256K -XX:SurvivorRatio=6 -XX:MetaspaceSize=256M -XX:MaxMetaspaceSize=256M -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly
复制代码

不清楚这些命令的同学请看下面的指令介绍,知道的可以跳过下面的这一截内容:

  1. -Xms1536M:设置JVM初始内存为1536M。此值可以设置与-Xmx相同,以避免每次垃圾回收完成后JVM重新分配内存。
  2. -Xmx1536M:设置JVM最大可用内存为1536M
  3. -Xmn512M:设置年轻代大小为512M
  4. -Xss256K:设置每个线程的线程栈大小为256K
  5. -XX:SurvivorRatio=6:设置年轻代中Eden区与Survivor区的大小比值。设置为6,则两个Survivor区与一个Eden区的比值为2:6,一个Survivor区占整个年轻代的1/8
  6. -XX:MetaspaceSize=256M:设置元空间大小为256M
  7. -XX:MaxMetaspaceSize=256M:设置最大元空间大小为256M
  8. -XX:+UseParNewGC:设置年轻代垃圾回收器是ParNew
  9. -XX:+UseConcMarkSweepGC:设置老年代垃圾回收器是CMS
  10. -XX:CMSInitiatingOccupancyFraction=75:设置CMS在对老年代内存使用率达到75%的时候开始GC因为CMS会有浮动垃圾,所以一般都较早启动GC
  11. -XX:+UseCMSInitiatingOccupancyOnly:只用设置的回收阈值上面指定的75%,如果不指定,JVM仅在第一次使用设定值,后续则自动调整,一般和上一个命令组合使用

猜想一:由于动态年龄判断机制导致频繁的发生Full GC

那么由于动态年龄判断机制的原因导致的频繁发生Full GC,应该怎么调优呢,我们先从以下几个方面来看?

  1. 动态年龄判断机制的关键点在于年轻代的空间大小,所以首先就是要把年轻代的空间调大

  2. 如果是并发量大的系统,我们可以调小CMSInitiatingOccupancyFraction设定的值,避免产生Serial Old收集器的情况,但是如果是并发量小的系统,我们可以调大CMSInitiatingOccupancyFraction设定的值,充分利用堆空间

所以,经过调整之后,JVM的参数就如下图代码中所示:把年轻代的空间调大成1024M 这样老年代的空间就是512M 把CMS老年代内存使用阈值调大成90% 充分利用老年代的空间,如果并发量大的同学 有可能需要调低这个值 避免最后因为并发冲突导致使用Serial Old收集器

-Xms1536M -Xmx1536M -Xmn1024M -Xss256K -XX:SurvivorRatio=6 -XX:MetaspaceSize=256M -XX:MaxMetaspaceSize=256M -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=90 -XX:+UseCMSInitiatingOccupancyOnly
复制代码

猜想二:由于老年代空间担保机制导致频繁的发生Full GC

如果按照上面设置,把老年代设置小的话,很容易会因为老年代空间担保机制,导致频繁的发生Full GC,老年代空间担保机制的关键点在于每次Minor GC的时候进入老年代对象的平均大小,所以我们要控制每次Minor GC后进入老年代的对象平均大小

判断内存中对象的分布情况

使用jmap -histo 进程号的命令,观察内存中对象的分布情况,观察有没有比较集中的对象,因为如果是并发量高的系统,接口很有可能是集中的,创建的对象也是集中的,所以可以从cpu占用比较高的方法,也就是热点方法内存占用比较多的对象这两个方面去分析

  • 借助jvisualvm的抽样器寻找热点方法jdk8有 jdk11不支持

image.png

  • 借助jmap -histo 进程号观察占用内存比较多的对象从你工程中的对象入手

image.png

优化方向

  1. 如果是循环创建对象的话,尽量控制循环次数比如每次查询5000条记录,这些记录如果加载到内存就是要创建不少的对象,如果这批对象经过Minor GC,很容易由于老年代空间分配担保机制,发生Full GC,所以要减少查询记录条数,从而减少创建的对象

  2. 最快也是最有效的办法,在预算允许的情况下,增加物理机器的配置,增大整个堆的内存,在条件允许的情况下,也不失为一个好方法

本文总结

好啦,以上就是这篇文章的全部内容,在这篇文章中,我们也经历了下面的几个步骤

  1. 第一阶段:讲述了jmap、jinfo、jstack、jstat各个命令的基本使用,以及有什么作用
  2. 第二阶段:讲述了JVM的优化思路方向,总共可以分为两个方向
  3. 第三阶段:根据线上频繁的发生Full GC这个案例讲述了各个命令是怎么配合使用的

命令有点多,大家可以多多收藏,等到下次遇到问题了,可以直接翻出来使用

絮叨

最后,如果感到文章有哪里困惑的,请第一时间留下评论,如果各位看官觉得小沙弥我有点东西的话 求点赞👍 求关注❤️ 求分享👥 对我来说真的 非常有用!!!

文章分类
后端
文章标签