thread dump日志文件分析

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

在这里插入图片描述

  • 新建状态(New)

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

  • 就绪状态(Runnable)

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

  • 运行状态(Running)

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

  • 阻塞状态(Blocked)

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

  1. 等待阻塞:处于对象等待池中的阻塞状态(Blocked in object’s wait pool): 当线程处于运行状态时,如果执行了某个对象的wait()方法,Java虚拟机就会把线程放到这个对象的等待池中,这涉及到“线程通信”的内容。(对应wait()方法)
  2. 同步阻塞:处于对象锁池中的阻塞状态(Blocked in object’s lock pool): 当线程处于运行状态时,试图获得某个对象的同步锁时,如果该对象的同步锁已经被其他线程占用,Java虚拟机就会把这个线程放到这个对象的锁池中,这涉及到“线程同步”的内容。(对应synchronized同步锁)
  3. 其他阻塞:处于其他阻塞状态(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

在这里插入图片描述

  • 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日志文件的格式(每个信息所处的位置),如下所示:

在这里插入图片描述

       关于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、)、自底向上调用堆栈树等等一系列的信息。很方便的来分类定位信息。

在这里插入图片描述

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文件。里面有展示线程的统计信息,线程的详细信息等,使用起来都很方便。

在这里插入图片描述
在这里插入图片描述

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),最后显示的效果如下:

在这里插入图片描述

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.
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值