准备程序

先启动一个web应用程序,并且使用jps查看其进程id,接下来用jdk自带命令优化应用

[root@localhost parallels]# jps
7088 Jps
14331 jar

我的应用程序是jar包运行的,进程id为14331。

Jmap

此命令可以用来查看内存信息,实例以及占用内存大小

# 输出内容到指定的文件
jmap -histo 14331 > log.txt

打开log文件,查看内容如下。

 num     #instances         #bytes  class name
----------------------------------------------
   1:          7523       18968712  [I
   2:         35550       10435592  [B
   3:         73520        9374624  [C
   4:         56237        1349688  java.lang.String
   5:         13090        1151920  java.lang.reflect.Method
   6:          7273         803256  java.lang.Class
   7:         14520         464640  java.util.concurrent.ConcurrentHashMap$Node
   8:          8509         461712  [Ljava.lang.Object;
   9:         11336         453440  java.util.LinkedHashMap$Entry
  10:         20097         435304  [Ljava.lang.Class;
  11:          4705         400896  [Ljava.util.HashMap$Node;
  12:          6065         289464  [Ljava.lang.String;
  13:          8112         259584  java.util.HashMap$Node
  14:          4589         256984  java.util.LinkedHashMap
  15:          5163         247824  org.springframework.core.ResolvableType
  16:          2812         202464  java.lang.reflect.Field
  17:          9482         151712  java.lang.Object
  18:           117         149840  [Ljava.util.concurrent.ConcurrentHashMap$Node;
  19:          2304         147456  io.netty.buffer.PoolSubpage
  20:          1632         130560  java.lang.reflect.Constructor
  21:          4999         119976  java.lang.StringBuilder
  22:          2428         116544  java.util.HashMap
  23:          3236         103552  java.io.File
  .....
  • num :序号
  • instances:实例数量
  • bytes:占用空间大小
  • class name :类名称
    • -[I :int数组 、 [C:char数组 、 [B:Byte数组、[S:Short数组

查看堆信息

jmap -heap 14331

输出内容如下:

Attaching to process ID 14331, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.261-b12

using thread-local object allocation.
Parallel GC with 2 thread(s)

Heap Configuration:
	 #堆空间 空闲的最小百分比
   MinHeapFreeRatio         = 0
   #堆空间 空闲的最大百分比
   MaxHeapFreeRatio         = 100
   #堆空间允许的最大值
   MaxHeapSize              = 482344960 (460.0MB)
   #新生代堆空间的默认值
   NewSize                  = 10485760 (10.0MB)
   #新生代堆空间允许的最大值
   MaxNewSize               = 160432128 (153.0MB)
   #老年代堆空间的默认值
   OldSize                  = 20971520 (20.0MB)
   #新生代(2个Survivor区和Eden区 )与老年代(不包括永久区)的堆空间比值,表示新生代:老年代=1:2
   NewRatio                 = 2
   #两个Survivor区和Eden区的堆空间比值为 8,表示 S0 : S1 :Eden = 1:1:8。
   SurvivorRatio            = 8
   #JVM 元空间的默认值
   MetaspaceSize            = 21807104 (20.796875MB)
   #默认1G,这个参数主要是设置Klass Metaspace的大小,不过这个参数设置了也不一定起作用,前提是能开启压缩指针,假如-Xmx超过了32G,压缩指针是开启不来的。如果有Klass Metaspace,那这块内存是和Heap连着的
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   #JVM 元空间允许的最大值
   MaxMetaspaceSize         = 17592186044415 MB
   #在使用 G1 垃圾回收算法时,JVM 会将 Heap 空间分隔为若干个 Region,该参数用来指定每个 Region 空间的大小
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
PS Young Generation
#新生代的Eden区
Eden Space:
	 #Eden区大小
   capacity = 144703488 (138.0MB)
   #已使用大小
   used     = 67090824 (63.98279571533203MB)
   #可用大小
   free     = 77612664 (74.01720428466797MB)
   46.364344721255094% used
#Survivor From区
From Space:
	 #Survivor From区大小
   capacity = 7864320 (7.5MB)
   #已使用大小
   used     = 0 (0.0MB)
   #可用大小
   free     = 7864320 (7.5MB)
   0.0% used
#Survivor To区
To Space:
   #Survivor To区大小
   capacity = 7864320 (7.5MB)
   #已使用大小
   used     = 0 (0.0MB)
   #可用大小
   free     = 7864320 (7.5MB)
   0.0% used
#老年代区
PS Old Generation
	 #老年代区大小
   capacity = 31457280 (30.0MB)
   #已使用大小
   used     = 11287816 (10.764900207519531MB)
   #可用大小
   free     = 20169464 (19.23509979248047MB)
   35.88300069173177% used

12532 interned Strings occupying 1068848 bytes.

查看堆内存占用

#导出堆内存快照文件  file={文件名}
jmap -dump:format=b,file=service.dump 14331

使用jvisualvm导入dump文件分析

如果是oracle jdk的话,可以直接执行jvisualvm,会启动这个工具,如果是openjdk的话,需要手动下载这个工具。

下载地址:https://visualvm.github.io/download.html

如果mac os,安装jdk是用解压方式安装,那么jvisualvm会找不到jdk目录,需要手动指定jdkhome,如下:

./visualvm --jdkhome /Users/pencilso/tools/java/jdk-8.jdk/Contents/Home

jvisualvm_load

对象分析,查看object实例大小,和实例数量。

jvisualvm_3

排查OOM内存溢出

如果OOM内存溢出的话,怎么生成这个内存快照文件?

我们可以通过设置JVM参数,在Java进程出现内存溢出的时候,生成一个dump快照文件

  • -XX:+HeapDumpOnOutOfMemoryError
  • -XX:HeapDumpPath=/xxx/xxx.dump

例如(我这里把堆内存设小点,更容易复现):java -jar server.jar -Xms10M -Xmx20M -XX:+PrintGCDetails -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/Users/pencilso/dump/jvm.dump

当程序出现OOM之后,我们把生成的dump文件导入到jvisualvm进行分析。(如果内存实在太大,有可能会生成不出来)

jvisualvm-4

如上图所示,可以看到占用内存最大的是byte数组,其次是char数组,然后是String。

接着往下找,寻找我们自己编写的类,可以在下面的Class Filter进行过滤。

jvisualvm-5

如上图所示,找到了数量最多的是一个UserModel的类。在idea中打开这个类进行分析。

@Data
@Accessors(chain = true)
public class UserModel {
    private String name;
    private Integer age;
    private byte[] buffer = new byte[1024 * 5];
}

如上述代码所示,可以看到UserModel里面创建了一个5kb的byte数组。

接下来再分析,创建UserModel的地方,全局搜一下 new UserModel 。

   //搜索到的关键点
   public List<UserModel> queryUser() {
        List<UserModel> userModelList = new ArrayList<>();
        for (int i = 0; i < 1000; i++) {
            userModelList.add(new UserModel().setName("user:" + i).setAge(i));
        }
        return userModelList;
    }

    private final List<UserModel> list = new ArrayList<>();
    @GetMapping("query_user")
    public List<UserModel> queryUser() {
        List<UserModel> userModelList = queryUser();
       //添加到静态变量里了,无法释放
        list.addAll(userModelList);
        return userModelList;
    }

如上述代码,通过全局搜索创建对象的地方,找到蛛丝马迹。

但是如果创建对象的地方过多,那么挨个去分析肯定不太合理。

jvisualvm-6

如上图所示,OOM溢出的线程 jvisualvm会标红,可以对该线程进行分析执调用的一些代码。

排查死锁问题

示例Java代码:

public class DeadLockTest {
    private final static Object lock_1 = new Object();
    private final static Object lock_2 = new Object();

    public static void main(String[] args) {
        new Thread(() -> {
            //加锁-1
            synchronized (lock_1) {
                System.out.println("thread -1 begin");
                //延迟一秒
                try {
                    Thread.sleep(1000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }

                //加锁-2
                synchronized (lock_2) {

                    System.out.println("thread -1 end");
                }
            }

        }).start();

        new Thread(() -> {
            System.out.println("thread -2 begin");
            //加锁-2
            synchronized (lock_2) {
                //延迟一秒
                try {
                    Thread.sleep(1000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
                synchronized (lock_1) {
                    System.out.println("thread -2 end");
                }
            }

        }).start();
    }
}

执行结果如下:

thread -1 begin
thread -2 begin

解读:

声明了两个对象作为锁,lock_1、lock_2,线程-1执行时获取lock_1锁,线程-2执行时获取lock_2锁,这时候是没有问题的。

但是线程-1延迟1秒后去获取lock_2锁,但是lock_2锁被线程-2获取了还没释放,线程2执行完毕后才会释放锁,而线程-2又要获取lock-1锁才能结束线程执行。所以最后两个线程一直会卡住等待对方释放锁。这两个线程永远不会结束。

结构图如下:

jvisualvm-7

用Jvisualvm自动检测死锁

jvisualvm-8

通过Thread Dump分析死锁原因

jvisualvm-9

用Jstack命令检测死锁

除了用jvisualvm检测,还可以用jstack命令进行检测,而且jvisualvm也是封装的jstack命令。

jstack {pid}

输出如下,跟jvisualvm的结果是一样的

...............
Found one Java-level deadlock:
=============================
"Thread-1":
  waiting to lock monitor 0x00007fdfd78186a8 (object 0x000000071d628468, a java.lang.Object),
  which is held by "Thread-0"
"Thread-0":
  waiting to lock monitor 0x00007fdfd7815e18 (object 0x000000071d628478, a java.lang.Object),
  which is held by "Thread-1"

Java stack information for the threads listed above:
===================================================
"Thread-1":
	at cn.pencilso.study.studyjvmtuning.DeadLockTest.lambda$main$1(DeadLockTest.java:43)
	- waiting to lock <0x000000071d628468> (a java.lang.Object)
	- locked <0x000000071d628478> (a java.lang.Object)
	at cn.pencilso.study.studyjvmtuning.DeadLockTest$$Lambda$2/815033865.run(Unknown Source)
	at java.lang.Thread.run(Thread.java:748)
"Thread-0":
	at cn.pencilso.study.studyjvmtuning.DeadLockTest.lambda$main$0(DeadLockTest.java:26)
	- waiting to lock <0x000000071d628478> (a java.lang.Object)
	- locked <0x000000071d628468> (a java.lang.Object)
	at cn.pencilso.study.studyjvmtuning.DeadLockTest$$Lambda$1/1401420256.run(Unknown Source)
	at java.lang.Thread.run(Thread.java:748)

Found 1 deadlock.

找出占用CPU最高的线程堆栈信息

示例Java代码

public class MathTest {
    public static int compute() {
        int a = 1;
        int b = 2;
        int c = (a + b) * 10;
        return c;
    }

    public static void main(String[] args) {
        while (true) {
            compute();
        }
    }
}

先通过jps查找java的进程id,例如16862

#可以看到CPU使用率在100%
PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                                                                                           
16862 root      20   0 2684272  21252  10408 S 100.0  1.1   0:12.79 java  

按shift+h键,获取每个线程的内存情况。

  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND                                                                                                                                                            
16863 root      20   0 2684272  21252  10408 R 99.9  1.1   1:41.36 java                                                                                                                                                               
16873 root      20   0 2684272  21252  10408 S  0.3  1.1   0:00.04 java                                                                                                                                                               
16862 root      20   0 2684272  21252  10408 S  0.0  1.1   0:00.00 java                                                                                                                                                               
16864 root      20   0 2684272  21252  10408 S  0.0  1.1   0:00.00 java                                                                                                                                                               
16865 root      20   0 2684272  21252  10408 S  0.0  1.1   0:00.00 java                                                                                                                                                               
16866 root      20   0 2684272  21252  10408 S  0.0  1.1   0:00.00 java                                                                                                                                                               
16867 root      20   0 2684272  21252  10408 S  0.0  1.1   0:00.00 java                                                                                                                                                               
16868 root      20   0 2684272  21252  10408 S  0.0  1.1   0:00.00 java                                                                                                                                                               
16869 root      20   0 2684272  21252  10408 S  0.0  1.1   0:00.00 java                                                                                                                                                               
16870 root      20   0 2684272  21252  10408 S  0.0  1.1   0:00.00 java                                                                                                                                                               
16871 root      20   0 2684272  21252  10408 S  0.0  1.1   0:00.00 java                                                                                                                                                               
16872 root      20   0 2684272  21252  10408 S  0.0  1.1   0:00.00 java 

找到内存和CPU占用最高的线程id,比如我这里是16863,并且转为十六进制,:0x41df(要记得小写)

执行命令查看线程所在行的后面10行,得到线程堆栈信息中0x41df这个线程所在行的后面10行代码,从堆栈中可以发现导致CPU彪高的调用方法。

 jstack {java进程id}|grep -A {num} {threadId}
 示例:jstack 16862|grep -A 10 41df

打印输出如下:找到了关键代码MathTest.java 的第11行代码。也就是调用compute();的这一行代码。

"main" #1 prio=5 os_prio=0 tid=0x00007f479c009800 nid=0x41df runnable [0x00007f47a3417000]
   java.lang.Thread.State: RUNNABLE
        at MathTest.main(MathTest.java:11)

"VM Thread" os_prio=0 tid=0x00007f479c073800 nid=0x41e2 runnable 

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f479c01e800 nid=0x41e0 runnable 

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f479c020800 nid=0x41e1 runnable 

"VM Periodic Task Thread" os_prio=0 tid=0x00007f479c0d7000 nid=0x41e9 waiting on condition 

JVM参数查看

查看正在运行的Java应用的扩展参数

##执行命令,
jinfo -flags 18172
## 输出如下
VM Flags:
-XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:CICompilerCount=12 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/Users/pencilso/dump/jvm.dump -XX:InitialHeapSize=10485760 -XX:+ManagementServer -XX:MaxHeapSize=20971520 -XX:MaxNewSize=6815744 -XX:MinHeapDeltaBytes=524288 -XX:NewSize=3145728 -XX:OldSize=7340032 -XX:+PrintGCDetails -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseFastUnorderedTimeStamps -XX:+UseParallelGC 

查看java系统参数

##执行命令
jinfo -sysprops 18172
##输出如下
java System Properties:
#Wed Jul 22 16:15:58 CST 2020
spring.output.ansi.enabled=always
java.runtime.name=Java(TM) SE Runtime Environment
sun.boot.library.path=/Users/pencilso/tools/java/jdk1.8.0_231.jdk/Contents/Home/jre/lib
java.vm.version=25.231-b11
gopherProxySet=false
java.vm.vendor=Oracle Corporation
java.vendor.url=http\://java.oracle.com/
path.separator=\:
java.rmi.server.randomIDs=true
java.vm.name=Java HotSpot(TM) 64-Bit Server VM
file.encoding.pkg=sun.io
user.country=CN
sun.java.launcher=SUN_STANDARD
sun.os.patch.level=unknown
...................

JVM统计

垃圾回收统计

可以评估程序内存使用以及GC压力整体情况

##执行命令
jstat -gc 18172

jvisualvm-10

  • S0C :第一个幸存区的大小,kb
  • S1C:第二个幸存区的大小
  • S0C:第一个幸存区的使用大小
  • S1U:第二个幸存区的使用大小
  • EC:伊甸园区的大小
  • EU:伊甸园区的使用大小
  • OC:老年代大小
  • OU:老年代使用大小
  • MC:方法区大小(元空间)
  • MU:方法区使用大小
  • CCSC:压缩类空间大小
  • CCSU:压缩类空间使用大小
  • YGC:年轻代垃圾回收次数
  • YGCT:年轻代垃圾回收消耗时间,单位s
  • FGC:老年代垃圾回收次数
  • FGCT:老年代垃圾回收消耗时间,单位s
  • GCT:垃圾回收消耗总时间,单位s

堆内存统计

## 统计内存
jstat -gccapacity 18172

jvisualvm-11

  • NGCMU:新生代最小容量
  • NGCMX:新生代最大容量
  • NGC:当前新生代容量
  • S0C:第一个幸存区的大小
  • S1C:第二个幸存区的大小
  • EC:伊甸园区的大小
  • OGCMN:老年代最小容量
  • OGCMX:老年代最大容量
  • OGC:当前老年代大小
  • OC:老年代大小
  • MCMN:最小元数据容量
  • MCMX:最大元数据容量
  • MC:当前元数据空间大小
  • CCSMN:最小压缩类空间大小
  • CCSMX:最大压缩类空间大小
  • CCSC:当前压缩类空间大小
  • YGC:年轻代gc次数
  • FGC:老年代GC次数

新生代垃圾回收统计

##执行命令
jstat -gcnew 18172

##输出如下
 S0C    S1C    S0U    S1U   TT MTT  DSS      EC       EU     YGC     YGCT  
 512.0  512.0  128.0    0.0 15  15  512.0   2560.0    878.5    136    0.208
  • S0C:第一个幸存区的大小
  • S1C:第二个幸存区的大小
  • S0U:第一个幸存区的使用大小
  • S1U:第二个幸存区的使用大小
  • TT:对象在新生代存活的次数
  • MTT:对象在新生代存活的最大次数
  • DSS:期望的幸存区大小
  • EC:伊甸园区的大小
  • EU:伊甸园区的使用大小
  • YGC:年轻代垃圾回收次数
  • YGCT:年轻代垃圾回收消耗时间

新生代内存统计

##执行命令
jstat -gcnewcapacity 18172

##输出如下
  NGCMN      NGCMX       NGC      S0CMX     S0C     S1CMX     S1C       ECMX        EC      YGC   FGC   CGC 
  3072.0     6656.0     4096.0   2048.0    512.0   2048.0    512.0     5632.0     2560.0   138     4     -
  • NGCMN:新生代最小容量
  • NGCMX:新生代最大容量
  • NGC:当前新生代容量
  • S0CMX:最大幸存1区大小
  • S0C:当前幸存1区大小
  • S1CMX:最大幸存2区大小
  • S1C:当前幸存2区大小
  • ECMX:最大伊甸园区大小
  • EC:当前伊甸园区大小
  • YGC:年轻代垃圾回收次数
  • FGC:老年代回收次数

老年代垃圾回收统计

##执行命令
jstat -gcold 18172
##输出如下
   MC       MU      CCSC     CCSU       OC          OU       YGC    FGC    FGCT    CGC    CGCT     GCT   
 35840.0  33545.1   4864.0   4436.5     13824.0     12298.6    141     4    0.258     -        -    0.472

  • MC:方法区大小
  • MU:方法区使用大小
  • CCSC:压缩类空间大小
  • CCSU:压缩类空间使用大小
  • OC:老年代大小
  • OU:老年代使用大小
  • YGC:年轻代垃圾回收次数
  • FGC:老年代垃圾回收次数
  • FGCT:老年代垃圾回收消耗时间
  • GCT:垃圾回收消耗总时间

老年代内存统计

##执行命令
jstat -gcoldcapacity 18172
##输出如下
   OGCMN       OGCMX        OGC         OC       YGC   FGC    FGCT    CGC    CGCT     GCT   
   7168.0     13824.0     13824.0     13824.0   144     4    0.258     -        -    0.476
  • OGCMN:老年代最小容量
  • OGCMX:老年代最大容量
  • OGC:当前老年代大小
  • OC:老年代大小
  • YGC:年轻代垃圾回收次数
  • FGC:老年代垃圾回收次数
  • FGCT:老年代垃圾回收消耗时间
  • GCT:垃圾回收消耗总时间

元数据空间统计

#执行指令
jstat -gcmetacapacity 18172
#输出如下
   MCMN       MCMX        MC       CCSMN      CCSMX       CCSC     YGC   FGC    FGCT    CGC    CGCT     GCT   
   0.0  1081344.0    35840.0        0.0  1048576.0     4864.0   146     4    0.258     -        -    0.478
  • MCMN:最小元数据容量
  • MCMX:最大元数据容量
  • MC:当前元数据空间大小
  • CCSMN:最小压缩类空间大小
  • CCSMX:最大压缩类空间大小
  • CCSC:当前压缩类空间大小
  • YGC:年轻代垃圾回收次数
  • FGC:老年代垃圾回收次数
  • FGCT:老年代垃圾回收消耗时间
  • GCT:垃圾回收消耗总时间

总结垃圾回收统计

#执行命令
jstat -gcutil 18172
#输出如下
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT    CGC    CGCT     GCT   
 25.00   0.00  32.32  89.20  93.60  91.21    152    0.228     4    0.258     -        -    0.486
  • **S0:**幸存1区当前使用比例
  • **S1:**幸存2区当前使用比例
  • **E:**伊甸园区使用比例
  • **O:**老年代使用比例
  • **M:**元数据区使用比例
  • **CCS:**压缩使用比例
  • **YGC:**年轻代垃圾回收次数
  • **FGC:**老年代垃圾回收次数
  • **FGCT:**老年代垃圾回收消耗时间
  • **GCT:**垃圾回收消耗总时间

JVM 调优

年轻代对象增长的速率

可以执行命令jstat -gc pid 1000 10(每隔1秒执行一次命令,共执行10次),通过观察EU(Eden区的使用)来估算每秒eden大概新增多少对象,如果系统负载不高,可以把频率1秒换成1分钟,甚至10分钟来观察整体情况。

注意,一般系统可能会有高峰期和日长期,所以需要在不同的时间分别估算不同情况下对象增长速率。

Young GC的触发频率和每次耗时

知道年轻代对象增长速率我们就能根据Eden区的大小推算出Young GC大概多久触发一次,Young GC的平均耗时可以通过YGCT/YGC公式算出,根据结果我们大概就能知道系统大概多久会因为Young GC的执行而卡顿多久。

每次Young GC后有多少对象存活和进入老年代

这个因为之前已经大概知道Young GC的频率,假设是5分钟一次,那么可执行命令jstat -gc pid 300000 10,管擦每次结果Eden、Survivor和老年代使用的变化情况,在每次GC后Eden区使用一般会大幅减少,Survivor和老年代都有可能增长,这些增长的对象就是Young GC后存活的对象,同时还可以看出每次Young GC后进去老年代大概多少对象,从而可以推算出老年代对象增长速率。

Full GC的触发频率和每次耗时

知道了老年代对象的增长速率就可以推算出Full GC的触发频率了,Full GC的每次耗时可以用公示 FGCT/FGC计算得出。

JVM运行情况预估

用jstat gc -pid 命令可以计算出如上述一些关键数据,有了这些数据就可以先给自己的系统设置一些初始性的JVM参数,比如堆内存大小、年轻代大小、Eden和Survivor的比例、老年代的大小、大对象的阈值、大龄对象进入老年代的阈值等。

优化思路

优化思路很简单,其实就是尽量让每次Young GC后的存活对象小于Survivor区域的50%,把对象都留在年轻代里,尽量别让对象进入老年代。减少Full GC的频率,避免频繁Full GC对JVM性能的影响。

部分参考自 : https://www.cnblogs.com/kabi/p/12124826.html