Java
Java虚拟机

Java虚拟机11 - JVM工具之jstack

简介:Java开发工具包中提供了众多的虚拟机工具可供开发者使用。

1. jstack简介

jstack(Stack Trace for Java)命令用于生成虚拟机当前时刻的线程快照(一般称为threaddump或者javacore文件)。线程快照就是当前虚拟机内每一条线程正在执行的方法堆栈的集合,生成线程快照的主要目的是定位线程出现长时间停顿的原因,如线程间死锁、死循环、请求外部资源导致的长时间等待等都是导致线程长时间停顿的常见原因。线程出现停顿的时候通过jstack来查看各个线程的调用堆栈,就可以知道没有响应的线程到底在后台做些什么事情,或者等待着什么资源。

注:Oracle官方提供的jstack命令的参考文档地址为https://docs.oracle.com/javase/8/docs/technotes/tools/unix/jstack.html

2. jstack命令格式

jstack命令格式为如下:

  • ubuntu@s100:~$ jstack
  • 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)

jstack三个选项的具体含义如下:

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

3. jstack使用演示

下面的演示使用了jstack命令查看了2281进程的线程快照,并查看了输出内容的前20行:

  • ubuntu@s100:~$ jstack 2281 > jstack.log
  • ubuntu@s100:~$ head -20 jstack.log
  • 2015-07-01 17:05:50
  • Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.65-b01 mixed mode):
  • "Attach Listener" #39 daemon prio=9 os_prio=0 tid=0x00007fa894006800 nid=0x1255 waiting on condition [0x0000000000000000]
  • java.lang.Thread.State: RUNNABLE
  • "ajp-bio-8009-AsyncTimeout" #37 daemon prio=5 os_prio=0 tid=0x00007fa8b83ff000 nid=0x918 waiting on condition [0x00007fa889c88000]
  • java.lang.Thread.State: TIMED_WAITING (sleeping)
  • at java.lang.Thread.sleep(Native Method)
  • at org.apache.tomcat.util.net.JIoEndpoint$AsyncTimeout.run(JIoEndpoint.java:152)
  • at java.lang.Thread.run(Thread.java:745)
  • "ajp-bio-8009-Acceptor-0" #36 daemon prio=5 os_prio=0 tid=0x00007fa8b83fd000 nid=0x917 runnable [0x00007fa889d89000]
  • java.lang.Thread.State: RUNNABLE
  • at java.net.PlainSocketImpl.socketAccept(Native Method)
  • at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
  • at java.net.ServerSocket.implAccept(ServerSocket.java:545)
  • at java.net.ServerSocket.accept(ServerSocket.java:513)
  • at org.apache.tomcat.util.net.DefaultServerSocketFactory.acceptSocket(DefaultServerSocketFactory.java:60)
  • at org.apache.tomcat.util.net.JIoEndpoint$Acceptor.run(JIoEndpoint.java:222)

以下面ajp-bio-8009-AsyncTimeout线程的片段为例:

  • "ajp-bio-8009-AsyncTimeout" #37 daemon prio=5 os_prio=0 tid=0x00007fa8b83ff000 nid=0x918 waiting on condition [0x00007fa889c88000]
  • java.lang.Thread.State: TIMED_WAITING (sleeping)
  • at java.lang.Thread.sleep(Native Method)
  • at org.apache.tomcat.util.net.JIoEndpoint$AsyncTimeout.run(JIoEndpoint.java:152)
  • at java.lang.Thread.run(Thread.java:745)

其中#37表示内部类的编号,daemon表示是守护进程,prio表示优先级,os_prio表示对应的操作系统优先级,nid即是十六进制格式的线程ID,java.lang.Thread.State: TIMED_WAITING (sleeping)表示线程的状态。对于线程的状态有以下的转换过程:

1.Java线程状态转换图.jpg

3.1. jstack检查死循环

一般来说,jstack可以用于排查死循环或者死锁问题。

