JVM thread dump日志文件

作者: tuacy | 来源:发表于2020-03-29 00:36 被阅读0次

在介绍thread dump文件之前，咱们得先来了解下Java线程状态。一般来说Java线程状态有五种：新建状态(New)、就绪状态(Runnable)、运行状态(Running) 、阻塞状态(Blocked) 、死亡状态(Dead) 。

线程状态.png

新建状态(New)

用new语句创建的线程处于新建状态，此时它和其他Java对象一样，仅仅在堆区中被分配了内存。(对象在堆区产生)

就绪状态(Runnable)

当一个线程对象创建后，其他线程调用它的start()方法，该线程就进入就绪状态，Java虚拟机会为它创建方法调用栈和程序计数器。处于这个状态的线程位于可运行池中，等待获得CPU的使用权。

运行状态(Running)

处于这个状态的线程占用CPU，执行程序代码。只有处于就绪状态的线程才有机会转到运行状态。

阻塞状态(Blocked)

阻塞状态是指线程因为某些原因放弃CPU，暂时停止运行。当线程处于阻塞状态时，Java虚拟机不会给线程分配CPU。直到线程重新进入就绪状态，它才有机会转到运行状态。阻塞状态也是分多钟情况的：等待阻塞、同步阻塞、其他阻塞。

等待阻塞：处于对象等待池中的阻塞状态(Blocked in object’s wait pool): 当线程处于运行状态时，如果执行了某个对象的wait()方法，Java虚拟机就会把线程放到这个对象的等待池中，这涉及到“线程通信”的内容。(对应wait()方法)
同步阻塞：处于对象锁池中的阻塞状态(Blocked in object’s lock pool): 当线程处于运行状态时，试图获得某个对象的同步锁时，如果该对象的同步锁已经被其他线程占用，Java虚拟机就会把这个线程放到这个对象的锁池中，这涉及到“线程同步”的内容。(对应synchronized同步锁)
其他阻塞：处于其他阻塞状态(Ohterwise Blick): 当前线程执行了sleep()方法，或者调用了其他线程的join()方法，或者发出了I/O请求时，就会进入这个状态。(对应sleep()或者join()或发出了I/O请求时)

死亡状态(Dead)

当线程退出run()方法时，就进入死亡状态，该线程结束生命周期。

接下来，我们才进入到我们本文的重点，thread dump日志文件

一 thread dump日志文件介绍

1.1 thread dump日志文件是什么

thread dump日志文件是应用程序当前活动线程的快照(所有线程堆栈)信息，简单来说thread dump日志里面保存的是某一时刻对应应用程序所有活动线程的详细信息。而且thread dump日志文件是一个纯文本文件。

thread dump文件里面为每个线程提供了：线程名字，id、线程的运行状态，锁的状态(锁被哪个线程持有，哪个线程在等待锁等)、调用堆栈信息(包含完整的类名，所执行的方法，源代码的行数等)。

1.2 thread dump日志文件的获取

我们一般使用JVM自带的jps和jstack工具来获取thread dump文件。先用jps命令获取到应用程序的PID，获取PID之后在通过jstack命令来导出对应的thread dump日志文件。

jps -l 获取PID(Linux系统下你也可以使用 ps –ef | grep java)。
jstack -l <PID> | tee -a 文件名字

我用一个简单的例子来说明下，比如我要获取我电脑里面basic-ioserver-websocket-server.jar程序对应的thread dump日志文件信息。

jps -l 找到basic-ioserver-websocket-server.jar对应的PID 51164

jps.png

jstack -l 51164 >> ioserver-websocket-thread-dump20200328.txt 把thread dump文件保存在ioserver-websocket-thread-dump20200328.txt文件里面

1.3 thread dump日志文件解析

上面我们已经知道了怎么获取thread dump日志文件。接下来我们得知道怎么去分析thread dump日志文件。thread dump日志文件是一个纯文本格式的文件。里面给出了thread dump日志文件的生成时间，以及JVM信息，还有当前时刻所有线程的详细信息，每个线程的信息又包括：线程名字，线程编号，线程优先级，线程状态，线程详细状态，线程堆栈信息等等。

我们简单一点，我直接用一个图来表示thread dump日志文件的格式(每个信息所处的位置)，如下所示：

线程Dump.png

关于thread dump日志文件重要关注点在：线程名字(用于找到对应的线程)，线程状态，线程详细状态，线程堆栈信息。

1.3.1 thread dump日志线程状态

thread dump日志文件里面的线程状态和咱们最上面讲的Java中的线程状态还不太一样。理解上可能会出现混乱。其实咱们也不用太纠结。因为虽然Java中的线程状态有五种，但是大多时候我们关注的是运行状态和阻塞状态，线程新建状态和死亡状态持续时间都是很短的。我们也不用太关心。thread dump线程状态如下：

