性能文章>XPocket插件jstack_x助力线程问题排查>

XPocket插件jstack_x助力线程问题排查原创

https://a.perfma.net/img/2382850
1年前
9324222

在程序开发过程中,开发人员通常会遇到许多线上问题,这些问题可能是代码Bug导致的,也可能是性能问题引起的。这些线上问题都会通过CPU飙升、GC频繁、抛出OOM异常等情况表现出来,这些问题的根因很可能是由于线程或线程池使用不当造成的。为了尽快定位根因,可以使用jstack_x插件以线程为切入点进行排查。
XPocket插件jstack_x在JDK自带的jstack工具上进行了增强,除了支持java栈和本地栈的输出外,还可以从锁的角度查看等待或持有锁的线程,另外还可以通过线程名称和nid过滤出特定的线程。
XPocket传送门:XPocket
jstack_x插件传送门:jstack_x
大家可根据本篇文章中的实例体验jstack_x插件,也可以通过此插件排查线上问题,如果有任何问题或想法,也可以去jstack_x插件讨论组进行讨论交流。
为了帮助使用者快速上手,我会举几个简单的小实例,然后用jstack_x插件进行根因排查和定位。这几个实例过于简单,不过实际线上许多问题都是这几个实例的复杂版,在虚拟机和操作系统上表示出来的结果通常都是一样的。我会通过这几个实例来介绍一下使用jstack_x插件排查问题的过程。

典型案例1-线程的cpu使用率飙升

对于死循环或者占用cpu高的Java线程来说,可通过jstack_x插件进行排查,举个简单的实例如下:

public class Test2 {
    static class MyThread extends Thread {
        public void run() { // 死循环,模拟实际过程中的死循环,或CPU密集型计算过程,目的是消耗CPU
            int i = 0;
            while (true) {
                i++;
            }
        }
    }
 
    public static void main(String args[]) throws InterruptedException {
        new MyThread().start();
        Thread.sleep(10000000);
    }
}

现在使用jstack_x来定位问题。如下:
image.png
XPocket支持管道操作,所以可通过top_x.cpu_p命令获取到占用CPU最高的Java进程pid,然后attach,这样在后续操作jstack_x中的任何命令时,都可以省略pid的输入。

获取占用进程最高的线程pid可通过如下top_x.cpu_t命令,执行结果如下图所示。
image.png

可以看到19590的线程的CPU使用率最高,为%93.8,为了快速定位到最耗时的业务代码,最好的办法就是查看调用栈,可通过stack -t 19590获取调用栈:
image.png

Test2$MyThread内部类中的run()方法的运行状态为RUNNABLE,所以这个方法中有CPU密集型运算,或者可能是代码Bug,如死循环等。此时就要查看run()方法的业务代码来改进了。

典型案例2-无意中创建了超量的线程

如果每次都new线程而不结束,最直观的现象就是会导致内存占用量上升,最终可能会抛出如下异常:

java.lang.OutOfMemoryError: unable to create new native thread

在内存占用量上升的过程中,有可能会造成频繁的GC,因为创建出来的线程除了本身占用的内存外,还可能会引用一些大的对象,导致这些对象长期释放不了而引起频繁的GC。所以在看到系统的这些表现时,我们首先需要排查线程的问题。下面举个线程泄漏的小实例,如下:

import java.util.concurrent.Executor;
import java.util.concurrent.Executors;
 
public class Test3 {
 
    public static void main(String[] args) throws Exception {
        Test3 t = new Test3();
        while (true) {
            Thread.sleep(1000);
            t.test();
        }
    }
 
    private void test() {
        for (int i = 0; i < 10; i++) {
            Executor mExecutors = Executors.newFixedThreadPool(3);
            for (int j = 0; j < 3; j++) {
                mExecutors.execute(new Runnable() {
                    @Override
                    public void run() {
                        System.out.println("execute");
                    }
                });
            }
        }
    }
}

每次调用test()方法都会创建一个有3个线程的线程池,当test()方法结束后,创建出的线程池没有shoutdown(),又由于线程池的实现原理,这些线程会变为GC Roots的强引用,这样就造成了内存泄漏。可通过jstack_x中的dump查看线程,由于线程的数量可能非常多,所以我们可以通过命令将线程栈导出到文件,如下图所示。
image.png

通过如下的linux命令统计一下处于WAITING状态的线程,通常能够看到处于此状态的线程数量巨大,这就说明了代码出现了Bug导致频繁创建了线程。

cat jstack_x_dump_9729.log |grep  "WAITING"|wc -l

我们还可以将jstack_x_dump_9729.log文件上传到XSheepdog上,通过网页的形式查看,如下图所示。  
image.png

