【故障诊断】MySql 慢查询

一般来说，SQL的执行时间在几十毫秒~几百毫秒左右，如果一个简单的sql，操作一个数据量不大的表，执行时间还很长，肯定是不正常的。

Mysql提供了记录慢查询日志的功能，方便我们找出执行时间过长的SQL语句。
我们可以在测试的时候，或出现偶发性问题了，开启慢查询日志，定位出异常的SQL。

开启慢查询日志的记录功能

mysql支持记录两种慢查询日志（只能二选一）：

1. 设置一个时间的阀值，记录执行时间超过阀值的数据的SQL（如：记录执行时间超过1秒的SQL）
2. 记录没有使用索引的SQL（此配置启用后，时间阀值等配置将失效）

日志的输出
慢查询日志可选择输出到文件和数据库表
输出到数据库表,则会在mysql数据库的slow_log表中可以查询到
输出到文件，可以从mysql全局变量slow_query_log_file中获取文件的路径【show VARIABLES like '%slow_query_log_file%'】
一般来说，输出到文件的开销更小，性能更好，也更加准确（例如：一个sql执行时间未0.1ms，但输出到table的时间可能就超出了0.1ms），但文件的形式不太适合分析，需要借助一些工具

示例1：记录超过时间阀值的SQL

-- 开启慢查询日志
set GLOBAL slow_query_log ='ON';
-- 输出日志到文件或，【TABLE】为表，【FILE】为文件，【FILE,TABLE】为同时输出表和文件
set GLOBAL log_output = 'FILE';

-- 开启慢查询日志的时间阀值，超过此时间被记录，，0代表记录所有,0.1代表100毫秒
set GLOBAL long_query_time = 0.1;

-- 查看慢查询时间的设置（set之后要重新连接才会看到值的变化）
show VARIABLES like '%long_query_time%';

示例2：记录没有使用索引的SQL（此配置一旦启用，则时间阀值相关失效）
在并发量大的情况下，记录未使用索引的慢查询日志可能给mysql带来更大的负担，因此Mysql提供了参数log_throttle_queries_not_using_indexes来限制每分钟记录到慢查询日志的数量

-- 开启慢查询日志
set GLOBAL slow_query_log ='ON';
-- 输出日志到文件或，【TABLE】为表，【FILE】为文件，【FILE,TABLE】为同时输出表和文件
set GLOBAL log_output = 'FILE';


set GLOBAL log-queries-not-using-indexes= 'ON';
-- 如下配置表示在每分钟最多记录5条慢查询日志，其他日志将被丢弃
set GLOBAL log_throttle_queries_not_using_indexes=5;

-- 查看参数设置
show VARIABLES like 'log-queries-not-using-indexes';

如上的参数设置都是设置到内存，重启后失效，也可以在my.conf文件中设置，重启后依然有效。

虽然一些书籍中提到，慢查询日志对mysql的负担是比较小的，一直开着日志记录影响也不大。
但我仍然建议，在生产环境，排查问题的时候开启，排查完毕后关闭。而开发环境和测试环境，可以一直开启，有问题的SQL应该在开发或测试的时候被发现。当然，如果遇到偶发性的不容易重现的问题，或者每隔一段时间有专人检查日志情况，可以尝试一直开启慢查询日志，但时间的阀值要慎重选择！

慢查询日志的查看与分析

如果log_output参数设置为输出到表，则在mysql.slow_log
关注2个字段，query_time为执行时间，sql_text为sql语句

image.png

SQL特征识别

一般来说，我们需要找出最慢的SQL，优化SQL，或者找到他对应的业务代码，优化业务代码
但是如果出现多条 差不多的SQL，即SQL结构一致，参数不一样，如下
SELECT * FROM test01 where sex=1 and age > 10 and name like '张%'
SELECT * FROM test01 where sex=2 and age > 20 and name like '李%'
这种情况，很可能就是一行业务代码，对于mysql来说，执行计划也是一样的
但在慢查询日志里面，就不好区分出来了，我们将数字、字符串替换为N和'S'，就可以视为1条SQL了
SELECT * FROM test01 where sex=N and age > N and name like 'S'

此时，就可以分组统计每个sql的执行数量，平均执行时间等信息了

**慢查询分析工具 percona-toolkit **

percona-toolkit是一个Mysql的命令行的工具套件，包含很多数据库操作相关的命令/工具
其中pt-query-digest工具可以很方便的分析慢查询日志

percona-toolkit 如下下载安装失败请参考官网下载

#下载工具（下载不了就去官网找新的下载链接）
wget percona.com/get/percona-toolkit.tar.gz
# 解压
tar zxf percona-toolkit*
# 进入解压文件夹
cd  percona-toolkit*

# 安装依赖
yum install perl-DBD-MySQL perl-Digest-MD5 perl-ExtUtils-CBuilder perl-ExtUtils-MakeMaker cpan  'perl(Data::Dumper)'

# 安装perl模块，制定依赖路径（执行报错就查百度，一般是缺少依赖）
perl Makefile.PL PREFIX=/usr/local/percona-toolkit
#安装（执行报错就查百度，一般是缺少依赖）
make && make install

其中pt-query-digest 是用来分析慢查询日志的工具
安装完毕之后，安装目录下的bin子目录就是各种命令了，如上make安装完毕后，安装目录为：/usr/local/percona-toolkit

使用【pt-query-digest 慢查询日志文件路径】来分析慢查询日志

image.png

第一个红框-总体概要信息
依次为
Current date:当前时间
Hostname: 主机名
Files: 文件路径
Overall: 分析的sql数量统计
Time range: sql的执行时间，最早时间和最晚时间

下面的表格分别表示
第一行 Exec time 执行时间，总共177s，最小执行时间6us，最大451ms，平均144us ,95%的执行时间424us，标准偏差899us，中位数93us
第二行 Lock time：锁占用的时间，各个列的含义同执行时间一样
第二行 Row sent：发送到客户端的行数，各个列的含义同执行时间一样
第二行 Row examine：select语句扫描行数，各个列的含义同执行时间一样
第二行 Query size：查询的字符数，各个列的含义同执行时间一样

第二个红框-SQL概要信息
统计了最慢的几个sql的信息，每一行一个SQL的信息
第一行数据释义：

1. SQL语句大致为SELECT EP?_EQUIP_INFO
2. 序号为1
3. pt-query-digest为此SQL生成的唯一ID为0X0EE51CD49......... (Query ID字段)，可搜索此ID找到本SQL对应的详细信息
4. 此SQL总共执行1037142次 (Calls字段)
5. 总共执行时间为100.3179秒，占本次分析的所有sql执行时间之和的56.8% (Response time字段)
   6.平均每次执行的响应时间为0.0001秒 (R/Call字段)

SQL详细信息
2个红框下面就是各个SQL的详细信息，如下图

image.png

第一个红框的内容同上面大致一致
下面的Database/Hosts/users 表示执行的数据库，主机号，用户等信息
第二个红框是时间分布的直方图，如图，表示大部分执行时间在10us、100us，而1ms、10ms 次数较少

下面的Tables部分是 pt-query-digest为你生成的SQl语句，用于分析SQL语句用的。
如第一行，显示表当前状态；第二行，显示建表语句；第三行，explain语句分析SQL

pt-query-digest工具还有很多参数，如从tcpdump文件、binlog文件中分析，筛选时间范围，将分析结果存入数据库等，可查阅官网资料、网上博客了解