JVM问题排查工具整理

作者: 茶还是咖啡 | 来源:发表于2020-03-19 16:09 被阅读0次

JVM问题排查工具整理
8、线上问题排查
jstat、jstack工具初体验
记一次用arthas排查jvm中CPU占用过高问题
JVM问题排查小工具
JVM 优化踩坑记
一次完整的JVM堆外内存泄漏故障排查记录
JDK命令行工具与可视化工具
JVM 问题排查
JVM问题排查

JVM参数类型

运行时JVM参数查看

标准参数

这些参数基本上不会发送改变，相对比较稳定，如：
-help
-server -client
-version -showversion
-cp -classpath
eg：

xxx@192 ~ % java -version
java version "1.8.0_241"
Java(TM) SE Runtime Environment (build 1.8.0_241-b07)
Java HotSpot(TM) 64-Bit Server VM (build 25.241-b07, mixed mode)
xxx@192 ~ % java -showversion
java version "1.8.0_241"
Java(TM) SE Runtime Environment (build 1.8.0_241-b07)
Java HotSpot(TM) 64-Bit Server VM (build 25.241-b07, mixed mode)

X 参数

非标准化参数，各个JVM版本有可能会变。
如：
-Xint：解释执行
-Xcomp：第一次就使用编译成本地代码
-Xmixed：混合模式，JVM自己决定是否编译成本地代码

java 代码是解释执行，但有时会通过jJIT即时编译技术，将java代码转换成本地代码去执行，如果指定-Xint，代表全部进行解释执行，如果执行-Xcomp则第一次使用就编译成本地代码，如果指定-Xmixed，JVM则自己决定何时编译成本地代码。

XX参数

非标准化参数，主要用于JVM调优和Debug

Boolean类型
格式：-XX:[+-]<name> 表示启用或者禁用name属性
比如：
-XX:+UseConcMarkSeepGC
-XX:+UseG1GC
key-value类型
格式：-XX:<name>=<value>表示name属性的值是value
比如：
-XX:MaxGCPauseMillis=500
-XX:GCTimeRatio=19

-Xmx -Xms
-Xms等价于-XX:InitialHeapSize 初始化堆的大小
-Xmx等价于-XX:MaxHeadpSize 最大堆的大小

jstat查看虚拟机统计信息

文档地址：https://docs.oracle.com/javase/8/docs/technotes/tools/unix/jstat.html#BEHHGFAE

jstat可以动态的查看类装载信息，垃圾收集信息以及JIT编译信息

使用方法：

Usage: jstat -help|-options
       jstat -<option> [-t] [-h<lines>] <vmid> [<interval> [<count>]]

Definitions:
  <option>      An option reported by the -options option
  <vmid>        Virtual Machine Identifier. A vmid takes the following form:
                     <lvmid>[@<hostname>[:<port>]]
                Where <lvmid> is the local vm identifier for the target
                Java virtual machine, typically a process id; <hostname> is
                the name of the host running the target Java virtual machine;
                and <port> is the port number for the rmiregistry on the
                target host. See the jvmstat documentation for a more complete
                description of the Virtual Machine Identifier.
  <lines>       Number of samples between header lines.
  <interval>    Sampling interval. The following forms are allowed:
                    <n>["ms"|"s"]
                Where <n> is an integer and the suffix specifies the units as 
                milliseconds("ms") or seconds("s"). The default units are "ms".
  <count>       Number of samples to take before terminating.
  -J<flag>      Pass <flag> directly to the runtime system.

options	说明
-class	类夹加载的信息
-compiler	JIT编译信息
-gc	垃圾回收信息

查看类装载信息

jstat -class  10365 1000 10
Loaded  Bytes     Unloaded  Bytes     Time   
  3517  6738.4        0     0.0       3.55
  3517  6738.4        0     0.0       3.55
  3517  6738.4        0     0.0       3.55
  3517  6738.4        0     0.0       3.55
  3517  6738.4        0     0.0       3.55
  3517  6738.4        0     0.0       3.55
  3517  6738.4        0     0.0       3.55
  3517  6738.4        0     0.0       3.55
  3517  6738.4        0     0.0       3.55
  3517  6738.4        0     0.0       3.55

