记一次线上SQL排查问题：CommunicationsException

记一次线上SQL排查问题

原文链接：https://blog.fengqingmo.top/articles/143

问题描述

线上有一个区域的一个查询接口突然失效了，异常日志如下：

Error querying database.
Cause: com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure
The last packet successfully received from the server was 10,004 milliseconds ago. 
The last packet sent successfully to the server was 10,190 milliseconds ago.
The error may exist in URL [jar:file:/usr/java/spring-cloud-oncedone-service-provider/spring-cloud-oncedone-service-provider-1.0.0.jar!/BOOT-INF/classes!/mapper/flow/FlowInfoMapper.xml]\n
The error may involve defaultParameterMap
The error occurred while setting parameters
SQL: SELECT         IFNULL (s.SCENE_NAME, '一件事一次办') SCENE_NAME,         f.FLOW_CODE,         f.qyid,         f.QYMC,         f.TYSHXYDM,         f.BUSI_CODE,         f.CUR_NODE,         f.HANDLE_TIME,         f.UPDATED_TIME,         f.user_id userId,         su.nickname,         su.id_number,         su.phone,         f.state,        
(select group_concat(d.ITEM_CODE) from t_flow_detail d where d.BUSI_CODE = f.BUSI_CODE group by BUSI_CODE)         ITEM_CODE,   
(select w.ONE_WEB_PARAM from t_flow_info_one_web w WHERE f.id = w.flowinfo_id) ONE_WEB_PARAM         FROM         t_flow_info f         LEFT JOIN t_scene s ON f.SCENE_CODE = s.id         LEFT JOIN auth_sys.sys_user su on su.user_id = f.USER_ID          WHERE f.DEL_FLAG = '0'             and f.qymc is not null             and f.REGION_CODE             IN (SELECT distinct region_code             FROM auth_sys.sys_dept       
WHERE FIND_IN_SET(region_code, (SELECT IFNULL(            
(SELECT region_code FROM auth_sys.sys_dept LEFT JOIN auth_sys.sys_user ON auth_sys.sys_user.dept_id =             auth_sys.sys_dept.dept_id WHERE auth_sys.sys_user.user_id = ?),             (SELECT DISTINCT GROUP_CONCAT(region_code) FROM auth_sys.sys_dept WHERE parent_id = 1 )))))      and f.flow_code like ?  order by UPDATED_TIME desc,submission_time desc,HANDLE_TIME desc LIMIT ?
}

解决方法

增加索引

排查过程

由于这个接口之前是可以正常访问，可以排除是SQL写错的问题。同时在网上搜了很多相关资料，都无法解决。

然后开始排查，首先根据报错显示

原因：com.mysql.cj.jdbc异常。通信异常：通信链路故障
从服务器成功接收到的最后一个数据包是10004毫秒前。
最后一个成功发送到服务器的数据包是10190毫秒前。

并且也看得出来这个SQL非常复杂，有很多连表和子查询，猜测是查询时间过长。

于是先拿到参数后手动拼接完SQL看一下explain执行计划

可以看到有四张表要全表查询，尤其是第一行

Using filesort :
意味着MySQL无法使用索引来排序结果集，因此它必须自己进行排序。这种排序通常发生在内存中（如果数据量不大），但如果内存不足，MySQL可能会将数据写入磁盘上的临时文件，然后对这些文件进行排序,会显著降低查询性能，尤其是当排序的数据量很大时。磁盘I/O操作比内存操作要慢得多
Using tempory:
使用临时表，临时表会占用内存资源，如果系统中有大量并发查询都在使用临时表，可能会导致内存不足的问题。如果临时表的大小超过了系统变量tmp_table_size或max_heap_table_size的设置，临时表会从内存转换为基于磁盘的表，这会大大增加I/O操作。

大概可以确定问题出在这个连表查询语句上，接下来通过SQL执行顺序（id），一步一步执行下来，发现果然是这个SQL执行时间特别长。

同时通过服务监控观察临时表数量

10.44-10.45属于正常范围的波动
开了5个线程循环3次执行SQL 临时表数量增加约70张，临时磁盘表增加约10张。
这是在测试数据库下执行的，数据量远低于正式的。

确定慢查询SQL

    (SELECT w.ONE_WEB_PARAM FROM t_flow_info_one_web w WHERE f.id = w.flowinfo_id) AS

发现这w表是与f的关联表，即w表的字段fid是f的主键，一般这种需要加唯一索引。但这张表没加。。。。（前人的遗留问题）

最后加了索引，后续就查询的很快了。

完结~