jstack配合top命令分析CPU飙高、程序死锁问题
jstack：Java堆栈跟踪工具
jstack（Stack Trace for Java)命令用于生成虚拟机当前时刻的线程快照（一般称为threaddump或者javacore文件）。线程快照就是当前虚拟机内每一条线程正在执行的方法堆栈的集合，生成线程快照的主要目的是定位线程出现长时间停顿的原因，如线程间死锁、死循环、请求外部资源导致的长时间等待等都是导致线程长时间停顿的常见原因。线程出现停顿的时候通过jstack来查看各个线程的调用堆栈，就可以知道没有响应的线程到底在后台做什么事情，或者等待什么资源。jstack的官方文档地址为：https://docs.oracle.com/javase/8/docs/technotes/tools/unix/jstack.html。
jstack命令格式：jstack [option] vmid
jstack的主要option选项如下：
- -F：当正常输出的请求不被响应时，强制输出线程堆栈。
- -l：除堆栈外，显示关于锁的附加信息。
- -m：除打印java线程堆栈外，还会输出native方法线程堆栈。
Java线程状态转化
官网线程状态介绍：https://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/tooldescr034.html，如下所示
- NEW：创建了线程但是还没有调用start方法
- RUNABLE：线程正在JVM中执行，有可能在等待CPU时间片轮转
- TIMED_WAITING：线程等待指定的时间，一般则是处于sleep方法，wait方法，join等操作，正在等待时间
- WAITING：线程无限期的等待，一般是wait，join等方法没有指定时间
- BLOCKED：线程等待获取监视器锁而处于阻塞状态
- TERMINATED：线程退出
关于线程各个状态的转化，从网上找了一张图，画的挺详细的。
jstack配合top命令分析CPU飙高问题
一般分析CPU飙高的步骤如下：
- 先用top 命令在机器上分析出当前占用cpu的进程，
- 通过top -H -p <pid> 查看进程内各个线程的资源占用
- top -H -p <pid>命令输出的是这些线程的pid，然后通过jstack命令导出线程dump信息。把线程pid（对应线程dump内容中的nid，nid是16进制表示的）转换成十六进制，然后在线程dump文件中搜索即可找到对应的线程。
创建一个springboot工程，controller程序如下，然后通过package -Dmaven.test.skip=true打包之后放到Linux上运行：
package com.wkp.jvm.chapter2;
import java.util.List;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;
@RestController
public class CpuController {
Logger log=LoggerFactory.getLogger(CpuController.class);
/**
* 演示死循环
*/
@RequestMapping("/loop")
public List<Long> loop(){
log.info("演示死循环============");
while(true){
}
}
private Object lock1 = new Object();
private Object lock2 = new Object();
/**
* 演示死锁
*/
@RequestMapping("/deadlock")
public String deadlock() {
log.info("演示死锁============");
new Thread(()->{
synchronized(lock1) {
try {Thread.sleep(1000);} catch(Exception e) {}
synchronized(lock2){
System.out.println("Thread 1 over");
}
}
}).start();
new Thread(()->{
synchronized(lock2) {
try {Thread.sleep(1000);} catch(Exception e) {}
synchronized(lock1){
System.out.println("Thread 2 over");
}
}
}).start();
return "deadlock";
}
}
通过http://ip:port/loop访问触发程序死循环，多访问几次之后，在Linux上通过top命令可以看到我们的Java应用程序CPU占用越来越高，系统负载也逐渐升高。
[root@wkp ~]# top top - 18:13:31 up 321 days, 3:37, 4 users, load average: 13.14, 9.15, 4.72 Tasks: 128 total, 1 running, 108 sleeping, 19 stopped, 0 zombie Cpu(s): 99.8%us, 0.2%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Mem: 8193352k total, 7702892k used, 490460k free, 9204k buffers Swap: 0k total, 0k used, 0k free, 75428k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 26295 root 20 0 4524m 378m 13m S 184.8 4.7 13:51.51 java
通过top命令，我们观察到java进程26295占用CPU很高，系统负载也越来越高.然后我们通过top -Hp 26295查看进程的线程占用情况。
top -Hp pid 可以查看某个进程的线程信息，其中-H 显示线程信息，-p指定pid
[root@wkp~]# top -Hp 26295 top - 18:16:39 up 321 days, 3:40, 4 users, load average: 13.24, 11.14, 6.33 Tasks: 31 total, 12 running, 19 sleeping, 0 stopped, 0 zombie Cpu(s): 99.8%us, 0.2%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Mem: 8193352k total, 7673852k used, 519500k free, 9752k buffers Swap: 0k total, 0k used, 0k free, 75508k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 26379 root 20 0 4524m 378m 13m R 15.6 4.7 2:36.42 java 26384 root 20 0 4524m 378m 13m R 15.6 4.7 1:41.46 java 26388 root 20 0 4524m 378m 13m R 15.6 4.7 1:10.34 java 5673 root 20 0 4524m 378m 13m R 15.6 4.7 1:07.09 java 26386 root 20 0 4524m 378m 13m R 15.3 4.7 1:17.68 java 26380 root 20 0 4524m 378m 13m R 15.0 4.7 2:18.31 java 26381 root 20 0 4524m 378m 13m R 15.0 4.7 2:05.06 java 26382 root 20 0 4524m 378m 13m R 15.0 4.7 1:45.69 java 26385 root 20 0 4524m 378m 13m R 15.0 4.7 1:20.29 java 26387 root 20 0 4524m 378m 13m R 15.0 4.7 1:13.59 java 5801 root 20 0 4524m 378m 13m R 15.0 4.7 0:51.41 java 26383 root 20 0 4524m 378m 13m R 14.6 4.7 1:55.11 java 26295 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.00 java 26305 root 20 0 4524m 378m 13m S 0.0 4.7 0:02.63 java 26306 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.21 java 26307 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.20 java 26311 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.36 java 26312 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.00 java 26314 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.01 java 26327 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.00 java 26328 root 20 0 4524m 378m 13m S 0.0 4.7 0:03.67 java 26329 root 20 0 4524m 378m 13m S 0.0 4.7 0:01.33 java 26330 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.00 java 26331 root 20 0 4524m 378m 13m S 0.0 4.7 0:01.79 java 26376 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.06 java 26377 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.00 java 26378 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.13 java 26389 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.13 java 26390 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.11 java 26391 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.00 java 26392 root 20 0 4524m 378m 13m S 0.0 4.7 0:00.16 java
然后我们执行 jstack 26295 > threadstack.txt 命令，将线程dump信息输出到txt文件中，然后下载下来。因为jstack打印出的线程堆栈中线程号是16进制的，所以我们从上面top -Hp命令打印出的线程中选取第一个26379，通过 printf "%x\n" 26379转为16进制得到670b。
[wkp@wkp4 Desktop]$ printf "%x\n" 26379 670b
然后我们通过16进制的线程号670b，在threadstack.txt文件中搜索，可以搜到对应的线程（内容太多了，只贴了一小部分）：可以看到 at com.wkp.jvm.chapter2.CpuController.loop(CpuController.java:21)，第21行就对应我们的while（true）死循环，这样就找到了CPU飙高的原因了。
2019-09-24 18:17:55 Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.162-b12 mixed mode): //=========省略=============================================== "http-nio-9999-exec-1" #16 daemon prio=5 os_prio=0 tid=0x00007fa06943c800 nid=0x670b runnable [0x00007fa01b3e9000] java.lang.Thread.State: RUNNABLE at com.wkp.jvm.chapter2.CpuController.loop(CpuController.java:21) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) //=========省略=============================================== "C1 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007fa06813e000 nid=0x66d9 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007fa06813b000 nid=0x66d8 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007fa068106800 nid=0x66ca in Object.wait() [0x00007fa054267000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x0000000082ebc820> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143) - locked <0x0000000082ebc820> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:212) "VM Thread" os_prio=0 tid=0x00007fa0680fa000 nid=0x66c7 runnable "GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007fa06801e000 nid=0x66c2 runnable "GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007fa068020000 nid=0x66c3 runnable "VM Periodic Task Thread" os_prio=0 tid=0x00007fa068146000 nid=0x66db waiting on condition JNI global references: 913
下面我们对线程dump日志的格式做个介绍，以 "http-nio-9999-exec-1" #16 daemon prio=5 os_prio=0 tid=0x00007fa06943c800 nid=0x670b runnable [0x00007fa01b3e9000]为例：
- http-nio-9999-exec-1：线程名称
- daemon线程类型：线程分为守护线程 (daemon) 和非守护线程 (non-daemon) 两种，通常都是守护线程
- prio=5：线程优先级：默认为5，数字越大优先级越高
- tid=0x00007fa06943c800JVM线程的id：JVM内部线程的唯一标识，通过 java.lang.Thread.getId()获取，通常用自增的方式实现；
- nid=0x670b系统线程id：对应的系统线程id（Native Thread ID)，可以通过 top -Hp 命令进行查看，线程id是十六进制的形式
- runnable：系统线程的状态
- [0x00007fa01b3e9000]起始栈地址：线程堆栈调用的起始内存地址
其他的线程名含义：
- "C1 CompilerThread1"和"C1 CompilerThread0"是Java的编译线程
- "Finalizer"是垃圾回收时，被标记的对象被放到F-Queue队列中，Finalizer线程取出队列中的对象进行处理
- "GC task thread#0 (ParallelGC)" 和"GC task thread#1 (ParallelGC)" 是ParallelGC垃圾收集器的工作线程
jstack配合top命令查找死锁
我们演示一下死锁问题的查找：同样是启动上面的示例springboot程序，然后访问 http://ip:port/deadlock触发程序死锁。然后通过jstack导出线程dump文件，在文件末尾可以看到如下内容：
Found one Java-level deadlock: ============================= "Thread-5": waiting to lock monitor 0x00007fc978003778 (object 0x00000000833d0c20, a java.lang.Object), which is held by "Thread-4" "Thread-4": waiting to lock monitor 0x00007fc978003568 (object 0x00000000833d0c30, a java.lang.Object), which is held by "Thread-5" Java stack information for the threads listed above: =================================================== "Thread-5": at com.wkp.jvm.chapter2.CpuController.lambda$deadlock$1(CpuController.java:46) - waiting to lock <0x00000000833d0c20> (a java.lang.Object) - locked <0x00000000833d0c30> (a java.lang.Object) at com.wkp.jvm.chapter2.CpuController$$Lambda$343/408916933.run(Unknown Source) at java.lang.Thread.run(Thread.java:748) "Thread-4": at com.wkp.jvm.chapter2.CpuController.lambda$deadlock$0(CpuController.java:38) - waiting to lock <0x00000000833d0c30> (a java.lang.Object) - locked <0x00000000833d0c20> (a java.lang.Object) at com.wkp.jvm.chapter2.CpuController$$Lambda$342/620117450.run(Unknown Source) at java.lang.Thread.run(Thread.java:748) Found 1 deadlock.
可以看到线程dump中已经把出现死锁的线程打印出来了，Thread-4和Thread-5互相等待对方持有的锁。
其实关于线程的dump和死锁检查等，JDK提供的有可视化的工具，比如 jconsole和jvisualvm 也是可以做到的。
另外，我们还可以通过如下 Thread.getAllStackTraces() 打印线程信息
@RequestMapping("/getAllThreadStack")
public void getAllThreadStack() {
for (Entry<Thread, StackTraceElement[]> stackTrace : Thread
.getAllStackTraces().entrySet()) {
Thread thread = (Thread) stackTrace.getKey();
StackTraceElement[] stack = (StackTraceElement[]) stackTrace
.getValue();
if (thread.equals(Thread.currentThread())) {
continue;
}
System.out.println("线程：" + thread.getName());
for (StackTraceElement stackTraceElement : stack) {
System.out.println(stackTraceElement);
}
}
}
到此这篇关于jstack配合top命令分析CPU飙高、程序死锁问题的文章就介绍到这了,更多相关Java 程序死锁内容请搜索我们以前的文章或继续浏览下面的相关文章希望大家以后多多支持我们！
相关推荐
-
如何解决Java多线程死锁问题
死锁问题 死锁定义 多线程编程中,因为抢占资源造成了线程无限等待的情况,此情况称为死锁. 死锁举例 注意:线程和锁的关系是:一个线程可以拥有多把锁,一个锁只能被一个线程拥有. 当两个线程分别拥有一把各自的锁之后,又尝试去获取对方的锁,这样就会导致死锁情况的发生,具体先看下面代码: /** * 线程死锁问题 */ public class DeadLock { public static void main(String[] args) { //创建两个锁对象 Object lock1 = new
-
一篇文章学会java死锁与CPU 100%的排查
目录 01 Java死锁排查和解决 1.啥是死锁? 2.为啥子会出现死锁? 3.怎么排查代码中出现了死锁?[重点来了] 第一个姿势:使用 jps + jstack 第二个姿势:使用jconsole 第三个姿势:使用Java Visual VM 4.如何避免死锁? 02.Java CPU 100% 排查技巧 第一个姿势,步骤有点多,难度四星 第二个姿势,待开发[奸笑脸] 03 推荐两个高效排查问题工具 04 总结 05 彩蛋-另一个姿势 00 本文简介 作为一名搞技术的程序猿或者是攻城狮,想必你应
-
Java检测死锁案例
导致死锁的程序 package com.study.train; import java.io.IOException; import java.lang.management.ManagementFactory; import java.lang.management.ThreadInfo; import java.lang.management.ThreadMXBean; import java.lang.reflect.Field; import java.util.*; import j
-
Java并发编程之死锁相关知识整理
一.什么是死锁 所谓死锁是指多个线程因竞争资源而造成的一种僵局(互相等待),若无外力作用,这些进程都将无法向前推进 二.死锁产生的条件 以下将介绍死锁的必要条件,只要系统发生死锁,这些条件必然成立,而只要上述条件之一不满足,就不会发生死锁 互斥条件 进程要求对所分配的资源(如打印机〉进行排他性控制,即在一段时间内某资源仅为一个进程所占有.此时若有其他进程请求该资源,则请求进程只能等待 不可剥夺条件 进程所获得的资源在未使用完毕之前,不能被其他进程强行夺走,即只能由获得该资源的进程自己来释放(只能
-
java定位死锁的三种方法（jstack、Arthas和Jvisualvm）
目录 死锁 死锁发生的原因 死锁发生的条件 1:通过jstack定位死锁信息 1.2:查看死锁线程的pid 2:通过Arthas工具定位死锁 3. 通过 Jvisualvm 定位死锁 死锁的预防 总结 死锁 死锁:是指两个或两个以上的进程在执行过程中,因争夺资源而造成的一种互相等待的现象,若无外力作用,它们都将无法推进下去. 死锁发生的原因 死锁的发生是由于资源竞争导致的,导致死锁的原因如下: 系统资源不足,如果系统资源充足,死锁出现的可能性就很低. 进程(线程)运行推进的顺序不合适. 资源分配
-
jstack配合top命令分析CPU飙高、程序死锁问题
jstack:Java堆栈跟踪工具 jstack(Stack Trace for Java)命令用于生成虚拟机当前时刻的线程快照(一般称为threaddump或者javacore文件).线程快照就是当前虚拟机内每一条线程正在执行的方法堆栈的集合,生成线程快照的主要目的是定位线程出现长时间停顿的原因,如线程间死锁.死循环.请求外部资源导致的长时间等待等都是导致线程长时间停顿的常见原因.线程出现停顿的时候通过jstack来查看各个线程的调用堆栈,就可以知道没有响应的线程到底在后台做什么事情,或者等待
-
linux下cpu飙高原因排查过程详解
目录 前言 开始 步骤 排查 前言 cpu飙高是很常见的线上问题,这都不会的话,属实有点拉跨 兄弟萌不用慌,来我教你一套连招 开始 先来个项目,整个api,到时候我们请求/cpu/{count}就能手动拉高cpu,机智鬼~ @GetMapping("/cpu/{count}") public long cpuTest(@PathVariable("count") long count) { long number = 0; for (int i = 0; i <
-
Linux下使用python调用top命令获得CPU利用率
本文定位:想通过python调用top命令获取cpu使用率但暂时没有思路的情况. 如果单纯为了获得cpu的利用率,通过top命令重定向可以轻松实现,命令如下: 复制代码 代码如下: top -bi > cpuHistory.log 或 复制代码 代码如下: top -bi | tee cpuHistory.log 这个就不解释了,不懂的朋友查询下top的帮助文档.这里要实现的是通过python调用top命令,并获得cpu的利用率信息. 用过popen的朋友很快就能想到类似如下的代码(这个是我第
-
使用top命令分析linux系统性能的详解
linux的top命令简介 top命令是Linux下常用的性能分析工具,能够实时显示系统中各个进程的资源占用状况,类似于Windows的任务管理器. top显示系统当前的进程和其他状况,是一个动态显示过程,即可以通过用户按键来不断刷新当前状态.如果在前台执行该命令,它将独占前台,直到用户 终止该程序为止. 比较准确的说,top命令提供了实时的对系统处理器的状态监视.它将显示系统中CPU最"敏感"的任务列表.该命令可以按CPU使用.内存使用和执行时间 对任务进行排序:而且该命令的很多特性
-
linux top命令详解与输出结果说明
top命令是Linux下常用的性能分析工具,能够实时显示系统中各个进程的资源占用状况,常用于服务端性能分析. top命令说明 [www.jb51.net@jb51 ~]$ top top - 16:07:37 up 241 days, 20:11, 1 user, load average: 0.96, 1.13, 1.25 Tasks: 231 total, 1 running, 230 sleeping, 0 stopped, 0 zombie Cpu(s): 12.7%us, 8.4%sy
-
Linux中top命令输出详解
前言 Linux下的top命令我相信大家都用过,自从我接触Linux以来就一直用top查看进程的CPU和MEM排行榜.但是top命令的其他输出结果我都没有了解,这些指标都代表什么呢,什么情况下需要关注呢?以及top命令输出结果的来源数据是什么呢,又是怎么一个计算原理呢? 演示环境 # uname -a Linux VM_1_11_centos 3.10.0-693.el7.x86_64 #1 SMP Tue Aug 22 21:09:27 UTC 2017 x86_64 x86_64 x86_6
-
linux top命令详解
top 命令主要用于查看进程的相关信息,同时它也会提供系统平均负载,cpu 信息和内存信息.下面的截图展示了 top 命令默认提供的信息: 系统平均负载 top 命令输出中的第一行是系统的平均负载,这和 uptime 命令的输出是一样的: 13:05:49 表示系统当前时间. up 7 days 表示系统最后一次启动后总的运行时间. 1 user 表示当前系统中只有一个登录用户. load average: 0.01, 0.04, 0.00 表示系统的平均负载,最后的三个数字分别表示最后一分钟的
-
批处理模式下运行 top 命令的方法
top 命令 是每个人都在使用的用于 监控 Linux 系统性能 的最好的命令.你可能已经知道 top 命令的绝大部分操作,除了很少的几个操作,如果我没错的话,批处理模式就是其中之一. 大部分的脚本编写者和开发人员都知道这个,因为这个操作主要就是用来编写脚本. 如果你不了解这个,不用担心,我们将在这里介绍它. 什么是 top 命令的批处理模式 批处理模式允许你将 top 命令的输出发送至其他程序或者文件中. 在这个模式中,top 命令将不会接收输入并且持续运行,直到迭代次数达到你用 -n 选项指
-
Linux监控cpu以及内存使用情况之top命令(详解)
top命令是Linux下常用的性能分析工具,比如cpu.内存的使用,能够实时显示系统中各个进程的资源占用状况,类似于Windows的任务管理器. top显示系统当前的进程和其他状况,是一个动态显示过程,即可以通过用户按键来不断刷新当前状态.如果在前台执行该命令,它将独占前台,直到用户终止该程序为止. 比较准确的说,top命令提供了实时的对系统处理器的状态监视.它将显示系统中CPU最"敏感"的任务列表.该命令可以按CPU使用.内存使用和执行时间对任务进行排序:而且该命令的很多特性都可以通
-
.NET医院公众号系统线程CPU双高问题分析
一:背景 1. 讲故事 上周四有位朋友加wx咨询他的程序出现 CPU + 线程 双高的情况,希望我能帮忙排查下,如下图: 从截图看只是线程爆高,没看到 cpu 爆高哈