阅读 204

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

前言

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

jstack

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

线程状态的转换
状态说明
NEW初始状态,线程被构建,但是还没有调用start()方法
RUNNABLE运行状态
WAITING等待状态,进入该状态表示当前线程需要等待其它线程做出特定动作(通知或中断)
TIMED_WAITING超时等待状态,在指定的时间内会自行返回
BLOCKED阻塞状态,表示线程阻塞于锁
TERMINATED终止状态,表示当前线程已经执行完毕

image.png

知道以上状态之后,我们理解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);
    }

}
复制代码

image.png

模拟死锁
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状态

image.png

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

image.png

模拟runnable
public class ThreadRunningTest {

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

}
复制代码

image.png

如何找到问题线程

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

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

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

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

image.png

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

image.png

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

image.png

数据库

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

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

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并发编程》

文章分类
后端
文章标签