thread dump线程状态	解释
runnable	线程运行中或I/O等待
sleeping	当前线程被挂起
waiting on condition	在等待另一个条件的发生，来把自己唤醒
waiting for monitor entry	在等待进入一个临界区，所以它在”Entry Set“队列中等待
in Object.wait()	进入临界区支行，又调用了java.lang.Object.wait()方法等待，在“Wait Set”对列中等待

monitor是Java中用以实现线程之间的互斥与协作的主要手段，它可以看成是对象或者Class的锁。每一个对象都有，也仅有一个monitor。每个monitor在某个时刻，只能被一个线程拥有，该线程就是“Active Thread”，而其它线程都是“Waiting Thread”，分别在两个队列“Entry Set”和 “Wait Set”里面等候。在“Entry Set”中等待的线程状态是“Waiting for monitor entry”，而在“Wait Set”中等待的线程状态是“in Object.wait()”。在“Entry Set”中的是试图获取锁而阻塞的线程；而“Wait Set”则是，获取锁后调用wait()而进入阻塞的线程，当其他线程调用notify()或者notifyall()唤醒等待该锁上的其他线程时，会把“Wait Set”队列中的一个或者全部线程放入“Entry Set”中，然后在其中随机选择一个重新获取锁，然后执行。

1.3.2 thread dump日志线程状态详细信息

通过查看线程状态的详细信息，我们可以简单的判断我们线程是因为啥进入了对应的线程状态。

thread dump线程状态详细信息	解释	对应的方法调用
java.lang.Thread.State: RUNNABLE	线程运行中或I/O等待	无
java.lang.Thread.State: BLOCKED (on object monitor)	等待进入一个临界区	synchronized
java.lang.Thread.State: TIMED_WAITING (parking)	线程等待唤醒，并且设置等待时长	LockSupport.parkNanos(等待时长)、LockSupport.parkUntil(等待时长)
java.lang.Thread.State: TIMED_WAITING (sleeping)	线程等待唤醒，并且设置等待时长	Thread.sleep(等待时长)，Thread.join(等待时长)
java.lang.Thread.State: TIMED_WAITING (on object monitor)	线程在等待唤醒，并且设置等待时长	Object.wait(等待时长)
java.lang.Thread.State: WAITING (parking)	线程等待唤醒，没有设置等待时长	LockSupport.park()
java.lang.Thread.State: WAITING (on object monitor)	线程等待唤醒，并且没有设置等待时长	Object.wait()
java.lang.Thread.State: WAITING (on object monitor)	线程等待唤醒，没有设置等待时长	Thread.join()

1.3.3 thread dump日志文件线程状态实例解释

下面我们通过几个简单的实例来理解下thread dump线程状态

wait()，sleep()对应的线程状态

    public static void main(String[] args) {

        Thread thread = new Thread("线程1") {
            //重写run方法
            public void run() {
                synchronized (this) {
                    System.out.println(Thread.currentThread().getName());
                    try {
                        wait();
                    } catch (InterruptedException e) {
                        e.printStackTrace();
                    }
                }
            }
        };
        thread.start();
        try {
            TimeUnit.SECONDS.sleep(3);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        synchronized (thread) {
            System.out.println(Thread.currentThread().getName());
            try {
                TimeUnit.SECONDS.sleep(60);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            thread.notify();
        }


    }

上面代码会先执行线程1 run()方法，然后调用wait()方法阻塞block住。等到主线程调用thread.notify()方法之后才会继续往下执行。我们在程序跑起来之后大概10秒时候导出thread dump日志文件信息，此时：

[线程1]线程：wait()方法阻塞住了，状态对应in Object.wait()，状态详细信息对应java.lang.Thread.State: WAITING (on object monitor)。
[main]线程：TimeUnit.SECONDS.sleep(60)阻塞住了，状态对应waiting on condition，状态详细信息对应java.lang.Thread.State: TIMED_WAITING (sleeping)。

对应thread dump日志文件的部分信息

2020-03-23 22:54:53
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.121-b13 mixed mode):

"线程1" #12 prio=5 os_prio=0 tid=0x00007f420024d800 nid=0x1ca5 in Object.wait() [0x00007f41e71ee000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000d8258ba0> (a com.jvm.study.threaddump.deadlock.ObjectWaitingMock$1)
    at java.lang.Object.wait(Object.java:502)
    at com.jvm.study.threaddump.deadlock.ObjectWaitingMock$1.run(ObjectWaitingMock.java:15)
    - locked <0x00000000d8258ba0> (a com.jvm.study.threaddump.deadlock.ObjectWaitingMock$1)

   Locked ownable synchronizers:
    - None

....(其他信息这里我们省略掉)

"main" #1 prio=5 os_prio=0 tid=0x00007f420000d800 nid=0x1c84 waiting on condition [0x00007f4209891000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    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 com.jvm.study.threaddump.deadlock.ObjectWaitingMock.main(ObjectWaitingMock.java:31)
    - locked <0x00000000d8258ba0> (a com.jvm.study.threaddump.deadlock.ObjectWaitingMock$1)

   Locked ownable synchronizers:
    - None

...(其他信息这里我们省略掉)

synchronized对应线程状态

    public static void main(String[] args) {

        Thread thread = new Thread("线程") {
            //重写run方法
            public void run() {
                synchronized (this) {
                    System.out.println(Thread.currentThread().getName());
                    try {
                        TimeUnit.SECONDS.sleep(60);
                    } catch (Exception e) {
                        e.printStackTrace();
                    }
                }
            }
        };
        thread.start();

        synchronized (thread) {
            System.out.println(Thread.currentThread().getName());
            try {
                TimeUnit.SECONDS.sleep(60);
            } catch (Exception e) {
                e.printStackTrace();
            }
        }

    }

程序刚开始执行的时候会先进入主线程的synchronized然后进入TimeUnit.SECONDS.sleep(60)阻塞，Thread("线程")因为主线程还阻塞主synchronized对应的锁还没有放开，所有会阻塞住

[线程]线程：synchronized等待进入同步状态。状态对应waiting for monitor entry，状态详细信息对应java.lang.Thread.State: BLOCKED (on object monitor)
[main]线程：TimeUnit.SECONDS.sleep(60)。状态对应waiting on condition，状态详细信息对应java.lang.Thread.State: TIMED_WAITING (sleeping)

对thread dump日志文件信息

2020-03-23 22:34:06
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.121-b13 mixed mode):

