美文网首页优化及排查JVM线上问题定位
jstack分析线程快照的三步曲及CPU占用过高和死锁问题的排查

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

作者: Acamy丶 | 来源:发表于2018-11-11 11:12 被阅读21次

    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死锁范例以及如何分析死锁

    相关文章

      网友评论

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

        本文链接:https://www.haomeiwen.com/subject/dsjxfqtx.html