一般来说,SQL的执行时间在几十毫秒~几百毫秒左右,如果一个简单的sql,操作一个数据量不大的表,执行时间还很长,肯定是不正常的。
Mysql提供了记录慢查询日志的功能,方便我们找出执行时间过长的SQL语句。
我们可以在测试的时候,或出现偶发性问题了,开启慢查询日志,定位出异常的SQL。
开启慢查询日志的记录功能
mysql支持记录两种慢查询日志(只能二选一):
- 设置一个时间的阀值,记录执行时间超过阀值的数据的SQL(如:记录执行时间超过1秒的SQL)
- 记录没有使用索引的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语句
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 慢查询日志文件路径
】来分析慢查询日志
第一个红框-总体概要信息
依次为
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的信息
第一行数据释义:
- SQL语句大致为
SELECT EP?_EQUIP_INFO
- 序号为
1
-
pt-query-digest
为此SQL生成的唯一ID为0X0EE51CD49.........
(Query ID字段),可搜索此ID找到本SQL对应的详细信息 - 此SQL总共执行
1037142
次 (Calls字段) - 总共执行时间为
100.3179
秒,占本次分析的所有sql执行时间之和的56.8%
(Response time字段)
6.平均每次执行的响应时间为0.0001秒 (R/Call字段)
SQL详细信息
2个红框下面就是各个SQL的详细信息,如下图
第一个红框的内容同上面大致一致
下面的Database/Hosts/users
表示执行的数据库,主机号,用户等信息
第二个红框是时间分布的直方图,如图,表示大部分执行时间在10us
、100us
,而1ms
、10ms
次数较少
下面的Tables部分是 pt-query-digest
为你生成的SQl语句,用于分析SQL语句用的。
如第一行,显示表当前状态;第二行,显示建表语句;第三行,explain语句分析SQL
pt-query-digest
工具还有很多参数,如从tcpdump文件、binlog文件中分析,筛选时间范围,将分析结果存入数据库等,可查阅官网资料、网上博客了解