在上传成功后会给出地址,我们用浏览器查看,从概述中就可看到1472个线程处于WAITING状态。
image.png

需要补充的一点是,如上实例的线程泄漏并不会造成CPU使用率飙升,使用率甚至还很低,因为处于WAITING状态的线程不占用CPU的计算资源。

典型案例3-大量线程等待获取共享资源

当应用服务遭遇到大流量访问时,经常会导致服务器整体负载过高,出现大面积的服务超时。我们举个简单的例子模拟一种情况。用SpringBoot模拟简单的HTTP请求,如下:

import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;
 
@RestController
public class HelloController {
    @RequestMapping("/hello")
    public void hello() {
        getResource();
    }
 
    public synchronized void getResource() {
        try {
            Thread.sleep(20); // 对于共享资源的占用时长为20ms
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
 
}

这个应用服务的一个瓶颈就是需要访问共享资源,为了线程安全,这个共享资源需要使用synchronized锁来保护,当请求不大时,这个问题暴露的不明显,我们通过安装ab测试工具来压测一下上面的应用服务,如下:

ab -n 100 -c 10 http://localhost:8080/hello

其中-n表示请求数,-c表示并发数,我们发送1000个请求,并发为10,最终执行的结果如下图所示。
image.png

假设我们可接受的服务时长为400ms,那么这个服务至少能够保证98%的请求在400ms之内处理完。
将ab测试的并发量改为20,压测的结果如下:
image.png

能够看到只有50%的服务请求在400ms之内能处理完,其它都超时。
在出现线上服务超时时,可通过XPocket的jstack_x插件定位由于共享资源引起的性能瓶颈,本例中由于争抢资源会引起大量线程处于WAITING状态。如上实例通过jstack_x定位,在attach状态下,输入lock命令:
image.png

在并发量为10的情况下,synchronized锁的持有和等待的情况如下图所示。
image.png

在并发量为20时的情况如下图所示。
image.png

如果出现了大量的线程等待锁资源,那么这绝对是一个需要优化的地方,优化的手段可以是缩小共享资源锁定的范围,横向扩展服务器等。
接下来我们可以使用stack -t nid命令查看某个等待锁线程的调用栈,通过调用栈来进一步定位业务代码,如下;
image.png

可以看到最后调用的是getResource()方法,等待这个方法上的同步锁。
至此我们确定了问题,在大流量情况下,Synchornized 锁导致了并发请求时性能下降,导致服务请求时间过长。

4、总结

本文结合了实例对jstack_x插件进行了深度体验,在JDK原有的jstack工具上做了增强,力求帮助每个开发者快速排查定位出线程相关的问题。

另外还需要补充一下Java线程的常见错误。如在应用中使用线程池时,使用newFixedThreadPool()方法创建线程池,而默认的LinkedBlockingQueue是无界的,当流量大时,向LinkedBlockingQueue中压入巨量的任务导致OOM;又或者使用newCachedThreadPool()创建线程池,由于其默认的工作队列是一个SynchronizedQueue的、没有额外存储空间的阻塞队列,当大量任务到来时,只能通过创建大量的线程执行任务,从而导致OOM;还或者创建大量的线程,由于线程频繁上下文切换,导致处理任务的时间变长,从而造成服务超时等。这些问题都可以使用jstack_x插件辅助定位,如果在使用jstack_x插件的过程中有任何问题,欢迎到讨论区交流反馈。

点赞收藏
鸠摩

著有《深入解析Java编译器:源码剖析与实例详解》、《深入剖析Java虚拟机:源码剖析与实例详解》等书籍。公众号“深入剖析Java虚拟机HotSpot”作者

请先登录,查看2条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

线上问题排查,一不小心踩到阿里的 arthas坑了

线上问题排查,一不小心踩到阿里的 arthas坑了

【全网首发】一次想不到的 Bootstrap 类加载器带来的 Native 内存泄露分析

【全网首发】一次想不到的 Bootstrap 类加载器带来的 Native 内存泄露分析

解读JVM级别本地缓存Caffeine青出于蓝的要诀 —— 缘何会更强、如何去上手

解读JVM级别本地缓存Caffeine青出于蓝的要诀 —— 缘何会更强、如何去上手

【全网首发】一次疑似 JVM Native 内存泄露的问题分析

【全网首发】一次疑似 JVM Native 内存泄露的问题分析

解读JVM级别本地缓存Caffeine青出于蓝的要诀2 —— 弄清楚Caffeine的同步、异步回源方式

解读JVM级别本地缓存Caffeine青出于蓝的要诀2 —— 弄清楚Caffeine的同步、异步回源方式

【全网首发】从源码角度分析一次诡异的类被加载问题

【全网首发】从源码角度分析一次诡异的类被加载问题

22
2