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

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

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

在程序开发过程中,开发人员通常会遇到许多线上问题,这些问题可能是代码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条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

【全网首发】JVM性能问题的自动分析

【全网首发】JVM性能问题的自动分析

一次java内存top res高排查记录

一次java内存top res高排查记录

【全网首发】揭密Java常用性能调优工具的底层实现原理

【全网首发】揭密Java常用性能调优工具的底层实现原理

JVM 优化踩坑记

JVM 优化踩坑记

代码改成多线程,竟有9大问题

代码改成多线程,竟有9大问题

JVM 常见线上问题:CPU100%、内存泄露的问题排查

JVM 常见线上问题:CPU100%、内存泄露的问题排查

21
2