利用jstack工具分析JVM线程

笔者是WEB JAVA后台开发，最近在线上遇到过几次服务不可用问题，基本现象是接口请求无响应或响应非常慢达到分钟级别。一般问题发生时我们都会去查看日志，经常遇到没有日志的情况（此时服务无法响应client请求），甚至要去找几个小时前的日志现象发生时，有些接口甚至没有日志打印，查找起来很困难，利用jvm的线程栈工具jstack对于查找问题有很大帮助。

文章以SpringBoot为框架开发一个web demo应用，以接口代码示例几种可能会导致服务无法响应的案例，并讲述如何以jstack等工具排查问题。
环境：单核CPU虚拟机CentOS6 + JAVA8 + SpringBoot

JAVA jstack日志文件中有以下几种状态需要关注的：
1.死锁，Deadlock，线程死锁；
2.执行中，Runnable，线程执行过程中可能会遇到第三方IO等阻塞或循环，仍需要关注；
3.等待资源， Waiting on condition，线程等待条件，可能是在等待网络资源响应请求，具体需结合栈信息stacktrace进行分析；
4.等待获取监视器，Waiting on monitor entry，一般是互斥锁实现线程同步；
5.条件等待/定时等待，Object.wait() 或 TIMED_WAITING，Object.wait()是让当前线程阻塞，并出让当前线程的拥有的Object锁，直到被持有Object锁的其它线程调用Object.notify()唤醒才继续执行
6.停止/停止中：Parked/Parking。

死循环

死循环或长时间循环计算，占用CPU计算资源，导致CPU占满。本例虚拟机CPU为1核，所以CPU占用用率达到100%，如果是多核，则占用率为1/n，如四核则为25%

代码示例

@RequestMapping("loop")
public void threadLoopDemo() throws Exception{
   
    int num = 0;
    long start = System.currentTimeMillis() / 1000;
    while (true) {
   
        log.info("====>  测试 Loop");
        num++;
        if (num == Integer.MAX_VALUE) {
   
            log.info("====> rest num");
            num = 0;
        }

        if (System.currentTimeMillis() / 1000 - start > 1000) {
   
            return;
        }
    }
}

现象说明

top -c CPU占用情况，发现此时CPU占用100%，说明以上死循环独占CPU资源。
ps -mp 3168 -o THREAD,tid,time或top -H -p 3168（3168为进程号<pid>） 可打印出进程对应的线程id及运行时间time，可以看到nid=3187的线程占用CPU82.8%，且运行时间为2min

线程堆栈

jstack 3168打印输出找到对应问题的堆栈，从下往上看，发现tomcat NIO Channel被locked，说明该请求的线程未释放，仍在执行；同时找到出问题的代码位置。nid=0xc73换成十进制为nid=3187，即上述占用CPU高且时间较少的线程。

"http-nio-10015-exec-1" #19 daemon prio=5 os_prio=0 tid=0x00007f75e4050800 nid=0xc73 runnable [0x00007f75e84e4000]
   java.lang.Thread.State: RUNNABLE
        at java.io.FileOutputStream.writeBytes(Native Method)
        at java.io.FileOutputStream.write(FileOutputStream.java:326)
        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
        at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
        - locked <0x00000000eb1a0b48> (a java.io.BufferedOutputStream)  // log日志，输出到file日志文件
        at java.io.PrintStream.write(PrintStream.java:482)
        - locked <0x00000000eb18a468> (a java.io.PrintStream)
        at java.io.FilterOutputStream.write(FilterOutputStream.java:97)
        at ch.qos.logback.core.joran.spi.ConsoleTarget$1.write(ConsoleTarget.java:37)
        at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:131)
        .... 问题代码出处
        at com.ljyhust.demo.web.ThreadTestDemoController.threadLoopDemo(ThreadTestDemoController.java:20)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        ..... 此处省略
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1520)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1476)
        - locked <0x00000000ec476d30> (a org.apache.tomcat.util.net.NioChannel)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)

网络/IO阻塞

大量网络IO阻塞，导致占用服务线程，导致服务无法响应。
这里以大家熟悉tomcat服务为例，tomcat设有最大线程数maxThreads和最大排队数acceptCount，这两个参数可以在server.xml文件中配置。tomcat处理请求可分为以下3种情况：
1.接收一个请求，当启动的线程数或正在运行的线程数< maxThreads时，则tomcat会启动一个线程来处理该请求；
2.接收一个请求，当启动的线程数或正在运行的线程数> maxThreads时，