详解 Java 线上问题排查思路

宫水三叶的刷题日记 • 2023-01-02 • 云技术社区 • 277 阅读

前言

针对各种常见的线上问题，梳理下排查思路。

测试环境搭建

既然要模拟排查线上问题，就不能使用本地环境。

至少是个 Linux 操作系统，最好还是个纯粹的 Java 环境。

所以直接使用 docker 搭建最为方便：

  1. 打开一个窗口（窗口 A），拉取 openjdk 镜像：
docker pull openjdk:8-jdk
  1. 启动容器，挂载一个数据卷，方便我们本地修改代码，然后在容器内运行：
docker run -it -v your/path/floder/:/folder/ openjdk:8-jdk /bin/bash
  1. 在挂载数据卷下，编写 Main.java 文件（之后模拟的线上问题代码会编写在此文件），然后在容器内编译执行：
cd folder/
javac Main.java
java -Xms50M -Xmx50M -XX:+PrintGC Main
  1. 打开另外一个窗口（窗口 B），进入容器，用于监控容器状况：
docker exec -it container_id /bin/bash

CPU 问题

导致线上 CPU 吃满通常是线程过多或者线程“死锁”，一般而言后者的可能性更大。

因为通常线程数量会由线程池管理，一般不会超过我们设定的最大值；而线程“死锁”通常是人为代码问题，某个获得锁的线程没有释放锁，导致其他线程一直处于 Waiting 状态（或者 CAS 自旋状态）。

模拟线程过多导致的 CPU 问题

修改 Main.java 文件如下，并在窗口 A 重新编译运行 Main ：

public class Main {
    public static void main(String[] args) {
        final int count = 1000;
        ExecutorService threadPool = Executors.newFixedThreadPool(count);
        for (int i = 0; i < count; i++) {
            threadPool.submit(new Runnable() {
                @Override
                public void run() {
                    for (;;) {
                        try {
                            // 模拟耗时操作
                            Thread.sleep(50);
                        } catch (InterruptedException e) {
                            e.printStackTrace();
                        }
                    }
                }
            });
        }
    }
}

定位线程过多导致的 CPU 问题

  1. top 命令：查看哪个进程占用 CPU 过高。定位到 pid （7610）

  1. top -Hp pid 命令：查看问题进程中的线程情况。可以看到 Threads: 1012 total, 0 running, 1012 sleeping, 0 stopped, 0 zombie ：

