阅读 5285

JVM 性能调优监控工具

本篇主要学习记录下工作中常用的 JDK 自带的一些 JVM 性能调优监控工具,通过了解这些工具,可以在排查问题时给予我们非常大的帮助,将一些隐藏在底下的东西拿到明面上来做分析。

jps(Java Virtual Machine Process Status Tool)

jps 主要用来输出 JVM 中运行的进程状态信息。语法格式如下:

jps [options] [hostid]
复制代码

如果不指定 hostid 就默认为当前主机或服务器,命令行参数选项说明如下:

-q 不输出类名、Jar名和传入main方法的参数

➜  ~ jps -q
42060
复制代码

-m 输出传入 main 方法的参数(与默认 jps 指令返回的信息相同)

➜  ~ jps -m
42060 TestSofaBootApplication
复制代码

-l 输出 main 类或 jar 的全限名

➜  ~ jps -l
42060 com.glmapper.bridge.boot.TestSofaBootApplication
复制代码

-v 输出传入 JVM 的参数

➜  ~ jps -v
42060 TestSofaBootApplication -agentlib:jdwp=transport=dt_socket,address=127.0.0.1:51645,suspend=y,server=n -XX:TieredStopAtLevel=1 -Xverify:none -Dspring.output.ansi.enabled=always -Dcom.sun.management.jmxremote -Dspring.jmx.enabled=true -Dspring.liveBeansView.mbeanDomain -Dspring.application.admin.enabled=true -javaagent:/Users/xxxx/Library/Caches/JetBrains/IntelliJIdea2020.1/captureAgent/debugger-agent.jar -Dfile.encoding=UTF-8
复制代码

在排查问题时,我们通过都会通过 jps 来看下当前机器运行的进程有哪些,通过不同的参数来快速找到我们目标进程所在的 pid,以便于我们后续的一系列排查操作。

jstack(Java Stack Trace)

jstack 主要用来查看某个 Java 进程内的线程堆栈信息。如果 java 程序崩溃生成 core 文件,jstack 工具可以用来获得 core 文件的 java stacknative stack 的信息,从而可以轻松地知道 java 程序是如何崩溃和在程序何处发生问题。另外,jstack 工具还可以附属到正在运行的 java 程序中,看到当时运行的 java 程序的 java stacknative stack 的信息, 如果现在运行的 java 程序呈现 hung 的状态,jstack 是非常有用的。

下面是 jstack 语法格式:

jstack [option] pid
jstack [option] executable core
jstack [option] [server-id@]remote-hostname-or-ip
复制代码

不管是什么指令,我们都要学会先通过 -h 去查一下

➜  ~ jstack -h
Usage:
    jstack [-l] <pid>
        (连接到正在运行的进程)
    jstack -F [-m] [-l] <pid>
        (连接到挂起的进程)
    jstack [-m] [-l] <executable> <core>
        (连接到 core 文件)
    jstack [-m] [-l] [server_id@]<remote server IP or hostname>
        (连接到远程调试服务器)

Options:
    -F  to force a thread dump. Use when jstack <pid> does not respond (process is hung)
    -m  to print both java and native frames (mixed mode)
    -l  long listing. Prints additional information about locks
    -h or -help to print this help message
复制代码

Options 参数说明如下:

选项作用
-F当正常输出的请求不被响应时,强制输出线程堆栈
-m如果调用到本地方法的话,可以显示 C/C++ 的堆栈
-l除堆栈外,显示关于锁的附加信息,在发生死锁时可以用 jstack -l pid 来观察锁持有情况

下面我们重点来聊一聊,jstack 中信息到底要怎么看。

jstack 堆栈信息介绍

下面是 jstack 输出的一段 tacer 数据

"main" #1 prio=5 os_prio=31 tid=0x00007fb93b802000 nid=0x2703 waiting on condition [0x0000700005e5d000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at com.glmapper.bridge.boot.TestJstack.testWaitingOnConditionCondition(TestJstack.java:19)
	at com.glmapper.bridge.boot.TestJstack.main(TestJstack.java:10)
复制代码

通过这段数据我们大概能 get 到的点主要包括以下信息:

  • main 线程名
  • #1 堆栈序号,没有实际含义,可忽略
  • prio 线程优先级
  • os_prio 操作系统层次的优先级
  • tid 线程标识
  • nid 线程id

