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

XPocket插件jstack_x助力线程问题排查 | PerfMa应用性能技术社区

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

在程序开发过程中，开发人员通常会遇到许多线上问题，这些问题可能是代码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来定位问题。如下：

XPocket支持管道操作，所以可通过top_x.cpu_p命令获取到占用CPU最高的Java进程pid，然后attach，这样在后续操作jstack_x中的任何命令时，都可以省略pid的输入。

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

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

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查看线程，由于线程的数量可能非常多，所以我们可以通过命令将线程栈导出到文件，如下图所示。

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

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

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

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

需要补充的一点是，如上实例的线程泄漏并不会造成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，最终执行的结果如下图所示。

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

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

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

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

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

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

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

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