请求过了10s还没返回，如何排查

前言

程序员定位问题的能力是非常重要的，假如现在产线上出了一个问题，客户端发的请求过了10s还没返回，你会怎么排查？

jstack

jstack是个很强大的命令，可以生成指定进程当前时刻的线程快照，在讲如何使用jstack排查之前，我们需要一些前置知识

线程状态的转换

知道以上状态之后，我们理解jstack的dump信息就会容易很多，在dump信息中，需要留意下面几种状态

1. 死锁，Deadlock
2. 等待资源，Waiting on condition
3. 等待获取监视器，Waiting on monitor entry（这个一般都有问题）
4. 阻塞，Blocked
5. 执行中，Runnable
6. 暂停，Suspended

模拟Waiting on condition

public class ThreadSleepTest {

    public static void main(String[] args) throws InterruptedException {
        Thread.sleep(10000000);
    }

}
复制代码

模拟死锁

public class ThreadDeadLockTest {

    public static void main(String[] args) {

        StringBuilder a = new StringBuilder();
        StringBuilder b = new StringBuilder();

        Thread thread1 = new Thread(() -> {
            synchronized (a) {
                a.append("a");
                b.append("b");

                try {
                    Thread.sleep(1000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }

                synchronized (b) {
                    b.append("c");
                    a.append("d");
                }
            }
        });

        Thread thread2 = new Thread(() -> {
            synchronized (b) {
                b.append("b");
                a.append("a");

                try {
                    Thread.sleep(1000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
                synchronized (a) {
                    a.append("c");
                    b.append("d");
                }
            }
        });
        thread1.setName("线程1");
        thread2.setName("线程2");

        thread1.start();
        thread2.start();
    }
}
复制代码

可以看到线程1和线程2都在等待锁资源，处于BLOCK状态

再往下看，就可以看到死锁的提示

模拟runnable

public class ThreadRunningTest {

    public static void main(String[] args) throws InterruptedException {
        int sum = 0;
        while (true) {
            sum += 1;
        }
    }

}
复制代码

如何找到问题线程

以上都是我们写程序模拟的，可以很容易地找到问题线程，但是在实际生产环境中，请求非常庞大的情况下，要怎么找到这个有问题的线程呢？

最经典的方法是以下四个步骤，找出占用cpu最高的线程，并且打印该堆栈信息

// 找出占用cpu最高的进程
top
// 找出该进程下占用cpu最高的线程
top -Hp pid
// 打印该线程的16进制数据
printf "%x\n" 线程id
// 打印堆栈信息
jstack pid | grep nid=16进制
复制代码

Time+：线程占用cpu的累积时间

还有一个比较巧妙的方法，dump出一份线程堆栈后，隔一段时间再dump出一份

在IDEA上使用Compare Files进行比较，分析两份dump文件的异同，如果有一个请求超过了10s还没返回，理论上在两份文件中都会存在，这个时候就可以找出那个线程id了，这是个较为经典的方法，比较抓包的请求也可以使用这个方法

数据库

请求太久没有返回，本人一般都会先排查数据库，万一数据库被打穿，后果很严重

现检查有没有开启慢查询日志

mysql> show variables like '%slow_query_log%';
+---------------------+----------------------------------------------------------+
| Variable_name       | Value                                                    |
+---------------------+----------------------------------------------------------+
| slow_query_log      | ON                                                       |
| slow_query_log_file | /usr/local/mysql/data/zhangxiaobindeMacBook-Pro-slow.log |
+---------------------+----------------------------------------------------------+
2 rows in set (0.01 sec)
复制代码

执行一条慢sql

mysql> select sleep(100), id from user where id = 1;
+------------+----+
| sleep(100) | id |
+------------+----+
|          0 |  1 |
+------------+----+
1 row in set (1 min 40.24 sec)
复制代码

我们就可以在慢查询日志中查询到这条sql，并且知道执行了多长时间

/usr/local/mysql/bin/mysqld, Version: 5.7.27-log (MySQL Community Server (GPL)). started with:
Tcp port: 3306  Unix socket: /tmp/mysql.sock
Time                 Id Command    Argument
# Time: 2021-07-03T08:33:40.680324Z
# User@Host: root[root] @ localhost []  Id:     7
# Query_time: 100.238479  Lock_time: 0.168766 Rows_sent: 1  Rows_examined: 1
use test;
SET timestamp=1625301220;
select sleep(100), id from user where id = 1;
复制代码

找到sql之后，就好办了，可以使用explain关键字看看sql的执行过程

show processlist

也有可能sql还没有进入慢查询日志中，这个时候可以使用show processlist命令，查询有没有执行时间过长的sql，就比较较为快速定位出问题的sql

mysql> show processlist;
+----+------+-----------------+------+---------+------+------------+----------------------------------------------+
| Id | User | Host            | db   | Command | Time | State      | Info                                         |
+----+------+-----------------+------+---------+------+------------+----------------------------------------------+
|  2 | root | localhost:54718 | test | Sleep   |   35 |            | NULL                                         |
|  3 | root | localhost:54725 | NULL | Sleep   |   42 |            | NULL                                         |
|  4 | root | localhost:51794 | test | Sleep   |   62 |            | NULL                                         |
|  5 | root | localhost:51795 | NULL | Sleep   |   12 |            | NULL                                         |
|  7 | root | localhost       | test | Query   |   23 | User sleep | select sleep(100), id from user where id = 1 |
|  9 | root | localhost       | NULL | Query   |    0 | starting   | show processlist                             |
+----+------+-----------------+------+---------+------+------------+----------------------------------------------+
6 rows in set (0.00 sec)
复制代码

参考资料

《Java并发编程》