JVM 线程dump 导出和分析
前言
-
线程dump是非常有用的诊断java应用问题的工具，每一个java虚拟机都有及时生成显示所有线程在某一点状态的线程dump的能力。虽然各个java虚拟机线程dump打印输出格式上略微有一些不同，但是线程dump出来的信息包含线程基本信息；线程的运行状态、标识和调用的堆栈；调用的堆栈包含完整的类名，所执行的方法，如果可能的话还有源代码的行数。
-
JVM中的许多问题都可以使用线程dump文件来进行诊断，其中比较典型的包括线程阻塞，CPU使用率过高，JVM Crash，堆内存不足和类装载等问题。
导出
1、查询java进程pid
- 使用jps [-l]命令查看本机所有java进程pid
jps [-l]
image.png
2、使用top查看目前正在运行的进程使用系统资源情况
top
image.png
image.png
当前占用cpu最高26.5%的进程为27796的java程序
3、导出指定进程pid所有线程信息
- 使用jstack将所有线程信息导出到指定文件中(jstack了解传送门)
1)将所有线程信息输入到指定文件中
jstack [-l] pid > xxx.log
image.png
2)-F （当'jstack [-l] pid'没有响应，强制导出堆栈dump）
jstack -F [-m] [-l] pid >xxx.log
4、分析
线程状态介绍
-
死锁，Deadlock（重点关注） :一般指多个线程调用间，进入相互资源占用，导致一直等待无法释放的情况。
-
执行中，Runnable :一般指该线程正在执行状态中，该线程占用了资源，正在处理某个请求，有可能正在传递SQL到数据库执行，有可能在对某个文件操作，有可能进行数据类型等转换。
-
等待资源，Waiting on condition（重点关注） :等待资源，或等待某个条件的发生。具体原因需结合 stacktrace来分析。
1、如果堆栈信息明确是应用代码，则证明该线程正在等待资源。一般是大量读取某资源，且该资源采用了资源锁的情况下，线程进入等待状态，等待资源的读取。
又或者，正在等待其他线程的执行等。
2、如果发现有大量的线程都在处在 Wait on condition，从线程 stack看，正等待网络读写，这可能是一个网络瓶颈的征兆。因为网络阻塞导致线程无法执行。
2.1、一种情况是网络非常忙，几乎消耗了所有的带宽，仍然有大量数据等待网络读写；
2.2、另一种情况也可能是网络空闲，但由于路由等问题，导致包无法正常的到达。
3、另外一种出现 Wait on condition的常见情况是该线程在 sleep，等待 sleep的时间到了时候，将被唤醒。 -
等待获取监视器，Waiting on monitor entry（重点关注）
-
对象等待中，Object.wait() 或 TIMED_WAITING
Waiting for monitor entry 和 in Object.wait()：
Monitor(Monitor的深入理解传送门)是 Java中用以实现线程之间的互斥与协作的主要手段，它可以看成是对象或者 Class的锁。每一个对象都有，也仅有一个 monitor。
从下图中可以看出，每个 Monitor在某个时刻，只能被一个线程拥有，该线程就是 “Active Thread”，而其它线程都是 “Waiting Thread”，分别在两个队列 “ Entry Set”和 “Wait Set”里面等候。
在 “Entry Set”中等待的线程状态是 “Waiting for monitor entry”，而在 “Wait Set”中等待的线程状态是 “in Object.wait()”
Java Monitor
- 暂停，Suspended
- 阻塞，Blocked（重点关注） ：是指当前线程执行过程中，所需要的资源长时间等待却一直未能获取到，被容器的线程管理器标识为阻塞状态，可以理解为等待资源超时的线程。
- 停止，Parked
jvm_27796.log展示
image.png
stack trace实例分析
"consumer_redirectUrl_topic_jmq206_1546013217302" daemon prio=10 tid=0x00007f1bf03f6800 nid=0x693e waiting on condition [0x00007f1b38388000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000f76e21a0> (a java.util.concurrent.CountDownLatch$Sync)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1033)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1326)
at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:282)
at com.jd.jmq.common.network.netty.ResponseFuture.await(ResponseFuture.java:133)
at com.jd.jmq.common.network.netty.NettyTransport.sync(NettyTransport.java:241)
at com.jd.jmq.common.network.netty.failover.FailoverNettyClient.sync(FailoverNettyClient.java:94)
at com.jd.jmq.client.consumer.GroupConsumer.pull(GroupConsumer.java:246)
at com.jd.jmq.client.consumer.GroupConsumer$QueueConsumer.run(GroupConsumer.java:445)
at java.lang.Thread.run(Thread.java:745)
Locked ownable synchronizers:
- None
- 线程名：consumer_redirectUrl_topic_jmq206_1546013217302
- 线程优先级：prio=10
- java线程的identifier：tid=0x00007f1bf03f6800
- native线程的identifier：nid=0x693e
- 线程的状态：waiting on condition [0x00007f1b38388000]
java.lang.Thread.State: TIMED_WAITING (parking) - 线程栈起始地址：[0x00007f1b38388000]
找出某进程中要分析的线程ID
top -H -p <pid>
image.png
image.png
将线程ID转换为16进制后，在线程dump文件中搜索相关信息
例如：27840==》6cc0
image.png
"System_Clock" daemon prio=10 tid=0x00007f1c2cbc6800 nid=0x6cc0 runnable [0x00007f1c24872000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000c0c9d918> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1090)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Locked ownable synchronizers:
- None
