性能优化：线程快照获取与分析

当我们想了解系统运行情况时，经常需要用到线程快照，这里介绍下线程快照的获取和分析。需要注意的时，线程快照展示的是某一时刻的线程状况，我们一般需要连续获取三到五次线程快照才能得到完整的运行状况。一、线程快照的导出1、JDK工具jstackjstack 命令是JDK工具之一，使用该命令可以打印正在运行中 Java 进程的栈信息。..............................

jchen104

6959人浏览 · 2022-06-27 08:30:00

jchen104 · 2022-06-27 08:30:00 发布

参考资料：

《JAVA线程状态梳理以及Jstack命令使用》

《Java线程Dump分析》

《jstack生成的Thread Dump日志线程状态》

《常见的Thread Dump日志案例分析》

《thread dump日志文件分析》

写在开头：本文为学习后的总结，可能有不到位的地方，错误的地方，欢迎各位指正。

（4）parking to wait for

一、线程快照的获取

目前我司拉取线程快照一般都通过云平台提供的功能了，简单好用，不过原生的方法还是要掌握的，下面我简单展示下。需要注意的时，线程快照展示的是某一时刻的线程状况，我们一般需要连续获取三到五次线程快照才能得到完整的运行状况。

1、linux环境

这里以使用jstack分析CPU占用率过高的问题为例，我们进入服务器，使用top指令按CPU或内存使用率排序，找到使用率最高的进程（即第一列的PID）。（ps –ef | grep java也可以用来查找进程id，不过这个场景下top要合适些同样效果命令还有jps，不过个人没怎么用过）。

然后使用top -Hp PID查看具体的线程。

使用printf "%x\n" PID（这里的PID是上图中的线程号）得到16进制的线程号。

然后我们使用jsatck PID 将该进程下的线程快照导出即可，也可以直接在服务器环境下使用jstack PID | grep 9a7a 查找刚才转换出的16进制的线程号（更多的时候我们会将线程日志打出来 jstack pid > pid.txt拉取到本地分析）来查看造成CPU消耗的代码，大部分情况下为死循环造成。

需要注意的是，服务器上安装的只有jre，是没有stack的，需要放JDK才行（只要放上去解压即可）。同时，尽量不要在生产环境下安装JDK。

2、windos环境

如果是windos环境的话（虽然少，不过也确实遇到过部署在windows上的老项目），这里引用下《JAVA线程状态梳理以及Jstack命令使用》中的截图。

首先查看任务管理器，找到PID。

使用Process Explorer工具，找到2284进程并查看属性。找到CPU占用最高线程TID，8840。

将8840换算为16进制，即为2288，记下这个16进制数字，然后在cmd下执行jstack -l PID命令，即jstack -l 2284。可以看到nid=0x2288线程堆栈信息。

二、状态信息

线程快照基本信息如下图所示，我们将其关键信息拆分出来，分别在本章的第1，3，4小节介绍。

1、JVM线程状态

jstack中输出的jvm线程的状态共有6种，出现在线程信息的第二行，在JVM中线程状态使用枚举 java.lang.Thread.State 来表示，State的定义如下：

    public enum State {
        NEW,
        RUNNABLE,
        BLOCKED,
        WAITING,
        TIMED_WAITING,
        TERMINATED;
    }

这几种状态的转换关系如下图

在这里插入图片描述

有了上面的转换关系图，我们再来逐个介绍每种状态

NEW,未启动的。不会出现在Dump中。
RUNNABLE,在虚拟机内执行的。运行中状态，可能里面还能看到locked字样，表明它获得了某把锁（注意，state中没有running状态）。
BLOCKED,受阻塞并等待监视器锁。被某个锁(synchronizers)給block住了。
WATING,无限期等待另一个线程执行特定操作。等待某个condition或monitor发生，一般停留在park(), wait(),join() 等语句里（注意没有sleep()）。
TIMED_WATING,有时限的等待另一个线程的特定操作。和WAITING的区别是wait() 等（如sleep()）语句加上了时间限制 wait(timeout)。
TERMINATED,已退出的，结束的进程。

