接口超时排查

生产环境突然报系统繁忙，通过查看当时的日志发现接口报 java.io.IOException:Broken pipe ，复现抓包看到网关报 504(Gateway Timeout)。

原因分析

随着数据越来越多，分页的页数也越来越多，当翻页过多的时候，就会产生深分页，导致查询效率急剧下降。

问题定位

使用arthas定位问题

一般通过代码review，就能大概猜测问题点。如果项目基建成熟，使用skywalking可以看到每次请求耗时。也可以通过arthas工具，帮忙定位下具体的耗时方法。

在服务器上下载arthas

// wget https://arthas.aliyun.com/arthas-boot.jar

xxl@xxl-ubuntu:~$ cd /home/xxl/tools
xxl@xxl-ubuntu:~$ mkdir arthas
xxl@xxl-ubuntu:~$ wget https://arthas.aliyun.com/arthas-boot.jar

启动arthas

xxl@xxl-ubuntu:~$ java -jar arthas-boot.jar

选择要抓取的jar包

xxl@xxl-ubuntu:~/tools/arthas$ java -jar arthas-boot.jar 
[INFO] JAVA_HOME: /usr/lib/jvm/java-11-openjdk-amd64
[INFO] arthas-boot version: 3.7.1
[INFO] Can not find java process. Try to run `jps` command lists the instrumented Java HotSpot VMs on the target system.
Please select an available pid.
xxl@xxl-ubuntu:~/tools/arthas$ java -jar arthas-boot.jar 
[INFO] JAVA_HOME: /usr/lib/jvm/java-11-openjdk-amd64
[INFO] arthas-boot version: 3.7.1
[INFO] Found existing java process, please choose one and input the serial number of the process, eg : 1. Then hit ENTER.
* [1]: 13059 xxl-ubuntu-springboot-0.0.1-SNAPSHOT.jar
1

使用 stack 命令可以看到方法内部调用命令 👉：​trace | arthas (aliyun.com) (opens new window)

// 类名+方法名
stack com.xxl.xxl.controller.UbuntuController helloUbuntu

下载插件 arthas idea，在方法名上右键 Arthas Command ，Trace。

到shell中粘贴命令，查看方法内详细耗时信息

[arthas@16342]$ trace com.xxl.xxl.controller.UbuntuController helloUbuntu2  -n 5 --skipJDKMethod false 
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 68 ms, listenerId: 2
`---ts=2023-09-24 19:50:59;thread_name=http-nio-8080-exec-5;id=16;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@7ba8c737
    `---[0.281693ms] com.xxl.xxl.controller.UbuntuController:helloUbuntu2()
        `---[54.11% 0.152427ms ] com.xxl.xxl.controller.UbuntuController:add() #20

Mybatis-Plus整合p6spy打印SQL耗时

添加依赖

<dependency>
	<groupId>p6spy</groupId>
	<artifactId>p6spy</artifactId>
	<version>3.9.1</version>
</dependency>

修改数据库连接配置

driver-class-name用p6spy提供的驱动类

url前缀为jdbc:p6spy跟着冒号，后面对应数据库连接地址

spring:
    datasource: 
        type: com.alibaba.druid.pool.DruidDataSource
        driver-class-name: com.p6spy.engine.spy.P6SpyDriver
        url: jdbc:p6spy:mysql://127.0.0.1:3306/test?useUnicode=true&characterEncoding=utf-8&useSSL=true&serverTimezone=UTC

增加配置文件：在resources文件夹下创建p6spy的配置文件spy.properties

#3.2.1以上使用
modulelist=com.baomidou.mybatisplus.extension.p6spy.MybatisPlusLogFactory,com.p6spy.engine.outage.P6OutageFactory
#3.2.1以下使用或者不配置
#modulelist=com.p6spy.engine.logging.P6LogFactory,com.p6spy.engine.outage.P6OutageFactory
# 自定义日志打印
logMessageFormat=com.baomidou.mybatisplus.extension.p6spy.P6SpyLogger
#日志输出到控制台
#appender=com.baomidou.mybatisplus.extension.p6spy.StdoutLogger
# 使用日志系统记录 sql
appender=com.p6spy.engine.spy.appender.Slf4JLogger
# 设置 p6spy driver 代理
deregisterdrivers=true
# 取消JDBC URL前缀
useprefix=true
# 配置记录 Log 例外,可去掉的结果集有error,info,batch,debug,statement,commit,rollback,result,resultset.
excludecategories=info,debug,result,commit,resultset
# 日期格式
dateformat=yyyy-MM-dd HH:mm:ss
# 实际驱动可多个
#driverlist=org.h2.Driver
# 是否开启慢SQL记录
outagedetection=true
# 慢SQL记录标准 2 秒
outagedetectioninterval=2

解决

1、分页关闭查询总数

如果使用mybatis-plus提供的分页插件，会默认开启查询总数的SQL，如果不需要可以关闭减少一次查询。

Page pageReq = request.plusPage();
pageReq.setSearchCount(false);

2、游标分页

游标翻页，只要命中索引，速度就非常快，和消息量基本没关系

mysql分页使用游标_mob64ca12d1a59e的技术博客_51CTO博客 (opens new window)

解密高效分页查询：Java实现MySQL分页的奥秘 (baidu.com) (opens new window)

mysql 分页的方法技巧有哪些？ - 知乎 (zhihu.com) (opens new window)

MySQL分页到了后面越来越慢，有什么好的解决办法？ - 知乎 (zhihu.com) (opens new window)