可见 CPU 过高原因是过多线程正在处于 SLEEPING 状态。而且每个线程的 CPU 占比和内存占比都差不多，我们随便找一个线程进行分析。PID 为 7622 的线程。

  1. jstack pid | grep nid -C10 ：查看对应的线程前后 10 行的状态信息（注意，先使用 `printf '%x\\n' nid 或者其他方式，将十进制的 nid 转换为十六进制的 nid）:

打印出的线程堆栈可以发现是在 Main.java 中的第 19 当导致的线程进入 SLEEPING 状态，其他的导致线程 TIMED_WAITING 甚至 BLOCKED 的原因也可以通过分析堆栈得出原因。这里的堆栈分析方法和我们常规的分析方法是一样的。

解决方案

解决线程过多问题，首先不能使用由 Executors 工具类提供的 newCachedThreadPool() 方法，因为查看源码就可以知道该方法所指定 maximumPoolSize 参数为 Integer.MAX_VALUE 。

也就是在高并发场景下，会不断的创建线程。会引发线程过多，导致 CPU 吃满问题。

事实上，除了 newCachedThreadPool() 以外，其他的如 newFixedThreadPool 、newSingleThreadExecutor 也不应该在生产上使用，因为这些内置线程池都是使用 LinkedBlockingQueue 作为任务队列，LinkedBlockingQueue属于“无界”队列，在高并发场景下会导致 OOM 。

所以使用线程池的最佳实践是自己调用 ThreadPoolExecutor 的构造方法：

  1. 指定合适的 maximumPoolSize 参数，防止过多的线程创建；
  2. 使用 ArrayBlockingQueue 等“有界”队列，防止 OOM；
  3. 自定义 ThreadFactory （为了给线程起名字），方便以后的 GC 日志排查。

通过这一个小例子，可以发现当线上出现 CPU 过高问题时，可以先通过 top 命令定位到问题进程的 id（如果是微服务，即当前服务器对应的 java 进程很少，百分百就确定是某个应用时，也可以通过 jps 直接取得进程 id ）；

然后使用 top -Hp pid 查看问题进程中的线程 CPU 占用情况，分析是某个线程占用 CPU 过高还是线程过多导致，定位线程 nid，并转换为十六进制；

使用 jstack pid | grep nid -C10 命令查看与 nid 对应的线程的状态信息和该线程的堆栈信息（主要是自身程序代码的堆栈信息），也可以使用 jstack -l nid 命令查看更详细的线程堆栈信息（主要是 JDK 方法调用的堆栈信息）。

模拟线程“锁等待”导致的 CPU 问题

修改 Main.java 文件如下，并在窗口 A 重新编译运行 Main ：

public class Main {
    public static void main(String[] args) {
        final int count = 10;
        final ReentrantLock lock = new ReentrantLock();
        ExecutorService threadPool = Executors.newFixedThreadPool(count, new ThreadFactory() {
                    @Override
                    public Thread newThread(Runnable r) {
                        Thread thread = new Thread(r);
                        thread.setName("PETERXX_PROJECT_POOL_" + UUID.randomUUID().toString());
                        return thread;
                    }
                }
        );
        for (int i = 0; i < count; i++) {
            threadPool.submit(new Runnable() {
                @Override
                public void run() {
                    for (; ; ) {
                        lock.lock();
                        for (int j = 0; j < 100_0000; j++) {

                        }
                        lock.unlock();
                    }
                }
            });
        }
    }
}

这次虽然只起 10 个线程，每个线程都是「循环执行获得锁操作，计数 100w 次，释放锁的过程」。

由于使用的 ReentrantLock（CAS），所以每次除成功获取锁的线程以外，其他线程都在自旋（内部也是使用 for(;;) 的方式），所以导致 CPU 过高。

另外我们通过自定义 ThreadFactory 的方式为线程池中的线程进行命名（主要是为了之后的方面定位线程），我们尝试使用前面总结的思路来定位问题。

定位线程“锁等待”导致的 CPU 问题

  1. 可以使用 top 命令来定位问题进程的 pid ，但由于我们使用的纯粹的 docker 环境，也只运行了一个 java 进程，我们这里直接使用 jps 命令来定位进程：
root@436f6af3feeb:/# jps
8992 Jps
8925 Main
  1. 还是使用 top -Hp pid 的方式，查看线程占用情况，发现只有三个线程处于 RUNNABLE 状态，其余线程处于 SLEEPING 状态。而且线程占用 CPU 资源情况不一，CPU 占用时高时低，这时候其实就相当于没法定位到具体某个线程的 id 了：

  1. 由于这次没有特定的线程 id ，可以直接执行 jstack pid 指令来大概看一眼各线程的状态（下面输出进行了部分删减）：
root@436f6af3feeb:/# jstack 8925
...
"PETERXX_PROJECT_POOL_31d60b05-41e9-4100-9068-93ed5edc2ab5" #17 prio=5 os_prio=0 tid=0x00007fa42810c800 nid=0x2489 waiting on condition [0x00007fa4125c7000]
   java.lang.Thread.State: WAITING (parking)
 at sun.misc.Unsafe.park(Native Method)
 - parking to wait for  <0x00000000fefdbca8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
 at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
 at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
 at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
 at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
 at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
 at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
 at Main$2.run(Main.java:26)
 at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
 at java.util.concurrent.FutureTask.run(FutureTask.java:266)
 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
 at java.lang.Thread.run(Thread.java:748)

"PETERXX_PROJECT_POOL_efb3edf0-886a-4abb-b6fe-cf3dbdcb31b4" #16 prio=5 os_prio=0 tid=0x00007fa42810a800 nid=0x2488 runnable [0x00007fa4126c8000]
   java.lang.Thread.State: WAITING (parking)
 at sun.misc.Unsafe.park(Native Method)
 - parking to wait for  <0x00000000fefdbca8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
 at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
 at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
 at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
 at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
 at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
 at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
 at Main$2.run(Main.java:26)
 at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
 at java.util.concurrent.FutureTask.run(FutureTask.java:266)
 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
 at java.lang.Thread.run(Thread.java:748)
...
"PETERXX_PROJECT_POOL_739c1a07-46f6-4f4f-9ecf-8373fb2c0e70" #13 prio=5 os_prio=0 tid=0x00007fa428105800 nid=0x2485 runnable [0x00007fa4129cb000]
   java.lang.Thread.State: RUNNABLE
 at Main$2.run(Main.java:30)
 at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
 at java.util.concurrent.FutureTask.run(FutureTask.java:266)
 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
 at java.lang.Thread.run(Thread.java:748)
 
"Service Thread" #7 daemon prio=9 os_prio=0 tid=0x00007fa4280ba800 nid=0x247e runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
...

可以发现有较多线程处于 WAITING 状态，只有较少数线程处于 RUNNABLE 状态。

由于之前我们对线程进行了命名，可以使用 jstack pid | grep PETERXX_PROJECT_POOL 对线名称进行过滤：

root@436f6af3feeb:/# jstack 8925 | grep PETERXX_PROJECT_POOL
"PETERXX_PROJECT_POOL_31d60b05-41e9-4100-9068-93ed5edc2ab5" #17 prio=5 os_prio=0 tid=0x00007fa42810c800 nid=0x2489 runnable [0x00007fa4125c7000]
"PETERXX_PROJECT_POOL_efb3edf0-886a-4abb-b6fe-cf3dbdcb31b4" #16 prio=5 os_prio=0 tid=0x00007fa42810a800 nid=0x2488 waiting on condition [0x00007fa4126c8000]
"PETERXX_PROJECT_POOL_037b173d-f28e-4a80-b98c-7fb875882f73" #15 prio=5 os_prio=0 tid=0x00007fa428109000 nid=0x2487 waiting on condition [0x00007fa4127c9000]
"PETERXX_PROJECT_POOL_efdc4d85-5735-4a04-bdd3-a47205539040" #14 prio=5 os_prio=0 tid=0x00007fa428107800 nid=0x2486 runnable [0x00007fa4128ca000]
"PETERXX_PROJECT_POOL_739c1a07-46f6-4f4f-9ecf-8373fb2c0e70" #13 prio=5 os_prio=0 tid=0x00007fa428105800 nid=0x2485 waiting on condition [0x00007fa4129cb000]
"PETERXX_PROJECT_POOL_fcc7d04c-a5f2-4be3-920a-ddc36fbfd9b1" #12 prio=5 os_prio=0 tid=0x00007fa428104000 nid=0x2484 runnable [0x00007fa412acc000]
"PETERXX_PROJECT_POOL_b17d1f19-bbf3-43cb-96a5-27eef6c46f0d" #11 prio=5 os_prio=0 tid=0x00007fa428102000 nid=0x2483 waiting on condition [0x00007fa412bcd000]
"PETERXX_PROJECT_POOL_42f75df3-c9cb-4031-bad5-670079e68b34" #10 prio=5 os_prio=0 tid=0x00007fa428100800 nid=0x2482 waiting on condition [0x00007fa412cce000]
"PETERXX_PROJECT_POOL_811769a4-ade2-4113-b644-235fb1d7c80f" #9 prio=5 os_prio=0 tid=0x00007fa4280ff000 nid=0x2481 waiting on condition [0x00007fa412dcf000]
"PETERXX_PROJECT_POOL_def0c7fd-c171-4356-9029-52ec793b3a37" #8 prio=5 os_prio=0 tid=0x00007fa4280fd000 nid=0x2480 waiting on condition [0x00007fa412ed0000]

可以看到只有少数线程处于 RUNNABLE 状态，其余都是处于 WAITING 状态。基本上可以判断是锁等待导致的。

这时候我们可以找一个处于 RUNNABLE 状态的 nid 查看堆栈：

root@436f6af3feeb:/# jstack 8925 | grep 0x2489 -C10
"PETERXX_PROJECT_POOL_31d60b05-41e9-4100-9068-93ed5edc2ab5" #17 prio=5 os_prio=0 tid=0x00007fa42810c800 nid=0x2489 runnable [0x00007fa4125c7000]
   java.lang.Thread.State: RUNNABLE
 at Main$2.run(Main.java:26)
 at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
 at java.util.concurrent.FutureTask.run(FutureTask.java:266)
 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
 at java.lang.Thread.run(Thread.java:748)
...

找一个处于 WAITING 状态的 nid 查看堆栈：

root@436f6af3feeb:/# jstack 9332 | grep 0x2483 -C10
"PETERXX_PROJECT_POOL_b17d1f19-bbf3-43cb-96a5-27eef6c46f0d" #11 prio=5 os_prio=0 tid=0x00007fa428102000 nid=0x2483 waiting on condition [0x00007fa412bcd000]
   java.lang.Thread.State: WAITING (parking)
 at sun.misc.Unsafe.park(Native Method)
 - parking to wait for  <0x00000000ffc00c18> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
 at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
 at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
 at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
 at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
 at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
 at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
 at Main$2.run(Main.java:26)
...

可以看到处于 WAITING 的线程在 Main.java 的 26 行开始等待地址为 <0x00000000ffc00c18> 的 ReentrantLock$NonfairSync 锁对象，而处于 RUNNABLE 状态的线程是在 Main.java 的 26 行开始执行，到这里基本可以确定是哪个类的哪个方法用到的锁没有及时释放导致过多线程处于“锁等待”状态，最终导致 CPU 过高问题。

解决方案

因为“锁等待”导致 CPU 过高问题，一般是因为使用的 CAS 锁（尝试获取 CAS 锁的进程会在死循环中不断请求锁），同时占用锁资源的线程没有及时把锁释放（占用锁资源的线程的任务耗时过长）。

针对这种情况可以将 CAS 锁替换为 synchronized ，因为 synchronized 存在“锁升级”过程，会将占用 CPU 资源的轻量级锁升级为不占用 CPU 资源的重量级锁。

模拟频繁 GC 导致的 CPU 问题

修改 Main.java 文件如下，并在窗口 A 重新编译运行 Main ：

public class Main {
    public static void main(String[] args) {
        for (int i = 0; i < 10; i++) {
            new Thread(new Runnable() {
                @Override
                public void run() {
                    for (;;) {
                        WeakReference<byte[]> weakReference = new WeakReference<>(new byte[1024 * 1024]);
                    }
                }
            }).start();
        }
    }
}

一个死循环，会不断的在堆上创建大小为 1M 的对象，同时由于使用的弱引用，可以确保达到「堆空间不断被占用，触发 GC，而 GC 后堆内存又能够被释放（即堆内存占用会持续升高，但不会导致 OOM）的效果」。

定位频繁 GC 导致的 CPU 问题

其实如果是 GC 导致的 CPU 问题，是很好定位的。按照我们之前的思路：先使用 top 定位到问题进程、 top -Hp pid 查看问题进程中的线程情况，如果是频繁 GC 导致的 CPU 问题，到这一步应该会看到 GC 线程会吃满了 CPU：

解决方案

如果是 GC 导致的 CPU 问题，一般是通过分析堆内存 dump 文件进行分析。

换句话说「频繁 GC 导致的 CPU 问题，通常是先引发的 OOM 内存问题导致的，解决了根本的内存问题，也就解决了频繁 GC 导致的 CPU 问题。」

内存问题

要解决内存问题，需要先想办法查看进程内存使用情况。

通常在生产上有两个参数是必须开启的：-XX:+HeapDumpAfterFullGC & -XX:+HeapDumpOnOutOfMemoryError，可以确保系统发生 FGC 和 OOM 的时候将 Java 堆的状况记录下来，便于分析。

在线定位（原生命令）

  • jstat -gc pid

查看 pid 对应的 Java 进程当前情况下的 GC 情况：

$ jstat -gc pid
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT
1024.0 1024.0  0.0    0.0    8704.0   4368.9   22016.0      0.0     4480.0 778.9  384.0   74.6       0    0.000   0      0.000    0.000

S0C、S1C、S0U、S1U ：两个 Survivor 区的容量和使用量

EC、EU ：Eden 区的容量和使用量

MC、MU ：方法区的容量和使用量

YGC、YGCT ：YGC 的次数和耗时

FGC、FGCT ：FGC 的次数和耗时

GCT ：GC 的总耗时

  • jinfo

jinfo -flags pid ：查看  pid 对应的 JVM 的参数

jinfo -sysprops pid ：查看当前系统参数包括 -D 设置的参数

$ jinfo -flag GCLogFileSize pid
-XX:GCLogFileSize=8192

  • jmap
  1. jmap pid ：查看进程中的内存映像信息。将会打印目标虚拟机中加载的每个共享对象的起始地址、映射大小以及共享文件的路径全称。
  2. jmap -heap pid ：显示 Java 堆详细信息。打印堆的摘要信息，包括 GC 算法，堆配置信息和各个分代的使用情况。
$ jmap -heap pid
Attaching to process ID pid, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.131-b11

## 使用的 GC 回收器
using thread-local object allocation.
Parallel GC with 10 thread(s)

## 当前 Heap 配置信息
Heap Configuration:
   MinHeapFreeRatio         = 0
   MaxHeapFreeRatio         = 100
   MaxHeapSize              = 4294967296 (4096.0MB)
   NewSize                  = 89128960 (85.0MB)
   MaxNewSize               = 1431306240 (1365.0MB)
   OldSize                  = 179306496 (171.0MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

## 当前堆内存使用情况（各个分代的总容量/已使用/空闲）
Heap Usage:
PS Young Generation
Eden Space:
   capacity = 67108864 (64.0MB)
   used     = 40373512 (38.50318145751953MB)
   free     = 26735352 (25.49681854248047MB)
   60.16122102737427% used
From Space:
   capacity = 11010048 (10.5MB)
   used     = 1277952 (1.21875MB)
   free     = 9732096 (9.28125MB)
   11.607142857142858% used
To Space:
   capacity = 11010048 (10.5MB)
   used     = 0 (0.0MB)
   free     = 11010048 (10.5MB)
   0.0% used
PS Old Generation
   capacity = 179306496 (171.0MB)
   used     = 8192 (0.0078125MB)
   free     = 179298304 (170.9921875MB)
   0.004568713450292397% used

1256 interned Strings occupying 87960 bytes.
  1. jmap -histo pid ：显示 Java 堆中的对象的统计信息。包括每个类的对象数量、所占内存大小等。可配合管道使用
$ jmap -histo pid | head -20

## 编号   实例数量            占用大小  类名
 num     #instances         #bytes  class name
----------------------------------------------
   1:           697         544360  [I
   2:          3480         274920  [C
   3:           322         119400  [B
   4:           629          71848  java.lang.Class
   5:          2605          62520  java.lang.String
   6:           876          47568  [Ljava.lang.Object;
   7:           130           9360  java.lang.reflect.Field
...
  1. jmap -clstats pid ：打印类加载器信息
$ jmap -clstats pid
Attaching to process ID 77pid221, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.131-b11
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 加载器/ Ext 拓展加载器 / APP 加载器
<bootstrap> 566 1151677   null   live <internal>
0x00000006c67956a0 20 63212 0x00000006c679f210 dead sun/misc/Launcher$AppClassLoader@0x00000007c000f6a0
0x00000006c679f210 0 0   null   dead sun/misc/Launcher$ExtClassLoader@0x00000007c000fa48

total = 3 586 1214889     N/A     alive=1, dead=2     N/A
  1. jmap -finalizerinfo pid ：打印等待 GC 的对象的信息
$ jmap -clstats pid
Attaching to process ID pid, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.131-b11
Number of objects pending for finalization: 0
  1. jmap -dump:live,format=b,file=filename pid ：将 pid 对应的 Java 进程中的内存使用情况以 .hprof 文件形式保存到本地，方便我们本地分析。

在线定位（Arthas 工具）

Arthas 是阿里开源的 Java 诊断工具。Arthas 还提供了在线工具学习工具，帮助快速上手。

下面记录一下 Arthas 的常用功能：

在开始之前，先下载 arthas-boot.jar 包，直接通过 java -jar 命令启动，然后会让列出所有正在运行的 java 进程，让用户选择需要监控的进程，之后会进入 Arthas 的操作界面。

  • dashboard 命令

在操作界面输入 dashboard 命令，可以看到所监控的进程的所有线程信息（线程 ID、名称、状态、占用 CPU 情况、占用内存情况、是否为守护线程等等）、内存信息（堆内存、Eden 区、Survivor 区、老年代、方法区）、以及机器情况：

  • sysporp / sysenv 命令

通过 sysporp 命令可以查看所有的 System Properties 信息。

通过 sysenv 命令可以查看所有的环境变量信息。

  • JVM 命令

查看当前的进程使用的 JVM 参数。

  • thread 命令

在知道了线程 id 之后，可以通过 thread thread_id 的方式查看某个线程正在执行的堆栈信息。

例如 thread 1 可以查看主线程的堆栈信息：

$ thread 1
"main" Id=1 TIMED_WAITING
    at java.lang.Thread.sleep(Native Method)
    at java.lang.Thread.sleep(Thread.java:340)
    at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
    at demo.MathGame.main(MathGame.java:17)
  • sc 命令

通过 sc 命令可以查看已经加载过的类的信息：

$ sc -d *MathGame
 class-info        demo.MathGame
 code-source       /arthas-demo.jar
 name              demo.MathGame
 isInterface       false
 isAnnotation      false
 isEnum            false
 isAnonymousClass  false
 isArray           false
 isLocalClass      false
 isMemberClass     false
 isPrimitive       false
 isSynthetic       false
 simple-name       MathGame
 modifier          public
 annotation
 interfaces
 super-class       +-java.lang.Object
 class-loader      +-sun.misc.Launcher$AppClassLoader@70dea4e
                     +-sun.misc.Launcher$ExtClassLoader@71b5ca3a
 classLoaderHash   70dea4e
  • sm 命令

通过 sm 类名的方式可以获取类的所有函数，添加 -d 可以获取详细的函数信息，也可以指定查看某个函数：

$ sm java.math.RoundingMode
java.math.RoundingMode <init>(Ljava/lang/String;II)Vjava.math.RoundingMode values()[Ljava/math/RoundingMode;
java.math.RoundingMode valueOf(I)Ljava/math/RoundingMode;
java.math.RoundingMode valueOf(Ljava/lang/String;)Ljava/math/RoundingMode;

$ sm -d java.math.RoundingMode
 declaring-class   java.math.RoundingMode
 constructor-name  <init>
 modifier          private
 annotation
 parameters        java.lang.String
                   int
                   int
 exceptions
 classLoaderHash   null
 
 declaring-class  java.math.RoundingMode
 method-name      values
 modifier         public,static
 annotation
 parameters
 return           java.math.RoundingMode[]
 exceptions
 classLoaderHash  null
 ...
 
$ sm -d java.math.RoundingMode <init>
 declaring-class   java.math.RoundingMode
 constructor-name  <init>
 modifier          private
 annotation
 parameters        java.lang.String
                   int
                   int
 exceptions
 classLoaderHash   null
  • jad 命令

通过 jad 命令可以进行反编译代码，该功能可以帮助我们查看动态代理生成了什么样的类（例如先通过 sc + 通配的方式定位到某个类，再通过 jad 命令反编译得出该类的代码）：

$ jad demo.MathGame
// 省略...
  • watch 命令

通过 watch 命令可以查看当前函数的参数/返回值/异常信息：

$ watch demo.MathGame primeFactors returnObj
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 42 ms, listenerId: 2
ts=2019-12-14 06:06:25; [cost=0.1876ms] result=null
ts=2019-12-14 06:06:26; [cost=0.1316ms] result=@ArrayList[
    @Integer[3],
    @Integer[173],
    @Integer[307],
]
...
  • ognl 命令

用于动态执行代码，在当前线程环境中执行代码：

$ ognl '@java.lang.System@out.println("hello ognl")'
  • redefine 命令

使用 redefine /path/xxx.class 的方式，能重新加载编译好的类。通常可以很方便的实现一些热修复。其实和 IDEA 中 tomcat 的热部署原理一样，就是用 ClasssLoader 重新 load 一遍修改的类。

事后分析（jhat 命令）

对于生产系统，其实能够进行在线定位的机会并不多。

主要是因为一直对发生问题的机器采用在线定位的手段的话，会影响该机器的业务性能；如果将该机器和集群隔离开来再进行在线定位的话，流量下去之后往往问题也消失了。

一般对于线上问题，都是采用这样的步骤：

  1. 先将机器和集群隔离开来
  2. 马上调用 jmap -dump 命令将 Java 堆的现场情况保存下来
  3. 对问题机器中的进程进行重启，恢复上线
  4. 将保存下来的 dump 文件导到本地进行分析

可直接使用 jhat [options] heap-dump-file 命令对 heap dump file 进行分析，其中 Options 参数有：

  • -stack ：false | true。是否跟踪对象分配调用栈，默认值为 true。
  • -refs ：false | true。是否跟踪对象引用，默认值为 true。
  • -port ：jhat HTTP server 的端口号，默认值 7000。
  • -exclude ：文件路径。指定对象查询时需要排除的数据成员列表文件。
  • -baseline ：文件路径。指定一个基准堆转储，在两个 heap dumps 中有相同 object ID 的对象会被标记为不是新的。
  • -debug ：debug 级别，值越大则表示输出更详细的 debug 信息。默认为 0 。
$ jhat heapdump.hprof
Snapshot read, resolving...
Resolving 447484 objects...
Chasing references, expect 89 dots ......................
Eliminating duplicate references ......................
Snapshot resolved.
Started HTTP server on port 7000
Server is ready.

然后访问本地的 7000 的端口，是一个包含 Java 堆信息的分析网页：

  • Package <Default Package> 中包含了我们自己写的包下的类的使用情况。
  • All classes including platform ：所有的类，包含平台启动创建的类
  • Show all members of the rootset ：所有根对象可以连接到的成员，也就是不会被 GC 回收的对象
  • Show instance counts for all classes (including platform) |(excluding platform) 【重要】：查看什么类有多少实例数量（包含平台的 | 不包含平台的）
  • Show heap histogram 【重要】：以列表的形式展示什么类有多少实例数量，占用了多少内存
  • Finalizer Summary ：等待被调用 finalize() 方法的对象，在对象被 GC 回收前，会被调用一次 finalize() 方法（可在方法中重新将该对象和 GC Roots 对象进行关联，实现对象重生）。
  • Object Query Language (OQL) query 【重要】：使用 OQL （类似 SQL）对堆内存信息进行过滤查询

事后分析（Java VisualVM 工具）

在 Mac 系统下，需要在 IDEA 中安装  VisualVM Launcher 插件并配置相关路径，然后装入 dump 文件。

通过可视化界面查看 dump 文件中记录所使用的类：

以及每个类有多少实例对象（以 500 个为单位进行显示）：

仅仅是这两个界面，基本上我们就能大概了解到 dump 文件都记录了什么内容，以及是哪些类创建了较多实例，占用了较大的内存。

Java VisualVM 除了能分析 dump 文件以外，还能进行实时的可视化监控分析。但使用 Java VisualVM 会占用较多资源，所以一般线上环境中不会使用，实在要在线定位问题的话，生产上通常选择前面说到的 Arthas + 原生命令（主要是 jmap 命令）的方式进行。

虽然在生产上使用有性能问题，但在上线前的测试环境压测，使用 Java VisualVM 进行监控还是十分方便：

  • 监控 CPU 、堆、类加载情况和线程数量：

  • 查看线程调度情况：

本站文章资源均来源自网络，除非特别声明，否则均不代表站方观点，并仅供查阅，不作为任何参考依据！
如有侵权请及时跟我们联系，本站将及时删除！
如遇版权问题，请查看 本站版权声明
THE END
分享
二维码
海报
详解 Java 线上问题排查思路
因为通常线程数量会由线程池管理，一般不会超过我们设定的最大值；而线程“死锁”通常是人为代码问题，某个获得锁的线程没有释放锁，导致其他线程一直处于 Waiting...
<<上一篇
下一篇>>