注意，这里只是状态的基本信息，实际上线程快照打印出来状态的信息是很丰富的，这一点我们会在本章结束的时候介绍。

2、Monitor

在多线程的 JAVA程序中，实现线程之间的同步，就要说说 Monitor。 Monitor是 Java中用以实现线程之间的互斥与协作的主要手段，它可以看成是对象或者 Class的锁。每一个对象都有，也仅有一个 monitor。下面这个图，描述了线程和 Monitor之间关系，以及线程的状态转换图：

进入区(Entrt Set):表示线程通过synchronized要求获取对象的锁。如果对象未被锁住,则迚入拥有者;否则则在进入区等待。一旦对象锁被其他线程释放,立即参与竞争。
拥有者(The Owner):表示某一线程成功竞争到对象锁。
等待区(Wait Set):表示线程通过对象的wait方法,释放对象的锁,并在等待区等待被唤醒。

从图中可以看出，一个 Monitor在某个时刻，只能被一个线程拥有，该线程就是 “Active Thread”，而其它线程都是 “Waiting Thread”，分别在两个队列 “ Entry Set”和 “Wait Set”里面等候。在 “Entry Set”中等待的线程状态是 “Waiting for monitor entry”，而在“Wait Set”中等待的线程状态是 “in Object.wait()”。先看 “Entry Set”里面的线程。我们称被 synchronized保护起来的代码段为临界区。当一个线程申请进入临界区时，它就进入了 “Entry Set”队列。对应的 code就像：

synchronized(obj) {
.........

}

3、调用修饰

调用修饰表示线程在方法调用时,额外的重要的操作，一般出现在线程内容中，用来协助分析线程的状态。

locked <对象地址> 对象名：使用synchronized申请对象锁成功,监视器的拥有者。
waiting to lock <对象地址> 对象名：使用synchronized申请对象锁未成功,在迚入区等待。
waiting on<对象地址> 对象名：使用synchronized申请对象锁成功后,释放锁幵在等待区等待。
parking to wait for <对象地址> 对象名（parking比较特殊）

（1）locked

表示当前线程通过synchronized关键字成功获取到了目标对象的监视器，拥有了在临界区操作的权限，状态一般为runnable。注意对象锁是可重入的，所以这里有2次锁住了同一个对象。

"BLOCKED_TEST pool-1-thread-1" prio=6 tid=0x0000000006904800 nid=0x28f4 runnable [0x000000000785f000]
   java.lang.Thread.State: RUNNABLE
                at java.io.FileOutputStream.writeBytes(Native Method)
                at java.io.FileOutputStream.write(FileOutputStream.java:282)
                at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
                at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123)
                - locked <0x0000000780a31778> (a java.io.BufferedOutputStream)
                at java.io.PrintStream.write(PrintStream.java:432)
                - locked <0x0000000780a04118> (a java.io.PrintStream)

（2）waiting to lock

表示当前线程未能通过synchronized关键字获取到目标对象的监视器，状态一般为blocked。