参数说明：
10365 代表的是进程号
1000 和 10 分别代表间隔1000毫秒进行打印，一共输出10次，如果不写打印当前的类装载信息
输出说明：
Loaded：已加载的类数
Bytes: 加载占用的字节数
Unloaded：卸载的类数
Bytes: 卸载类占用的字节数
Time：执行类加载和卸载操作所花费的时间

查看GC信息

jstat -gc 10365
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
10752.0 10752.0  0.0   4340.5 65536.0  23922.5   175104.0    144.0    17152.0 16426.6 2048.0 1907.5      1    0.004   0      0.000    0.004

参数说明：

参数	说明
SOC、S1C、S0U、S1U	S0和S1的总量与使用量
EC、EU	Eden区的总量与使用量
OC、OU	Old区的总量与使用量
MC、MU	Metaspace的总量与使用量
CCSC、CCSU	压缩类空间总量与使用量
YGC、YGCT	YoungGC的次数与时间
GGC、FGCT	FullGC的次数与时间
GCT	总的GC时间

Java8内存结构划分

java8内存结构划分

java的堆区，主要分为新生代和老年代，新生代中又分为Eden区和S0，S1区，统一时刻，S0和S1区只有一个被使用。
非堆区属于操作系统的本地内存，独立于JVM堆区之外。称为Metaspace，启用对象“短指针”会存在“CCS”，“CodeCache”存放的JIT的代码信息和JNI的代码信息。如果没有开启JIT编译，这块内存是不存在的。

查看JIT编译信息

jstat -compiler 10365
Compiled Failed Invalid   Time   FailedType FailedMethod
    1299      0       0     1.89          0

参数说明

参数	说明
Compiled	执行的编译任务数
Failed	失败的编译任务数
Invalid	无效的编译任务数
Time	执行编译任务所花费的时间
FailedType	上次编译失败的编译类型
FailedMethod	上次编译失败的类名和方法

jmap

此处参考：https://www.jianshu.com/p/7abbb6ef785b

堆内存转储（heap dump）生成工具，可以用来分析某JVM进程的堆内存占用，以及所有对象的概况
用法

Usage:
    jmap [option] <pid>
        (to connect to running process)
    jmap [option] <executable <core>
        (to connect to a core file)
    jmap [option] [server_id@]<remote server IP or hostname>
        (to connect to remote debug server)

where <option> is one of:
    <none>               to print same info as Solaris pmap
    -heap                to print java heap summary
    -histo[:live]        to print histogram of java object heap; if the "live"
                         suboption is specified, only count live objects
    -clstats             to print class loader statistics
    -finalizerinfo       to print information on objects awaiting finalization
    -dump:<dump-options> to dump java heap in hprof binary format
                         dump-options:
                           live         dump only live objects; if not specified,
                                        all objects in the heap are dumped.
                           format=b     binary format
                           file=<file>  dump heap to <file>
                         Example: jmap -dump:live,format=b,file=heap.bin <pid>
    -F                   force. Use with -dump:<dump-options> <pid> or -histo
                         to force a heap dump or histogram when <pid> does not
                         respond. The "live" suboption is not supported
                         in this mode.
    -h | -help           to print this help message
    -J<flag>             to pass <flag> directly to the runtime system

-heap：查看堆配置信息和使用情况

[root@localhost ~]# jmap -heap 18342
Attaching to process ID 18342, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.191-b12

using thread-local object allocation.
Mark Sweep Compact GC

Heap Configuration:
   MinHeapFreeRatio         = 40
   MaxHeapFreeRatio         = 70
   MaxHeapSize              = 33554432 (32.0MB)
   NewSize                  = 11141120 (10.625MB)
   MaxNewSize               = 11141120 (10.625MB)
   OldSize                  = 22413312 (21.375MB)
   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 = 10027008 (9.5625MB)
   used     = 7103016 (6.773963928222656MB)
   free     = 2923992 (2.7885360717773438MB)
   70.83883846507354% used