线程状态介绍

从上面 jstack 输出的信息可以看到线程状态相关的信息,比如

TIMED_WAITING

java.lang.Thread.State: TIMED_WAITING (sleeping)
复制代码

RUNNABLE

java.lang.Thread.State: RUNNABLE
复制代码

还有一些 "GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007fcee9004000 nid=0x1f07 runnable 信息,这种是 jvm 用来回收内存的,先不关注,这里主要看下 java.lang.Thread.State;

public enum State {
    /**
     * 当线程对象创建时存在的状态,此时线程不可能执行
     */
    NEW,
   /**
    * 当调用thread.start()后,线程变成为 Runnable 状态。只要得到CPU,就可以执行;
    */
    RUNNABLE,
    /**
     * 如果进入同步方法或同步代码块,没有获取到锁,则会进入该状态;
     */
    BLOCKED,
    /**
     * 执行thread.join()或在锁对象调用obj.wait()等情况就会进该状态,表明线程正处于等待某个资源或条件发生来唤醒自己;
     */
    WAITING,
    /**
     * 执行Thread.sleep(long)、thread.join(long)或obj.wait(long)等就会进该状态,与Waiting的区别在于Timed_Waiting的等待有时间限制;
     */
    TIMED_WAITING,
    /**
     * 终止
     */
    TERMINATED;
}
复制代码

再回到上面堆栈信息,可以观察到,当状态是 TIMED_WAITING 时,堆栈中会出现 waiting on condition xxxx 信息,类似的还有:

  • waiting on monitor entry : 在等待获取锁,一般对应 BLOCKED
  • in Object.wait() : 获取锁后又执行obj.wait()放弃锁,一般对应 WAITING

下面就针对这些状态举一些简单的小例子。

线程状态举例及 jstack 分析

waiting on condition

1、执行代码

/**
 * 产生 waiting on condition
 */