...省略掉其他信息

"线程" #12 prio=5 os_prio=0 tid=0x00007f7ccc24d000 nid=0x195f waiting for monitor entry [0x00007f7caa8e5000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at com.jvm.study.threaddump.deadlock.BlockMock$1.run(BlockMock.java:16)
    - waiting to lock <0x00000000d8258140> (a com.jvm.study.threaddump.deadlock.BlockMock$1)

   Locked ownable synchronizers:
    - None

...省略掉其他信息

"main" #1 prio=5 os_prio=0 tid=0x00007f7ccc00d800 nid=0x193a waiting on condition [0x00007f7cd4f00000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    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 com.jvm.study.threaddump.deadlock.BlockMock.main(BlockMock.java:30)
    - locked <0x00000000d8258140> (a com.jvm.study.threaddump.deadlock.BlockMock$1)

   Locked ownable synchronizers:
    - None

二 thread dump文件能做什么(能帮咱们解决什么问题)

我们了解thread dump日志文件的最终肯定是用他来帮我们解决问题的，咱们不可能无缘无故的去导出thread dump日志文件而什么都不干吧。

在用thread dump文件解决问题之前，咱们得先找个好点的thread dump日志文件的分析工具。工欲善其事必先利其器。

2.1 thread dump日志文件分析工具

2.1.1 fastthread在线工具

fastthread在线工具，在线网址 http://fastthread.io/

打开网址，在网页上选择我们需要分析的thread dump文件。通过fastthread工具。我们可以很容易的知道线程统计信息(WAITING、RUNNABLE、TIMED_WAITING、BLOCK中的线程个数，以及每种状态里面的所有线程)、守护程序与非守护程序的统计信息、具有相同堆栈跟踪的线程信息、最常用的方法(park()、wait()、sleep、)、自底向上调用堆栈树等等一系列的信息。很方便的来分类定位信息。

fastthread.png

2.1.2 IBM Thread and Monitor Dump Analyzer for Java

通过网址 https://www.ibm.com/support/pages/ibm-thread-and-monitor-dump-analyzer-java-tmda 我们可以下载到jca465.jar(也可能是jcaxxx.jar啥的，不一定是jca465.jar)。下载到jca465.jar文件之后我们就好办了。

执行jca465.jar文件。 java -jar jca465.jar 执行之后，会打开相应的图形化界面。之后选择我们需要分析的thread dump文件。里面有展示线程的统计信息，线程的详细信息等，使用起来都很方便。

thraddumptool.png

threaddumptoolsummary.png

2.2 thread dump案例分析

2.2.1 CPU占用率很高，响应很慢

先找到占用CPU的进程，然后再定位到对应的线程，最后分析出对应的堆栈信息。所以我们得关键点在获取到占CPU线程的堆栈信息。需要在多个时间段提出多个 Thread Dump信息，然后综合进行对比分析，单独分析一个文件是没有意义的。

top -c 动态显示进程及占用资源的排行榜)找到占用CPU最高的进程PID
通过PID去找到当前PID下占CPU最高的线程的堆栈信息。关于这一部分的内容网上以及有高手帮我们写成了一个脚本(Linux环境)，我们只需要执行脚本，执行脚本的时候需要输入两个参数第一个参数对应PID，第二个参数对应需要显示占CPU线程堆栈的多少行数据。脚本文件如下：