Eden Space:
   capacity = 8912896 (8.5MB)
   used     = 6630128 (6.3229827880859375MB)
   free     = 2282768 (2.1770172119140625MB)
   74.38803280101104% used
From Space:
   capacity = 1114112 (1.0625MB)
   used     = 472888 (0.45098114013671875MB)
   free     = 641224 (0.6115188598632812MB)
   42.44528377757353% used
To Space:
   capacity = 1114112 (1.0625MB)
   used     = 0 (0.0MB)
   free     = 1114112 (1.0625MB)
   0.0% used
tenured generation:
   capacity = 22413312 (21.375MB)
   used     = 11167688 (10.650337219238281MB)
   free     = 11245624 (10.724662780761719MB)
   49.82613903737207% used

12018 interned Strings occupying 1036416 bytes.

-histo：生成类的实例统计直方图

[root@localhost ~]$ jmap -F -histo 18342 >1.txt
Iterating over heap. This may take a while...
Heap traversal took 11.946 seconds.
[root@localhost ~]$ head -30 1.txt 
Attaching to process ID 18342, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.191-b12
Object Histogram:

num       #instances    #bytes  Class description
--------------------------------------------------------------------------
1:      51188   6866416 char[]
2:      4422    1296216 byte[]
3:      7871    1191696 int[]
4:      43636   1047264 java.lang.String
5:      8724    767712  java.lang.reflect.Method
6:      6509    718600  java.lang.Class
7:      21673   693536  java.util.concurrent.ConcurrentHashMap$Node
8:      7179    380872  java.lang.Object[]
9:      12965   277928  java.lang.Class[]
10:     6719    268760  java.util.LinkedHashMap$Entry
11:     124 243456  java.util.concurrent.ConcurrentHashMap$Node[]
12:     2729    239560  java.util.HashMap$Node[]
13:     14238   227808  java.lang.Object
14:     6617    211744  java.util.HashMap$Node
15:     3098    173488  java.util.LinkedHashMap
16:     2404    153856  java.net.URL
17:     1025    123000  org.springframework.boot.loader.jar.JarEntry
18:     1631    117432  java.lang.reflect.Field
19:     2019    96912   org.springframework.util.ConcurrentReferenceHashMap$SoftEntryReference
20:     1064    85120   java.lang.reflect.Constructor
21:     1299    67176   java.lang.reflect.Method[]
22:     1120    62720   java.lang.invoke.MemberName

打印的结果有实例数、占用内存总大小和类的全限定名，并按占用内存降序排序。如果在-histo后面加上:live开关的话，表示只统计存活的对象，即在统计之前会触发一次Full GC。

特别注意，遍历堆并生成直方图的过程中，目标JVM都是stop-the-world的，所以对于较大的堆或者生产环境上的程序，要谨慎执行。如果目标JVM无响应，就加上-F参数强制执行之（同jstack），此时:live开关无效化。

-dump：生成堆转储快照文件

[root@localhost ~]$ jmap -dump:live,format=b,file=dump_18342.hprof 18342
Dumping heap to /root/dump_18342.hprof ...
Heap dump file created

生成的二进制快照文件可以使用jhat、MAT、VisualVM等带有分析heap dump功能的工具查看详情，
比如通过保留大小（retained size）指标来观察有哪些对象在引用大对象。
:live开关和-F参数的功能与-histo选项下相同，并且生成快照文件的过程同样会stop-the-world。

-finalizerinfo：输出等待finalize的对象数

[root@localhost ~]$ jmap -finalizerinfo 18342
Attaching to process ID 18342, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.191-b12
Number of objects pending for finalization: 0

jmap实战内存溢出

构造一个堆内存溢出

@RestController
public class MemoryController {

    private List<User> userList;

    @GetMapping("heap")
    public Object heap(){
        userList = new LinkedList<>();
        while (true){
            userList.add(new User());
        }
    }
}

指定jvm启动参数-Xms和-Mmx都是32m

浏览器访问，控制台会出现内存溢出的情况

