jstack分析线程快照的三步曲及CPU占用过高和死锁问题的排查

jstack(Stack Trace For Java, 官方链接)用于生成java虚拟机某个进程在当前时刻的线程快照(一般称为threaddump或javacore文件,由线程的调用堆栈组成),用来定位线程长时间停顿的原因,如死循环、死锁等。

一般在用该工具时主要分为三步:

  1. 获取进程id

    方法1: jps -l

    方法2: ps -ef|grep java

    方法3: lsof -i:<port>

    上述三个方法根据具体情况选择使用,方法1最简便(适合java进程少的情况),方法2信息更详尽,方法3则适合有多个java进程,根据方法1可能分辨不出来想找的进程,而需要通过端口号进行定位。

  2. 获取进程中的线程状态

    top -Hp <pid>

    注意该命令只能在linux中使用,而在macOS上不能使用。因为linux将线程作为轻量级进程也分配了pid,而macOS并没有这么处理。

    如果通过上述命令我们发现进程中的某个线程指标不正常,想重点关注,这时需要将线程的pid通过下面命令转化为十六进进制,方便在线程快照信息中查找。

echo 'obase=16; ibase=10; <pid>' | bc | tr '[A-Z]' '[a-z]'

  1. 查看并分析线程快照信息

    jstack <pid>命令可以在控制台打印线程快照信息, jstack <pid> > <path>可以将线程快照信息输出到文件。如下为打印出来的一条线程快照,由10个部分组成。

    image-20181111102804259
    1. 线程名称,如果程序中没有显示给线程命名则显示默认名称
    2. 线程序号,相当于程序所有线程的一个编号
    3. 线程优先级,java中线程的默认优先级为5
    4. 线程系统优先级
    5. 线程id
    6. 线程native id,在linux中对应线程的轻量级进程id,十六进制,通过该字段都与top命令中的线程对应起来。
    7. 线程描述
    8. 线程栈的起始地址
    9. 线程状态
    10. 线程执行堆栈,具体到代码的行数

    需要注意的是执行该命令时当前用户必须为启动该进程的用户,否则会失败,即使是root用户也不行。

接下来将通过两个实例来对该工具的使用进行详细说明:

实例1: 利用线程快照分析CPU占用过高的原因

用于演示CPU示例代码如下: 启动三个线程,且某个线程获取唯一的锁后一直没有释放,可想而知,另外两个线程将处于阻塞状态。

import java.util.UUID;

public class HighCPUCase {
    public static Object lock = new Object();

    public static void main(String[] args) {
        new Thread(new Task(), "task1").start();
        new Thread(new Task(), "task2").start();
        new Thread(new Task(), "task3").start();
    }

    static class Task implements Runnable{
        @Override
        public void run(){
            synchronized (lock){
                while (true){
                    System.out.println(UUID.randomUUID().toString());
                }
            }
        }
    }
}

现在用文章开始的三步曲来验证我们的猜想。

  1. 首先获取进程id

    image-20181110225814867
  2. 获取进程中消耗CPU最高的线程

    image-20181110230019853

    将23068用如下命令转化为16进制后为5a1c

    image-20181110230321690
  3. 查看并分析线程快照

    image-20181110231223530

    ​ 上图中蓝色线框为我们需要重点关注的内容,可以看到5a1c(由第2步得到)对应的线程为task1,该线程处于RUNNABLE状态,且下在执行HighCPUCase.java中的第17行,而线程task2和task3都因为等待锁而处于BLOCKED状态。仔细观察可以发现task2和task3等待的锁与task1获得的锁完全相同。

    ​ 由此我们下结论,CPU高的原因是因为线程task1,而它正在执行HighCPUCase.java中的第17行,线程task2和task3处于阻塞状态是因为task1获得唯一一把锁后一直没有释放。然后我们根据结论再去看代码,分析得完全没毛病。

实例2: 利用线程快照分析死锁

下面为演示死锁的代码,模拟有两个线程A,B, 两把锁1,2,当线程1成功拿到锁1尝试去拿锁2发现拿不到,而此时线程2成功拿到锁2尝试去拿锁1也拿不到,谁也不让谁就只能干耗着了,导致程序一直不能结束。

public class DeadLockCase {
    public static void main(String[] args){
        Object o1 = new Object();
        Object o2 = new Object();
        new Thread(new SyncThread(o1, o2),  "t1").start();
        new Thread(new SyncThread(o2, o1),  "t2").start();
    }

    static class SyncThread implements Runnable {
        private Object lock1;
        private Object lock2;

        public SyncThread(Object o1, Object o2){
            this.lock1 = o1;
            this.lock2 = o2;
        }

        @Override
        public void run() {
            String name = Thread.currentThread().getName();
            System.out.println(name + " acquiring lock on " + lock1);
            synchronized (lock1) {
                System.out.println(name + " acquired lock on " + lock1);
                work();
                System.out.println(name + " acquiring lock on " + lock2);
                synchronized (lock2) {
                    System.out.println(name + " acquired lock on " + lock2);
                    work();
                }
                System.out.println(name + " released lock on " + lock2);
            }
            System.out.println(name + " released lock on " + lock1);
        }

        private void work() {
            try {
                //模拟死锁的关键,保证线程1只能获取一个锁,而线程2能获取到另一个锁
                Thread.sleep(3000);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }
    }
}

运行上面代码输出如下,可以看到符合我们的预期:

image-20181110235104076

下面还是通过线程快照来反推:

  1. 首先拿到进程id

    image-20181110235201192
  2. 查看进程内的线程情况

    image-20181110235336030

    可以看到所有线程无异常指标,这一步还不知道哪一个线程有问题。

    23152对就的十六进制数为5a70, 23144对应的十六进制数为5a68,接下来就重点关注这两个。

  3. 查看线程快照

    开始部分:细心观察发现两个线程处于BLOCKED状态是因为在等相互之间的锁。

    image-20181111000447280

    结尾部分:很明确的告诉了你发现了一个java级别死锁,t2在待t1手上的锁,t1在等t2手上的锁。

在实际生产中肯定比这本文中涉及到的两个例子复杂,但如果能先把基础的学会,碰到问题也不会慌而是学会去分解复杂的问题,大而化小,最后方能解决问题。

参考文章:

如何使用jstack分析线程状态

Java死锁范例以及如何分析死锁

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 159,015评论 4 362
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 67,262评论 1 292
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 108,727评论 0 243
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 43,986评论 0 205
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 52,363评论 3 287
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 40,610评论 1 219
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 31,871评论 2 312
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 30,582评论 0 198
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 34,297评论 1 242
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 30,551评论 2 246
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 32,053评论 1 260
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 28,385评论 2 253
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 33,035评论 3 236
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 26,079评论 0 8
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,841评论 0 195
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 35,648评论 2 274
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 35,550评论 2 270

推荐阅读更多精彩内容