#!/bin/bash
if [ $# -le 0 ]; then
    echo "usage: $0 <pid> [line-number]"
    exit 1
fi

# java home
if test -z $JAVA_HOME 
then
    JAVA_HOME='/usr/local/jdk'
fi

#pid -- 第一个参数进程pid
pid=$1
# checking pid
if test -z "$($JAVA_HOME/bin/jps -l | cut -d '' -f 1 | grep $pid)"
then
    echo "process of $pid is not exists"
    exit
fi

#line number -- 第二个参数显示多少行的堆栈信息
linenum=$2
if test -z $linenum
then
    linenum=10
fi

stackfile=stack$pid.dump
threadsfile=threads$pid.dump

# generate java stack
$JAVA_HOME/bin/jstack -l $pid >> $stackfile
ps -mp $pid -o THREAD,tid,time | sort -k2r | awk '{if ($1 !="USER" && $2 != "0.0" && $8 !="-") print $8;}' | xargs printf "%x\n" >> $threadsfile
tids="$(cat $threadsfile)"
for tid in $tids
do
    echo "------------------------------ ThreadId ($tid) ------------------------------"
    cat $stackfile | grep 0x$tid -A $linenum
done

rm -f $stackfile $threadsfile

比如我们想看下PID=82125里面最占CPU线程的前10行堆栈信息（sh height-thread-cpu-stack.sh 82125 10），最后显示的效果如下：

heightcputhreadstack.png

2.2.2 CPU占用率不高，但响应很慢

在整个请求的过程中多次执行Thread Dump然后进行对比，取得 BLOCKED状态的线程列表(通过我们上面提供的thread dump工具是很容易获取到的)，通常是因为线程停在了I/O、数据库连接或网络连接的地方。

2.2.3 线程死锁

线程死锁，thread dump文件里面肯定有给出Found one Java-level deadlock:信息。

2020-03-22 23:04:49
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.121-b13 mixed mode):


"线程2" #13 prio=5 os_prio=0 tid=0x00007f1d3825f800 nid=0x2142 waiting for monitor entry [0x00007f1d16eeb000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at com.jvm.study.threaddump.deadlock.DeadLockMock$2.run(DeadLockMock.java:31)
    - waiting to lock <0x00000000d8251168> (a java.lang.String)
    - locked <0x00000000d8251198> (a java.lang.String)

   Locked ownable synchronizers:
    - None

"线程1" #12 prio=5 os_prio=0 tid=0x00007f1d3825e000 nid=0x2141 waiting for monitor entry [0x00007f1d16fec000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at com.jvm.study.threaddump.deadlock.DeadLockMock$1.run(DeadLockMock.java:16)
    - waiting to lock <0x00000000d8251198> (a java.lang.String)
    - locked <0x00000000d8251168> (a java.lang.String)

   Locked ownable synchronizers:
    - None


Found one Java-level deadlock:
=============================
"线程2":
  waiting to lock monitor 0x00007f1d04006218 (object 0x00000000d8251168, a java.lang.String),
  which is held by "线程1"
"线程1":
  waiting to lock monitor 0x00007f1d04002178 (object 0x00000000d8251198, a java.lang.String),
  which is held by "线程2"

Java stack information for the threads listed above:
===================================================
"线程2":
    at com.jvm.study.threaddump.deadlock.DeadLockMock$2.run(DeadLockMock.java:31)
    - waiting to lock <0x00000000d8251168> (a java.lang.String)
    - locked <0x00000000d8251198> (a java.lang.String)
"线程1":
    at com.jvm.study.threaddump.deadlock.DeadLockMock$1.run(DeadLockMock.java:16)
    - waiting to lock <0x00000000d8251198> (a java.lang.String)
    - locked <0x00000000d8251168> (a java.lang.String)

Found 1 deadlock.

JVM thread dump日志文件

一 thread dump日志文件介绍

1.1 thread dump日志文件是什么

1.2 thread dump日志文件的获取

1.3 thread dump日志文件解析

1.3.1 thread dump日志线程状态

1.3.2 thread dump日志线程状态详细信息

1.3.3 thread dump日志文件线程状态实例解释

二 thread dump文件能做什么(能帮咱们解决什么问题)

2.1 thread dump日志文件分析工具

2.1.1 fastthread在线工具

2.1.2 IBM Thread and Monitor Dump Analyzer for Java

2.2 thread dump案例分析

2.2.1 CPU占用率很高，响应很慢

2.2.2 CPU占用率不高，但响应很慢

2.2.3 线程死锁

相关文章

网友评论

延伸阅读

深度阅读

栏目导航

热点阅读

Java多线程