Exception in thread "http-nio-8080-exec-1" java.lang.OutOfMemoryError: GC overhead limit exceeded
Exception in thread "http-nio-8080-exec-2" java.lang.OutOfMemoryError: GC overhead limit exceeded
Exception in thread "SpringContextShutdownHook" org.springframework.context.ApplicationContextException: Failed to unregister LiveBeansView MBean; nested exception is java.lang.OutOfMemoryError: GC overhead limit exceeded
    at org.springframework.context.support.LiveBeansView.unregisterApplicationContext(LiveBeansView.java:103)
    at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1008)
    at org.springframework.context.support.AbstractApplicationContext$1.run(AbstractApplicationContext.java:948)
Caused by: java.lang.OutOfMemoryError: GC overhead limit exceeded

导出内存映像文件

内存溢出自动导出

# 开启内存溢出自动导出
-XX:+HeapDumpOnOutOfMemoryError
# 指定导出路径
-XX:+HeapDumpPath=./

使用jmap命令手动导出

[root@localhost ~]$ jmap -dump:live,format=b,file=dump_18342.hprof 18342
Dumping heap to /root/dump_18342.hprof ...
Heap dump file created

导入jdk自带的jvisualvm

jstack实战死循环与死锁

jstack用法
参考：https://www.jianshu.com/p/99562e9391b5

[root@localhost ~]$ jstack -help
Usage:
    jstack [-l] <pid>
        (to connect to running process)
    jstack -F [-m] [-l] <pid>
        (to connect to a hung process)
    jstack [-m] [-l] <executable> <core>
        (to connect to a core file)
    jstack [-m] [-l] [server_id@]<remote server IP or hostname>
        (to connect to a remote debug server)

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

线程状态切换图

线程状态切换

打印线程快照

这里只是一部分

[root@localhost ~]$ jstack 18809
2020-03-07 14:40:32
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.191-b12 mixed mode):

"Attach Listener" #27 daemon prio=9 os_prio=0 tid=0x00007f3c88001800 nid=0x49a8 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"DestroyJavaVM" #26 prio=5 os_prio=0 tid=0x00007f3cb4009800 nid=0x497a waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"http-nio-8080-Acceptor" #24 daemon prio=5 os_prio=0 tid=0x00007f3cb48cf000 nid=0x4993 runnable [0x00007f3ca09dd000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
    at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:422)
    at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:250)
    - locked <0x00000000fe2a87c8> (a java.lang.Object)
    at org.apache.tomcat.util.net.NioEndpoint.serverSocketAccept(NioEndpoint.java:466)
    at org.apache.tomcat.util.net.NioEndpoint.serverSocketAccept(NioEndpoint.java:72)
    at org.apache.tomcat.util.net.Acceptor.run(Acceptor.java:95)
    at java.lang.Thread.run(Thread.java:748)

"http-nio-8080-ClientPoller" #23 daemon prio=5 os_prio=0 tid=0x00007f3cb49c4000 nid=0x4992 runnable [0x00007f3ca0ade000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000000fe454e00> (a sun.nio.ch.Util$3)
    - locked <0x00000000fe454df0> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000000fe454cd8> (a sun.nio.ch.EPollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:709)
    at java.lang.Thread.run(Thread.java:748)

死锁检测

构建一个死锁

public class DeadLockDemo {
    private static final Object lock1 = new Object();
    private static final Object lock2 = new Object();

    public static void main(String[] args) throws Exception {
        new Thread(() -> {
            for (int i = 0; i < 100; i++) {
                synchronized (lock1) {
                    System.out.println("thread1 synchronized lock1");
                    synchronized (lock2) {
                        System.out.println("thread1 synchronized lock2");
                    }
                }
            }
        }, "thread1").start();

        new Thread(() -> {
            for (int i = 0; i < 100; i++) {
                synchronized (lock2) {
                    System.out.println("thread2 synchronized lock2");
                    synchronized (lock1) {
                        System.out.println("thread2 synchronized lock1");
                    }
                }
            }
        }, "thread2").start();
    }
}

程序只会打印一部分就停止打印发生死锁：

thread1 synchronized lock1
thread1 synchronized lock2
thread1 synchronized lock1
thread2 synchronized lock2

使用jstack打印线程快照,会出现死锁相关信息

...
JNI global references: 320