死循环会导致CPU使用率的飙升,我们编写以下的测试代码:

  • public class LoopTest {
  • public static void main(String[] args) {
  • while (true) {
  • ;
  • }
  • }
  • }

代码非常简单,就是一个死循环。在Linux系统下编译并运行,然后可以通过top命令来查看占用资源最大的进程:

  • ubuntu@s100:~$ top
  • top - 17:42:27 up 4:15, 1 user, load average: 0.22, 0.06, 0.06
  • Tasks: 360 total, 1 running, 359 sleeping, 0 stopped, 0 zombie
  • Cpu(s): 99.0%us, 0.7%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.3%hi, 0.0%si, 0.0%st
  • Mem: 4033168k total, 476028k used, 3557140k free, 24904k buffers
  • Swap: 1046524k total, 0k used, 1046524k free, 162444k cached
  • PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
  • 5493 ubuntu 20 0 2836m 21m 10m S 99.1 0.6 0:16.14 java
  • 325 root 20 0 0 0 0 S 0.3 0.0 0:17.46 kworker/0:2
  • ...

从第9行可以看出,PID为5293的进程占用了最大的CPU;有了进程ID后,通过top -p PID -H可以查看某个进程中的线程状态信息,如:

  • ubuntu@s100:~$ top -p 5493 -H
  • top - 17:42:56 up 4:15, 1 user, load average: 0.57, 0.15, 0.09
  • Tasks: 10 total, 1 running, 9 sleeping, 0 stopped, 0 zombie
  • Cpu(s): 99.7%us, 0.3%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
  • Mem: 4033168k total, 475936k used, 3557232k free, 24920k buffers
  • Swap: 1046524k total, 0k used, 1046524k free, 162444k cached
  • PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
  • 5494 ubuntu 20 0 2836m 21m 10m R 99.2 0.6 0:44.41 java
  • 5493 ubuntu 20 0 2836m 21m 10m S 0.0 0.6 0:00.00 java
  • 5495 ubuntu 20 0 2836m 21m 10m S 0.0 0.6 0:00.00 java
  • ...

有了线程ID后,就可以通过线程ID在jstack 5493 > jstack.log命令获取的进程5493的线程快照中根据nid来找到对应的线程调用栈,定位产生死循环的方法调用。

从上面的信息中可以得知,线程ID为5494(十进制,转换为十六禁止为1576)的线程占用的CPU使用率最大,因此我们去jstack产生的线程快照中查找该线程:

注:需要注意的是,Linux使用top命令获取的线程ID是十进制的,而jstack产出的线程快照中nid是十六进制的,需要进行转换。

  • 2015-07-01 17:44:10
  • Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.65-b01 mixed mode):
  • "Attach Listener" #8 daemon prio=9 os_prio=0 tid=0x00007ff338001000 nid=0x15cf waiting on condition [0x0000000000000000]
  • java.lang.Thread.State: RUNNABLE
  • ...
  • "main" #1 prio=5 os_prio=0 tid=0x00007ff35c009800 nid=0x1576 runnable [0x00007ff3648ff000]
  • java.lang.Thread.State: RUNNABLE
  • at LoopTest.main(LoopTest.java:4)
  • "VM Thread" os_prio=0 tid=0x00007ff35c06e000 nid=0x1577 runnable
  • "VM Periodic Task Thread" os_prio=0 tid=0x00007ff35c0b9000 nid=0x157e waiting on condition
  • JNI global references: 6
  • ...

从上面日志中nid=0x1576片段可以得知,运行的正是LoopTest.main方法导致了CPU使用率飙升,因此我们可以检查该方法。

3.2. jstack检查死锁