"DEADLOCK_TEST-1" daemon prio=6 tid=0x000000000690f800 nid=0x1820 waiting for monitor entry [0x000000000805f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
                at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.goMonitorDeadlock(ThreadDeadLockState.java:197)
                - waiting to lock <0x00000007d58f5e60> (a com.nbp.theplatform.threaddump.ThreadDeadLockState$Monitor)
                at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.monitorOurLock(ThreadDeadLockState.java:182)
                - locked <0x00000007d58f5e48> (a com.nbp.theplatform.threaddump.ThreadDeadLockState$Monitor)
                at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.run(ThreadDeadLockState.java:135)

（3）waiting on

表示当前线程通过synchronized关键字成功获取到了目标对象的监视器，但调用了wait方法,进入对象的等待区等待。在调用栈顶出现,线程状态为WAITING或TIMED_WATING。

"RMI RenewClean-[172.16.5.19:28475]" daemon prio=10 tid=0x0000000041428800 nid=0xb09 in Object.wait() [0x00007f34f4bd0000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
                at java.lang.Object.wait(Native Method)
                - waiting on <0x00000000aa672478> (a java.lang.ref.ReferenceQueue$Lock)
                at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
                - locked <0x00000000aa672478> (a java.lang.ref.ReferenceQueue$Lock)
                at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run(DGCClient.java:516)
                at java.lang.Thread.run(Thread.java:662)

（4）parking to wait for

park是基本的线程阻塞原语,不通过监视器在对象上阻塞。随concurrent包会出现的新的机制,不synchronized体系不同，具体介绍可以看stackoverflow上的回答传送门

"My thread" prio=10 tid=0x00007fffec082800 nid=0x17e8 waiting on condition [0x00007ffff14eb000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000007d6a33d30> (a java.util.concurrent.locks.ReentrantLock$FairSync)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:156)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:842)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1178)
    at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:201)
    at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:262)
    at LockTest.reentrantLock(LockTest.java:22)
    at LockTest$2.run(LockTest.java:25)
    at java.lang.Thread.run(Thread.java:662)

4、系统线程状态

系统线程状态出现在线程信息第一行的末尾。

deadlock：死锁线程
runnable：表示线程运行中或I/O等待，线程状态一般为RUNNABLE。
in Object.wait()：进入临界区之后，又调用了java.lang.Object.wait()方法等待,jvm线程状态一般为WAITING或TIMED_WAITING。
waiting for monitor entry：在等待进入一个临界区,线程状态一般状态为BLOCKED。
waiting on condition：
线程正处于等待资源或等待某个条件的发生，具体的原因需要结合下面堆栈信息进行分析。

（1）如果堆栈信息明确是应用代码，则证明该线程正在等待资源，一般是大量读取某种资源且该资源采用了资源锁的情况下，线程进入等待状态，等待资源的读取，或者正在等待其他线程的执行等。

（2）如果发现有大量的线程都正处于这种状态，并且堆栈信息中得知正等待网络读写，这是可能因为网络阻塞导致线程无法执行。

（3）还有一种常见的情况是该线程在 sleep，等待 sleep 的时间到了，将被唤醒。

将JVM线程状态信息与系统线程状态信息整合后，得出完整的线程状态信息

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、基本信息介绍

线程状态信息我们上一章已经介绍过了，这一章我们介绍下其余信息

"Log4j2-TF-3-AsyncLoggerConfig--1" #67 daemon prio=5 os_prio=0 tid=0x00007fc511a40000 nid=0x316c waiting on condition [0x00007fc4cbbfa000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x000000008a0a5428> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
	at com.lmax.disruptor.TimeoutBlockingWaitStrategy.waitFor(TimeoutBlockingWaitStrategy.java:38)
	at com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarrier.java:56)
	at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:128)
	at java.lang.Thread.run(Thread.java:745)

"Log4j2-TF-3-AsyncLoggerConfig--1"：线程名
#67：表示当前线程ID，从 main线程开始，JVM 根据线程创建的顺序为线程编号。
prio：是priority优先级的缩写，表名了当前线程的优先级，取值范围为[1-10]，默认为 5。在虚拟机进行线程调度的时候会参考该优先级为线程分配计算资源，这个数值越低越有优先获取到计算资源，一般不设置直接使用默认的优先级。
os_prio：是该线程在操作系统中的优先级。
nid：是Native thread ID，本地操作系统相关的线程id,对应JVM 虚拟机中线程映射在操作系统中的线程编号。（这个nid就是我们用top -Hp pid 查看到的线程号，不过要用printf "%x\n"转换一下进制）。

2、常见案例

（1）锁争用

