第三篇 JVM性能调优之jstack实战死循环与死锁

一 jstack命令

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

示例：

$ jps
61728 Launcher
61729 ImServerApplication
79652 Jps
$ jstack 61729 > temp.log

打开temp.log 可以看到所有线程的当前状态。

附线程状态表：
参考官网：https://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/tooldescr034.html#sthref31
| Thread State | Description |
|:————-:|:————-:|
| NEW | The thread has not yet started. |
| RUNNABLE | The thread is executing in the JVM. |
| BLOCKED | The thread is blocked waiting for a monitor lock. |
| WAITING | The thread is waiting indefinitely for another thread to perform a particular action. |
| TIMED_WAITING | The thread is waiting for another thread to perform an action for up to a specified waiting time. |
| TERMINATED | The thread has exited. |

二 实战死循环

先实现一段死循环代码

@GetMapping("/loop")
public void loop() {
    int page = 1;
    while (true) {
        List<String> pageInfoList = this.findPage(page, 2);
        if (pageInfoList.size() == 0) {
            break;
        }
        // 对数据做处理 省略...
    }
}

执行命令定位位置

# top

top - 03:12:10 up 21 min,  3 users,  load average: 0.86, 0.28, 0.15
Tasks:  90 total,   2 running,  88 sleeping,   0 stopped,   0 zombie
%Cpu(s): 97.7 us,  1.6 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.8 si,  0.0 st
KiB Mem :  1882828 total,  1040648 free,   218336 used,   623844 buff/cache
KiB Swap:  1572860 total,  1572860 free,        0 used.  1477032 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
10595 root      20   0 2520336 142300  13304 S 99.9  7.6   0:47.24 java
    1 root      20   0  128004   6540   4148 S  0.0  0.3   0:01.09 systemd
    2 root      20   0       0      0      0 S  0.0  0.0   0:00.00 kthreadd
    3 root      20   0       0      0      0 S  0.0  0.0   0:00.09 ksoftirqd/0
    5 root       0 -20       0      0      0 S  0.0  0.0   0:00.00 kworker/0:0H

# top -p 10595 -H

top - 03:16:14 up 25 min,  3 users,  load average: 1.76, 1.13, 0.53
Threads:  30 total,   1 running,  29 sleeping,   0 stopped,   0 zombie
%Cpu(s): 98.4 us,  1.6 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  1882828 total,  1040252 free,   218664 used,   623912 buff/cache
KiB Swap:  1572860 total,  1572860 free,        0 used.  1476676 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
10614 root      20   0 2521364 143048  13308 R 62.6  7.6   2:59.32 java
10597 root      20   0 2521364 143048  13308 S 37.4  7.6   1:45.27 java
10624 root      20   0 2521364 143048  13308 S  0.3  7.6   0:00.13 java
10595 root      20   0 2521364 143048  13308 S  0.0  7.6   0:00.00 java

# printf "%x" 10614
2976

# jstack 10595 > tmp.log

查看tmp.log中线程id为0x2976的线程

"http-nio-8080-exec-1" #18 daemon prio=5 os_prio=0 tid=0x00007f9c7415e000 nid=0x2976 waiting on condition [0x00007f9c439fa000]
   java.lang.Thread.State: RUNNABLE
	at java.util.Arrays.copyOf(Arrays.java:3181)
	at java.util.ArrayList.grow(ArrayList.java:265)
	at java.util.ArrayList.ensureExplicitCapacity(ArrayList.java:239)
	at java.util.ArrayList.ensureCapacityInternal(ArrayList.java:231)
	at java.util.ArrayList.add(ArrayList.java:462)
	at com.jacky.imserver.controller.UserController.findPage(UserController.java:34)
	at com.jacky.imserver.controller.UserController.loop(UserController.java:24)

则定位出来是因为UserController.loop方法出现的死循环

步骤说明：

1. 通过top命令查询出占用cpu高的进程
2. 根据进程ID执行命令 top -p [PID] -H 查看占用cpu最好的线程
3. 把线程ID转16进制 printf “%x” 10614
4. jstack查询进程ID的日志到文件
5. 查询这个文件进程ID为转好的16进制线程ID，从而定位出哪里导致的cpu飙高的代码。

三 实战死锁

先模拟出一段死锁代码

@GetMapping("/deadlock")
public void deadlock() {
    Object lock1 = new Object();
    Object lock2 = new Object();
    new Thread(() -> {
        try {
            synchronized (lock1) {
                Thread.sleep(500L);
                synchronized (lock2) {
                    System.out.println("线程1处理");
                }
            }
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }).start();
    new Thread(() -> {
        try {
            synchronized (lock2) {
                Thread.sleep(500L);
                synchronized (lock1) {
                    System.out.println("线程2处理");
                }
            }
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }).start();
    System.out.println("已触发");
}

通过jstack [PID] 查询
看到最后面有

Found one Java-level deadlock:
=============================
"Thread-21":
  waiting to lock monitor 0x00007fec5398f968 (object 0x00000007fbb68fe0, a java.lang.Object),
  which is held by "Thread-20"
"Thread-20":
  waiting to lock monitor 0x00007fec5082ed48 (object 0x00000007fbb68ff0, a java.lang.Object),
  which is held by "Thread-21"

Java stack information for the threads listed above:
===================================================
"Thread-21":
	at com.jacky.imserver.controller.UserController.lambda$deadlock$1(UserController.java:41)
	- waiting to lock <0x00000007fbb68fe0> (a java.lang.Object)
	- locked <0x00000007fbb68ff0> (a java.lang.Object)
	at com.jacky.imserver.controller.UserController$$Lambda$427/1168450100.run(Unknown Source)
	at java.lang.Thread.run(Thread.java:748)
"Thread-20":
	at com.jacky.imserver.controller.UserController.lambda$deadlock$0(UserController.java:29)
	- waiting to lock <0x00000007fbb68ff0> (a java.lang.Object)
	- locked <0x00000007fbb68fe0> (a java.lang.Object)
	at com.jacky.imserver.controller.UserController$$Lambda$426/169622243.run(Unknown Source)
	at java.lang.Thread.run(Thread.java:748)

Found 1 deadlock.

jstack已经帮我们找出了死锁的位置，更改修复即可。