有以下的死锁测试代码,其中两个线程分别获取两把锁,会出现死锁的情况:

  • public class DeadLockTest {
  • public static void main(String[] args) {
  • // 两把锁
  • DeadLockTest monitor1 = new DeadLockTest();
  • DeadLockTest monitor2 = new DeadLockTest();
  • new Thread(new Runnable() {
  • @Override
  • public void run() {
  • synchronized (monitor1) {
  • try {
  • Thread.sleep(1000);
  • } catch(Exception e) {
  • e.printStackTrace();
  • }
  • synchronized (monitor2) {
  • System.out.println("DeadLock test Thread - 1 End");
  • }
  • }
  • }
  • }, "DeadLock test Thread - 1").start();
  • new Thread(new Runnable() {
  • @Override
  • public void run() {
  • synchronized (monitor2) {
  • try {
  • Thread.sleep(1000);
  • } catch(Exception e) {
  • e.printStackTrace();
  • }
  • synchronized (monitor1) {
  • System.out.println("DeadLock test Thread - 2 End");
  • }
  • }
  • }
  • }, "DeadLock test Thread - 2").start();
  • }
  • }

在Linux系统下编译并运行,通过jps命令获取进程ID并使用jstack命令获取该进程的线程快照片段如下:

  • 2015-07-01 18:09:41
  • Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.65-b01 mixed mode):
  • "Attach Listener" #11 daemon prio=9 os_prio=0 tid=0x00007f7a58001000 nid=0x177b waiting on condition [0x0000000000000000]
  • java.lang.Thread.State: RUNNABLE
  • ...
  • Found one Java-level deadlock:
  • =============================
  • "DeadLock test Thread - 2":
  • waiting to lock monitor 0x00007f7a600062c8 (object 0x00000000c2659e88, a DeadLockTest),
  • which is held by "DeadLock test Thread - 1"
  • "DeadLock test Thread - 1":
  • waiting to lock monitor 0x00007f7a60004e28 (object 0x00000000c2659e98, a DeadLockTest),
  • which is held by "DeadLock test Thread - 2"
  • Java stack information for the threads listed above:
  • ===================================================
  • "DeadLock test Thread - 2":
  • at DeadLockTest$2.run(DeadLockTest.java:32)
  • - waiting to lock <0x00000000c2659e88> (a DeadLockTest)
  • - locked <0x00000000c2659e98> (a DeadLockTest)
  • at java.lang.Thread.run(Thread.java:745)
  • "DeadLock test Thread - 1":
  • at DeadLockTest$1.run(DeadLockTest.java:17)
  • - waiting to lock <0x00000000c2659e98> (a DeadLockTest)
  • - locked <0x00000000c2659e88> (a DeadLockTest)
  • at java.lang.Thread.run(Thread.java:745)
  • Found 1 deadlock.

从日志最底部可以直接看到Found 1 deadlock.字样,并且在上面显示出了出现死锁的原因,可以得知DeadLock test Thread - 2线程正在等待lock <0x00000000c2659e88>这把锁,且已经获取了locked <0x00000000c2659e98>这把锁;而DeadLock test Thread - 1恰好相反,它正在等待lock <0x00000000c2659e98>这把锁,且已经获取了locked <0x00000000c2659e88>这把锁,因此造成了死锁的发生。

3.3. 其他应用

在JDK 1.5中,java.lang.Thread类新增了一个getAllStackTraces()方法用于获取虚拟机中所有线程的StackTraceElement对象。使用这个方法可以通过简单的几行代码就完成jstack的大部分功能,在实际项目中可以调用这个方法做个管理员页面,可以随时使用浏览器来查看线程堆栈,如下代码:

  • <%@page import="java.util.Map"%>
  • <html>
  • <head>
  • <title>服务器线程信息</title>
  • </head>
  • <body>
  • <pre>
  • <%
  • for (Map.Entry<Thread, StackTraceElement[]>stackTrace: Thread.getAllStackTraces().entrySet()) {
  • Thread thread = (Thread)stackTrace.getKey();
  • StackTraceElement[]stack = (StackTraceElement[])stackTrace.getValue();
  • if (thread.equals(Thread.currentThread())) {
  • continue;
  • }
  • out.print("\n线程:" + thread.getName() + "\n");
  • for(StackTraceElement element: stack) {
  • out.print("\t" + element + "\n");
  • }
  • }
  • %>
  • </pre>
  • </body>
  • </html>