private static void testWaitingOnConditionCondition(){
    while (true){
        try {
            Thread.sleep(60000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}
复制代码

2、执行结果

"main" #1 prio=5 os_prio=31 tid=0x00007fb93b802000 nid=0x2703 waiting on condition [0x0000700005e5d000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at com.glmapper.bridge.boot.TestJstack.testWaitingOnConditionCondition(TestJstack.java:19)
	at com.glmapper.bridge.boot.TestJstack.main(TestJstack.java:10)
复制代码

3、结果分析

这里就比较明显的是 main 线程中正在 sleep 方法。不过这里 TIMED_WAITING 后面的括号里还特殊表明了 sleeping,在一些场景下,常见的还有 parking,下面继续看例子。

waiting on condition (parking)

1、执行代码

private static void testWaitingOnConditionConditionWithParking(){
    // 提供一个阻塞对了
    BlockingQueue<String> blockingQueue = new ArrayBlockingQueue<String>(1);
    // 先加一个
    blockingQueue.add("test-parking");
    try {
        //继续加,这里肯定加不进去,所以会阻塞
        blockingQueue.put("test-parking-xxx");
    } catch (InterruptedException e) {
        e.printStackTrace();
    }
}
复制代码

2、执行结果

"main" #1 prio=5 os_prio=31 tid=0x00007fd6d5008800 nid=0x2803 waiting on condition [0x000070000ffc1000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x000000076af3a938> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
	at java.util.concurrent.ArrayBlockingQueue.put(ArrayBlockingQueue.java:353)
	at com.glmapper.bridge.boot.TestJstack.testWaitingOnConditionConditionWithParking(TestJstack.java:113)
	at com.glmapper.bridge.boot.TestJstack.main(TestJstack.java:13)
复制代码

3、结果分析

main 线程进入了 waiting on conditon 状态,等待某一个资源,可以看到是在 a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObjec 进行了等待,阻塞住了。

waiting on monitor entry

1、执行代码

/**
 * 产生 waiting on monitor entry
 */
private static void testWaitingOnMonitorEntry(){
    final Object obj = new Object();
    final Thread thread = new Thread(){
        @Override
        public void run() {
            // 锁 obj 对象
            synchronized (obj){
                System.out.println(Thread.currentThread().getName());
                try {
                    Thread.sleep(60000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }
        }
    };
    final Thread thread1 = new Thread(){
        @Override
        public void run() {
            // 锁 obj 对象
            synchronized (obj){
                System.out.println(Thread.currentThread().getName());
                try {
                    Thread.sleep(60000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }
        }
    };
    thread.setName("test-thread");
    thread.start();
    thread1.setName("test-thread1");
    thread1.start();
}
复制代码

2、执行结果

"test-thread1" #14 prio=5 os_prio=31 tid=0x00007f9563880800 nid=0x5c03 waiting for monitor entry [0x000070000b029000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at com.glmapper.bridge.boot.TestJstack$2.run(TestJstack.java:50)
	- waiting to lock <0x000000076af261d0> (a java.lang.Object)

"test-thread" #13 prio=5 os_prio=31 tid=0x00007f956387f800 nid=0x5a03 waiting on condition [0x000070000af26000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at com.glmapper.bridge.boot.TestJstack$1.run(TestJstack.java:38)
	- locked <0x000000076af261d0> (a java.lang.Object)
复制代码

3、结果分析

test-thread 获取到 obj 对象上的锁,因此正在执行 sleep 操作,状态为 TIMED_WAINTING, 而 test-thread1 由于未获取到 obj 对象上的锁,因此处于BLOCKED 状态。

test-thread1 正在 "waiting to lock <0x000000076af261d0>",试图在地址为 0x000000076af261d0 所在的对象获取锁,而该锁却被 test-thread 线程占有 [locked <0x000000076af261d0>]。test-thread 线程正在 "waiting on condition",说明正在等待某个条件触发,由 jstack 来看,此线程正在sleep。

object.wait()

1、执行代码

private static void testObjectWait() {
    final Thread thread = new Thread() {
        @Override
        public void run() {
            synchronized (this) {
                System.out.println(Thread.currentThread().getName());
                try {
                    wait();
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }
        }
    };
    thread.start();
    thread.setName("test-object-wait");
    try {
        Thread.sleep(5000);
    } catch (InterruptedException e) {
        e.printStackTrace();
    }

    synchronized (thread) {
        System.out.println(Thread.currentThread().getName());
        try {
            Thread.sleep(30000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        thread.notify();
    }
}
复制代码

2、执行结果

"test-object-wait" #13 prio=5 os_prio=31 tid=0x00007fd43a809000 nid=0xa803 in Object.wait() [0x0000700010926000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x000000076af26140> (a com.glmapper.bridge.boot.TestJstack$3)
	at java.lang.Object.wait(Object.java:502)
	at com.glmapper.bridge.boot.TestJstack$3.run(TestJstack.java:73)
	- locked <0x000000076af26140> (a com.glmapper.bridge.boot.TestJstack$3)

"main" #1 prio=5 os_prio=31 tid=0x00007fd43b001800 nid=0x2603 waiting on condition [0x000070000f2e4000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at com.glmapper.bridge.boot.TestJstack.testObjectWait(TestJstack.java:93)
	- locked <0x000000076af26140> (a com.glmapper.bridge.boot.TestJstack$3)
	at com.glmapper.bridge.boot.TestJstack.main(TestJstack.java:10)
复制代码

3、结果分析

由于调用了 object.wait() 方法的时候放弃了锁,所以 test-object-wait 这个线程就出现了 Object.wait() 状态,线程的状态就是 waiting;等待 notify 来进行唤醒。由于 mian 线程在获得 test-object-wait 的线程锁后,调用了 Thread.sleep 方法,所以此时进入了 wating on condition 等待某一个资源,进入到 time_waiting 状态。

小结

一般情况我们在做问题排查时,如果系统非常慢,我们需要特别关注 BlockedWaiting on condition 这些状态。如果系统的 cpu 负载比较高的话,则可以死循环等思路去摸查,此时要关注下 Runable 状态;那如果堆栈中有 Deadlock,那就是产生了死锁。

jstat(JVM统计监测工具)

jstat 是 JVM 统计监测工具,其语法格式如下:

jstat -<option> [-t] [-h<lines>] <vmid> [<interval> [<count>]]
复制代码

vmidJava 虚拟机 ID,在 Linux/Unix 系统上一般就是进程 IDinterval 是采样时间间隔; count 是采样数目。比如下面输出的是 GC 信息,采样时间间隔为 1000ms,采样数为 3:

➜  ~ jstat -gc 58950 1000 3
S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT
10752.0 10752.0  0.0    0.0   65536.0   6554.0   175104.0     0.0     4480.0 785.7  384.0   75.9       0    0.000   0      0.000    0.000
10752.0 10752.0  0.0    0.0   65536.0   6554.0   175104.0     0.0     4480.0 785.7  384.0   75.9       0    0.000   0      0.000    0.000
10752.0 10752.0  0.0    0.0   65536.0   6554.0   175104.0     0.0     4480.0 785.7  384.0   75.9       0    0.000   0      0.000    0.000
复制代码

输出信息的列释义:

  • S0C、S1C、S0U、S1U:Survivor 0/1区容量(Capacity)和使用量(Used)
  • EC、EU:Eden区容量和使用量
  • OC、OU:年老代容量和使用量
  • PC、PU:永久代容量和使用量
  • YGC、YGT:年轻代 GC 次数和 GC 耗时
  • FGC、FGCT:Full GC 次数和 Full GC耗时
  • GCT:GC 总耗时

jmap(Memory Map)

jmap 用来查看堆内存使用状况,一般结合 jhat 使用。其使用语法如下:

jmap [option] <pid>
jmap [option] <executable <core>
jmap [option] [server_id@]<remote server IP or hostname>
复制代码

Options 参数说明如下:

选项作用
打印与 Solaris pmap 相同的信息
-heap打印 java 堆摘要
-histo[:live]打印 java 对象堆的直方图;如果指定了“live”子选项,则只计算live对象
-clstats打印 classloader 统计信息
-finalizerinfo打印 等待终结 对象的信息
--dump: :以 hprof 二进制格式dump java heap
-F使用 -dump: or -histo 强制执行
-J将 直接传递给运行时系统

dump-options 又包括以下几个选项:

  • live : 只 dump 活动对象;如果未指定,堆中的所有对象将被dump。
  • format=b : 二进制格式
  • file= : dump 到指定文件

jmap -heap

通过指定 pid,可以将当前进程的 heap 信息打印在 console 上,包括使用的 GC 算法、堆配置参数和各代中堆内存使用情况,如下:

$ jmap -heap 3493
Attaching to process ID 3493, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.172-b245

using parallel threads in the new generation.(eden 区使用的是并发线程)
using thread-local object allocation.(使用线程本地对象分配)
Concurrent Mark-Sweep GC (使用 CMS 垃圾收集器)
# 堆配置信息
Heap Configuration:
   MinHeapFreeRatio         = 40
   MaxHeapFreeRatio         = 70
   MaxHeapSize              = 2147483648 (2048.0MB)
   NewSize                  = 805306368 (768.0MB)
   MaxNewSize               = 805306368 (768.0MB)
   OldSize                  = 1342177280 (1280.0MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

# 堆使用情况
Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 724828160 (691.25MB)
   used     = 35156456 (33.527809143066406MB)
   free     = 689671704 (657.7221908569336MB)
   4.850315970063856% used
Eden Space:
   capacity = 644349952 (614.5MB)
   used     = 19878008 (18.95714569091797MB)
   free     = 624471944 (595.542854309082MB)
   3.084970820328392% used
From Space:
   capacity = 80478208 (76.75MB)
   used     = 15278448 (14.570663452148438MB)
   free     = 65199760 (62.17933654785156MB)
   18.984577787815553% used
To Space:
   capacity = 80478208 (76.75MB)
   used     = 0 (0.0MB)
   free     = 80478208 (76.75MB)
   0.0% used
concurrent mark-sweep generation:
   capacity = 1342177280 (1280.0MB)
   used     = 166885296 (159.1542205810547MB)
   free     = 1175291984 (1120.8457794189453MB)
   12.433923482894897% used

55843 interned Strings occupying 6689024 bytes.
复制代码

jmap -clstats

通过指定 pid ,可以将当前进程的 classloader 统计信息打印在 console 上,包括类加载器名称、对象是否存活、对象地址、父类加载器、已加载的类大小等信息,如下:

$ jmap -clstats  3493
Attaching to process ID 3493, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.172-b245
finding class loader instances ..done.
computing per loader stat ..done.
please wait.. computing liveness.......................liveness analysis may be inaccurate ...
class_loader	classes	bytes	parent_loader	alive?	type

<bootstrap>	3211	5818395	  null  	live	<internal>
0x00000000b150ed50	1	1491	0x00000000b0020830	dead	sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000b8715670	1	900	    0x00000000b0020830	dead	sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000cb417140	1	1503	0x00000000b0020830	dead	sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000b98b4388	1	1491	  null  	dead	sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000b5a419a0	1	900	    0x00000000b0020830	dead	sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000b358df50	1	1493	0x00000000b0020830	dead	sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000b7b277b8	1	1503	0x00000000b0020830	dead	sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000c2527c58	1	1505	0x00000000b0020830	dead	sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000b98b4580	1	1491	0x00000000b0026260	dead	sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000b9b307b8	1	1493	0x00000000b0020830	dead	sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000e236b038	1	900	    0x00000000b0020830	dead	sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000b0108400	1	1493	0x00000000b0020830	dead	sun/reflect/DelegatingClassLoader@0x000000010000a040
0x00000000b010bc00	3	7946	0x00000000b0022f60	live	org/jacoco/compass/agent/rt/internal/fastjson/util/ASMClassLoader@0x00000001000eb830
0x00000000b358e148	1	1493	0x00000000b0020830	dead	sun/reflect/DelegatingClassLoader@0x000000010000a040
复制代码

jmap -histo

使用 jmap -histo pid 可以查看堆内存中的对象数目、大小统计直方图,如下:

# jmap -histo:live 1493  带上 live 则只统计存活对象
$ jmap -histo 1493  
num     #instances         #bytes  class name
----------------------------------------------
   1:       1314509      144436976  [C
   2:       1572864       37748736  org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapper
   3:         77458       32776608  [B
   4:       1061561       25477464  java.lang.String
   5:        731623       23411936  java.util.HashMap$Node
   6:         32930       22826616  [I
   7:        150340       15546784  [Ljava.util.HashMap$Node;
   8:        144895       14968208  [Ljava.lang.Object;
   9:        377379       12076128  java.util.concurrent.ConcurrentHashMap$Node
  10:        230943       11085264  java.util.HashMap
  11:         81124        3893952  java.nio.HeapByteBuffer
  12:          3396        3869944  [Ljava.util.concurrent.ConcurrentHashMap$Node;
  13:         78418        3764064  java.nio.HeapCharBuffer
  14:         75784        3031360  java.util.TreeMap$Entry
  15:         72865        2914600  java.util.LinkedHashMap$Entry
  16:        166213        2659408  java.util.HashSet
  17:         18355        2643120  com.mysql.jdbc.Field
  18:         18394        2044336  java.lang.Class
  19:         19966        1757008  java.lang.reflect.Method
复制代码

PS: 上图中的 [C [B 指的是 class 的对象类型,下面是常见类型的参考

  • B byte
  • C char
  • D double
  • F float
  • I int
  • J long
  • Z boolean
  • [ 数组,如 [I 表示 int[]
  • [L+类名 其他对象,如 [Ljava.lang.Object

jmap -dump

绝大多数情况下,我们不会直接在 console 来打印分析,更常规的做法是 dump 到指定的文件,然后通过一些可视化工具来辅助分析;那执行 dump 到文件一般使用如下指令:

jmap -dump:format=b,file=dumpFileName pid   # 语法

$ jmap -dump:format=b,file=test-dump.bin 85716  # 举例
Dumping heap to /Users/guolei.sgl/test-dump.bin ...
Heap dump file created
复制代码

对于 dump 下来的文件,可以通过 jprofile 等图形化工具来分析,如下

也可以通过 jhat 查看,操作方式如下:

1、起 http 服务

jhat -port 9300 test-dump.bin
Reading from test-dump.bin...
Dump file created Wed Oct 28 17:54:24 CST 2020
Snapshot read, resolving...
Resolving 1151952 objects...
Chasing references, expect 230 dots......................................................................................................................................................................................................................................
Eliminating duplicate references......................................................................................................................................................................................................................................
Snapshot resolved.
Started HTTP server on port 9300
Server is ready.
复制代码

2、dump 类概要信息

访问 localhost:9300 查看 dump 概要信息

3、class 详情

点击某个类查看详细信息

小结

本文介绍了一些 JDK 自带的一些性能调优监控工具,通过对这些工具的掌握,可以使的我们在实际的开发或者运维中能够快速的去定位和解决一些问题,常见的有 OOM、内存泄漏、线程死锁、CPU 负载高等等;目前社区也有很多好用的工具,例如 Arthasperfma 等。

文章分类
后端
文章标签