Found one Java-level deadlock:
=============================
"thread2":
  waiting to lock monitor 0x00007fbc37805968 (object 0x000000076acd1f90, a java.lang.Object),
  which is held by "thread1"
"thread1":
  waiting to lock monitor 0x00007fbc37806eb8 (object 0x000000076acd1fa0, a java.lang.Object),
  which is held by "thread2"

Java stack information for the threads listed above:
===================================================
"thread2":
    at org.yuwb.customer.controller.DeadLockDemo.lambda$main$1(DeadLockDemo.java:33)
    - waiting to lock <0x000000076acd1f90> (a java.lang.Object)
    - locked <0x000000076acd1fa0> (a java.lang.Object)
    at org.yuwb.customer.controller.DeadLockDemo$$Lambda$2/1134517053.run(Unknown Source)
    at java.lang.Thread.run(Thread.java:748)
"thread1":
    at org.yuwb.customer.controller.DeadLockDemo.lambda$main$0(DeadLockDemo.java:22)
    - waiting to lock <0x000000076acd1fa0> (a java.lang.Object)
    - locked <0x000000076acd1f90> (a java.lang.Object)
    at org.yuwb.customer.controller.DeadLockDemo$$Lambda$1/1237514926.run(Unknown Source)
    at java.lang.Thread.run(Thread.java:748)

Found 1 deadlock.

用jstack诊断高CPU占用

构建一个死循环

public class DeadLockDemo {
private static final Object lock = new Object();

    static class InfiniteLoopRunnable implements Runnable {
        @Override
        public void run() {
            synchronized (lock) {
                long l = 0;
                while (true) {
                    l++;
                }
            }
        }
    }

    public static void main(String[] args) throws Exception {
        new Thread(new InfiniteLoopRunnable(), "thread1").start();
        new Thread(new InfiniteLoopRunnable(), "thread2").start();
    }
}

使用top命令查看进程信息

查看该进程他所有的线程信息，找到占用CPU最高线程

$ top -Hp 12251

导出线程快照

jstack 12251> 12251.log

使用jstack导出线程快照到文件中。由于线程ID是十六进制表示的，所以我们要将线程ID转换成十六进制再grep。

cat 12251.log | grep -C 10 `printf "%x" 12266`

参考文档

https://docs.oracle.com/javase/8/docs/technotes/tools/unix/
https://www.jianshu.com/p/7abbb6ef785b

JVM问题排查工具整理
JVM参数类型运行时JVM参数查看标准参数这些参数基本上不会发送改变，相对比较稳定，如：-help-serv...
8、线上问题排查
文章主要列出了常见的排查工具，也有部分线上问题案例； JVM 问题排查 JDK工具包 javap 反编译工具jav...
jstat、jstack工具初体验
概要 JVM排查工具的实践 permG与方法区 permG与Metaspace 记第一次使用jvm排查工具实践的过...
记一次用arthas排查jvm中CPU占用过高问题
记一次使用 arthas 排查jvm中CPU占用过高问题。这工具屌爆了碾压我目前使用的全部JVM工具。安装小...
JVM问题排查小工具
注：最近一直想出一篇介绍JVM底层函数调用的博客，奈何越写越多，现在还没写完，先来个简单的安慰下我受伤的心灵滴滴...
JVM 优化踩坑记
本文记录了服务 JVM 优化的过程与思路，有对 JVM GC 原理以及对问题排查方向和工具的介绍，也有走弯路和踩坑...
一次完整的JVM堆外内存泄漏故障排查记录
前言记录一次线上JVM堆外内存泄漏问题的排查过程与思路，其中夹带一些JVM内存分配机制以及常用的JVM问题排查指...
JDK命令行工具与可视化工具
jdk/bin目录中提供了很多jdk工具，在查看JVM运行状态以及排查问题时需要结合Linux命令并结合这些工具进...
JVM 问题排查
CPU使用率高找出使用率高的进程的pid 找出使用率高的线程tpid 查看使用率高的线程当前在干什么 GC问题 ...
JVM问题排查
一、线上CPU飚高、死锁等排查基本步骤： 1、top 记录CPU使用率最高的JAVA进程PID 2、top -H...