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

    参考资料：

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

    《Java线程Dump分析》

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

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

    《thread dump日志文件分析》

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

    目录

    一、线程快照的获取

            1、linux环境

            2、windos环境

    二、状态信息

            1、JVM线程状态

            2、Monitor

            3、调用修饰

            （1）locked

            （2）waiting to lock

            （3）waiting on

            （4）parking to wait for

            4、系统线程状态

    三、日志分析

            1、基本信息介绍

            2、常见案例

            （1）锁争用

            （2）死锁

            （3）等待区等待

    四、JCA工具

    五、常见问题思路

            1、CPU占用率很高

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

    一、线程快照的获取

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

            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的定义如下：

    1.     public enum State {
    2.         NEW,
    3.         RUNNABLE,
    4.         BLOCKED,
    5.         WAITING,
    6.         TIMED_WAITING,
    7.         TERMINATED;
    8.     }

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

    在这里插入图片描述

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

    • 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就像：

    1. synchronized(obj) {
    2. .........
    3.  
    4. }

            3、调用修饰

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

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

            （1）locked

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

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

            （2）waiting to lock

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

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

            （3）waiting on

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

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

            （4）parking to wait for

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

    1. "My thread" prio=10 tid=0x00007fffec082800 nid=0x17e8 waiting on condition [0x00007ffff14eb000]
    2.    java.lang.Thread.State: WAITING (parking)
    3.     at sun.misc.Unsafe.park(Native Method)
    4.     - parking to wait for  <0x00000007d6a33d30> (a java.util.concurrent.locks.ReentrantLock$FairSync)
    5.     at java.util.concurrent.locks.LockSupport.park(LockSupport.java:156)
    6.     at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811)
    7.     at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:842)
    8.     at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1178)
    9.     at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:201)
    10.     at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:262)
    11.     at LockTest.reentrantLock(LockTest.java:22)
    12.     at LockTest$2.run(LockTest.java:25)
    13.     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、基本信息介绍

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

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

    1. "DB-Processor-13" daemon prio=5 tid=0x003edf98 nid=0xca waiting for monitor entry [0x000000000825f000]
    2. java.lang.Thread.State: BLOCKED (on object monitor)
    3.                 at beans.ConnectionPool.getConnection(ConnectionPool.java:102)
    4.                 - waiting to lock <0xe0375410> (a beans.ConnectionPool)
    5.                 at beans.cus.ServiceCnt.getTodayCount(ServiceCnt.java:111)
    6.                 at beans.cus.ServiceCnt.insertCount(ServiceCnt.java:43)
    7.  
    8. "DB-Processor-14" daemon prio=5 tid=0x003edf98 nid=0xca waiting for monitor entry [0x000000000825f020]
    9. java.lang.Thread.State: BLOCKED (on object monitor)
    10.                 at beans.ConnectionPool.getConnection(ConnectionPool.java:102)
    11.                 - waiting to lock <0xe0375410> (a beans.ConnectionPool)
    12.                 at beans.cus.ServiceCnt.getTodayCount(ServiceCnt.java:111)
    13.                 at beans.cus.ServiceCnt.insertCount(ServiceCnt.java:43)
    14.  
    15. "DB-Processor-3" daemon prio=5 tid=0x00928248 nid=0x8b waiting for monitor entry [0x000000000825d080]
    16. java.lang.Thread.State: RUNNABLE
    17.                 at oracle.jdbc.driver.OracleConnection.isClosed(OracleConnection.java:570)
    18.                 - waiting to lock <0xe03ba2e0> (a oracle.jdbc.driver.OracleConnection)
    19.                 at beans.ConnectionPool.getConnection(ConnectionPool.java:112)
    20.                 - locked <0xe0386580> (a java.util.Vector)
    21.                 - locked <0xe0375410> (a beans.ConnectionPool)
    22.                 at beans.cus.Cue_1700c.GetNationList(Cue_1700c.java:66)
    23.                 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）死锁

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

    1. "MyThread-2" daemon prio=5 tid=0x00007f1d3825f800 nid=0x2142 waiting for monitor entry [0x00007f1d16eeb000]
    2. java.lang.Thread.State: BLOCKED (on object monitor)
    3. 	at com.jvm.study.threaddump.deadlock.DeadLockMock$2.run(DeadLockMock.java:31)
    4. 	- waiting to lock <0x00000000d8251168> (a java.lang.String)
    5. 	- locked <0x00000000d8251198> (a java.lang.String)
    6.  
    7.  
    8. "MyThread-1" daemon prio=5 tid=0x00007f1d3825e000 nid=0x2141 waiting for monitor entry [0x00007f1d16fec000]
    9. ava.lang.Thread.State: BLOCKED (on object monitor)
    10. 	at com.jvm.study.threaddump.deadlock.DeadLockMock$1.run(DeadLockMock.java:16)
    11. 	- waiting to lock <0x00000000d8251198> (a java.lang.String)
    12. 	- locked <0x00000000d8251168> (a java.lang.String)

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

            （3）等待区等待

    1. "RMI RenewClean-[172.16.5.19:28475]" daemon prio=10 tid=0x0000000041428800 nid=0xb09 in Object.wait() [0x00007f34f4bd0000]
    2. java.lang.Thread.State: TIMED_WAITING (on object monitor)
    3.                 at java.lang.Object.wait(Native Method)
    4.                 - waiting on <0x00000000aa672478> (a java.lang.ref.ReferenceQueue$Lock)
    5.                 at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
    6.                 - locked <0x00000000aa672478> (a java.lang.ref.ReferenceQueue$Lock)
    7.                 at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run(DGCClient.java:516)
    8.                 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，恢复到的运行态。

    四、JCA工具

            jca是IBM提供的线程快照的一个图形化分析工具，下载地址及使用方式都有介绍《传送门》

            我下载的是jca4611.jar，使用方式为java -jar jca4611.jar。

             导入线程快照

     然后我们就可以看到整改线程快照的基本情况，主要分为2个部门，Thread Status Analysis 与 Thread Method Analysis，分别从线程状态与线程执行的方法的角度来将线程分类。

             在Analysis菜单里，jca提供了Thread Status Analysis 与 Method Analysis的详细信息，以饼状图的形式将他们展示出来。

            Thread Status Analysis中以不同的颜色区分不同的线程状态，点击左侧线程后，右侧会展示该线程的详细信息。

            Method Analysis与上面类似。

            最后是Monitor Detail，会展示哪个线程持有锁，哪些线程在等待该锁的具体信息。

    在这里插入图片描述

     

    五、常见问题思路

            1、CPU占用率很高

            使用开头我们介绍的打出线程快照的方法，利用top定位到问题线程，然后排查代码，根据过往经验，一般是代码中循环有问题导致的，比如死循环等。

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

            导致这个现象的可能原因非常多，典型的如同上文jca分析中的Monitor Detail部分，一个持有锁的线程执行缓慢导致大量线程无法获取到锁而进入阻塞状态，需要多次打印线程快照后进行比对后定位，个人经验往往是数据库慢sql或者I/O、网络原因导致。

  • 相关阅读:
    【数据结构】手撕单链表
    辅助知识-第7 章 知识产权与标准规范
    041：vue中 el-table每个单元格包含多个数据项处理
    FFmpeg 基础模块：容器相关的 API 操作
    目标检测YOLO实战应用案例100讲-基于YOLOv5自适应损失权重的生活垃圾目标检测模型
    逻辑卷LVM和交换分区
    【MAX7800实现KWS20 demo演示】
    师傅教你~LNMP源码搭建
    基于java web的企业财务管理系统设计与实现
    LDAP——实现用户统一登录管理
  • 原文地址：https://blog.csdn.net/wzngzaixiaomantou/article/details/124766869