"DB-Processor-13" daemon prio=5 tid=0x003edf98 nid=0xca waiting for monitor entry [0x000000000825f000]
java.lang.Thread.State: BLOCKED (on object monitor)
                at beans.ConnectionPool.getConnection(ConnectionPool.java:102)
                - waiting to lock <0xe0375410> (a beans.ConnectionPool)
                at beans.cus.ServiceCnt.getTodayCount(ServiceCnt.java:111)
                at beans.cus.ServiceCnt.insertCount(ServiceCnt.java:43)

"DB-Processor-14" daemon prio=5 tid=0x003edf98 nid=0xca waiting for monitor entry [0x000000000825f020]
java.lang.Thread.State: BLOCKED (on object monitor)
                at beans.ConnectionPool.getConnection(ConnectionPool.java:102)
                - waiting to lock <0xe0375410> (a beans.ConnectionPool)
                at beans.cus.ServiceCnt.getTodayCount(ServiceCnt.java:111)
                at beans.cus.ServiceCnt.insertCount(ServiceCnt.java:43)

"DB-Processor-3" daemon prio=5 tid=0x00928248 nid=0x8b waiting for monitor entry [0x000000000825d080]
java.lang.Thread.State: RUNNABLE
                at oracle.jdbc.driver.OracleConnection.isClosed(OracleConnection.java:570)
                - waiting to lock <0xe03ba2e0> (a oracle.jdbc.driver.OracleConnection)
                at beans.ConnectionPool.getConnection(ConnectionPool.java:112)
                - locked <0xe0386580> (a java.util.Vector)
                - locked <0xe0375410> (a beans.ConnectionPool)
                at beans.cus.Cue_1700c.GetNationList(Cue_1700c.java:66)
                at org.apache.jsp.cue_1700c_jsp._jspService(cue_1700c_jsp.java:120)

上图中，我们可以看到线程”DB-Processor-3“获取到了<0xe0375410>对象的锁，进入了临界区，另外2个线程”DB-Processor-13“、”DB-Processor-14“无法获取到锁，停留在Entry Set种，输出waiting to lock <0xe0375410>。

如果线程中出现大量的锁争用，可能是否个线程阻塞了，需要引起重视，轻则引发性能问题，重则是线上事故。

（2）死锁

如果两个线程相互都被对方的线程锁锁住，这样就造成了死锁。

"MyThread-2" daemon prio=5 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)


"MyThread-1" daemon prio=5 tid=0x00007f1d3825e000 nid=0x2141 waiting for monitor entry [0x00007f1d16fec000]
ava.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)

上图中，我们可以看到MyThread-1与MyThread-2在获取到了一个锁后，又尝试去获取另一个锁，但此时该锁已被对方获取，除非某一方先释放锁，否则这两个锁将无限等待下去。

（3）等待区等待

"RMI RenewClean-[172.16.5.19:28475]" daemon prio=10 tid=0x0000000041428800 nid=0xb09 in Object.wait() [0x00007f34f4bd0000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
                at java.lang.Object.wait(Native Method)
                - waiting on <0x00000000aa672478> (a java.lang.ref.ReferenceQueue$Lock)
                at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
                - locked <0x00000000aa672478> (a java.lang.ref.ReferenceQueue$Lock)
                at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run(DGCClient.java:516)
                at java.lang.Thread.run(Thread.java:662)

上图中JVM线程的状态是 java.lang.Thread.State: TIMED_WAITING (on object monitor)，说明线程调用了 java.lang.Object.wait(long timeout) 方法而进入了等待状态。

"Wait Set"中等待的线程状态就是 in Object.wait()，当线程获得了 Monitor进入临界区之后，如果发现线程继续运行的条件没有满足，它就调用对象（通常是被 synchronized 的对象）的wait()方法，放弃了Monitor，进入 "Wait Set" 队列中。只有当别的线程在该对象上调用了 notify()或notifyAll()方法， "Wait Set" 队列中线程才得到机会去竞争，但是只有一个线程获得对象的 Monitor，恢复到的运行态。