*本文章使用数据均来自MySQL样本数据库Sakila,参考:https://blog.csdn.net/tanglei6636/article/details/93042010
慢查询日志概述
MySQL的慢查询日志是MySQL提供的一种日志记录,它用来记录在MySQL中响应时间超过阀值的语句,具体指运行时间超过long_query_time值的SQL,则会被记录到慢查询日志中。
默认情况下,MySQL数据库并不启动慢查询日志,需要我们手动来设置这个参数,当然,如果不是调优需要的话,一般不建议启动该参数,因为开启慢查询日志会或多或少带来一定的性能影响。
慢查询日志配置
- 参数说明:
- slow_query_log:是否开启慢查询日志,1表示开启,0表示关闭;
- slow_query_log_file:MySQL慢查询日志存储路径;
- long_query_time:慢查询阈值,以秒为单位,支持到毫秒级别,当查询时间多于设定的阈值时,记录到慢查询日志中;
- log_queries_not_using_indexes:未使用索引的查询是否可以记录到慢查询日志中;
- log_throttle_queries_not_using_indexes:表示每分钟允许记录到slow_log的且未使用索引的sql语句次数(0为无限制,如果为固定值,可能会记录不到sql);
- log_output:日志存储方式。’FILE’表示存入文件,‘TABLE’表示存入系统表。因为FILE模式开销比较低,所以默认为FILE;
- log_slow_admin_statements = 1: 记录ALTER TABLE等语句引发的慢查询;
- log_slow_slave_statements = 1:记录从服务器产生的慢查询;
- min_examined_row_limit = 100 :SQL扫描行数大于等于100行才会被记录;
-
常用配置:
set global slow_query_log = 1; 打开慢查询日志
set global long_query_time = 0.1; 设置查询时间超过100ms的查询为慢查询。在数据库调优过程中可以设置为此数值或者更低,自学过程中可以设置为0,保证所有查询都打印到慢查询日志中,正式上线后应将此数值调大,避免过多的日志打印或者将慢查询日志关闭
set global log_queries_not_using_indexes = 1; 将未使用索引的查询是否可以记录到慢查询日志,帮助定位没有使用索引的查询,建议一直开启此选项
set globle log_output = file; FILE模式开销比较低,不会对数据库造成额外压力
set global slow_query_log_file = ‘/log/slow_log.log’; 设置日志路径 -
查看参数:
通过show variables命令可以查看MySQL配置。
show variables like ‘%slow_query_log%’;
show variables like ‘%long_query_time%’;
PS:如果Window版的MySQL设置set global long_query_time = 0.1;不生效,需要找到my.ini文件的位置,直接在在my.ini中添加long_query_time = 0.1,并重启MySQL数据库,接下来就可以正常使用set global long_query_time语句设置慢查询阈值
慢查询日志分析
执行SQL:select * from store;
慢查询日志内容记录如下:
日志内容说明:
# User@Host: root[root] @ localhost [127.0.0.1] Id:7 执行SQL的用户、主机信息,如此次查询 :root用户在本机执行
# Query_time: 0.013955 查询执行时间
Lock_time: 0.006970 锁定时间
Rows_sent: 4 查询发送的行数
Rows_examined: 4 查询扫描行数
SET timestamp=1562496726; 查询执行在哪一时刻
SHOW COLUMNS FROM `sakila`.`store`; SQL内容
pt_query_digest分析慢查询日志
- 安装pt_query_digest
pt-query-digest是用于分析MySQL慢查询的一个工具,它可以分析binlog、General log、slowlog, 也可以通过SHOWPROCESSLIST或者通过tcpdump抓取的MySQL协议数据来进行分析。
可以把分析结果输出到文件中,分析过程是先对查询语句的条件进行参数化,然后对参数化 以后的查询进行分组统计,统计出各查询的执行时间、次数、占比等,可以借助分析结果找出问题进行优化。
pt-query-digest是一个perl脚本,只需下载并赋权即可执行。
wget percona.com/get/pt-query-digest
chmod u+x pt-query-digest
或者使用yum安装。
yum install -y percona-toolkit-3.0.12-1.el6.x86_64.rpm
执行命令:pt-query-digest --help 验证是否安装成功。
- 参数说明
pt-query-digest [OPTIONS] [FILES] [DSN]
–create-review-table 当使用 --review 参数把分析结果输出到表中时,如果没有表就自动创建
–create-history-table 当使用 --history 参数把分析结果输出到表中时,如果没有表就自动创建
–filter 对输入的慢查询按指定的字符串进行匹配过滤后再进行分析
–limit 限制输出结果百分比或数量,默认值是 20, 即将最慢的 20 条语句输出,如果是 50% 则按总响应时间占比从大到小排序,输出到总和达到 50% 位置截止
–host mysql 服务器地址
–user mysql 用户名
–password mysql 用户密码
–history 将分析结果保存到表中,分析结果比较详细,下次再使用 --history 时,如果存在相同的语句,且查询所在的时间区间和历史表中的不同,则会记录到数据表中,可以通过查询同一 CHECKSUM 来比较某类型查询的历史变化
–review 将分析结果保存到表中,这个分析只是对查询条件进行参数化,一个类型的查询一条记录,比较简单。当下次使用 --review 时,如果存在相同的语句分析,就不会记录到数据表中
–output 分析结果输出类型,值可以是 report( 标准分析报告 ) 、 slowlog(Mysql slow log) 、 json 、 json-anon ,一般使用 report ,以便于阅读
–since 从什么时间开始分析,值为字符串,可以是指定的某个 ”yyyy-mm-dd [hh:mm:ss]” 格式的时间点,也可以是简单的一个时间值: s( 秒 ) 、 h( 小时 ) 、 m( 分钟 ) 、 d( 天 ) ,如 12h 就表示从 12 小时前开始统计
–until 截止时间,配合 —since 可以分析一段时间内的慢查询
- 使用说明
执行命令:pt-query-digest slow_log.log > slow_analyse_log.log
分析慢查询日志文件slow_log.log,将分析结果导入文件slow_analyse_log.log。
分析结果如下
第一部分:
#该工具执行日志分析的用户时间,系统时间,物理内存占用大小,虚拟内存占用大小
# 180ms user time, 20ms system time, 25.57M rss, 220.11M vsz
# 工具执行时间
# Current date: Sun Jul 7 20:31:56 2019
# 运行分析工具的主机名
# Hostname: iZ2ze49dsj767ouqcmxlqaZ
# 被分析的文件名
# Files: slow_log.log
# 语句总数量,唯一的语句数量,QPS,并发数
# Overall: 1 total, 1 unique, 0 QPS, 0x concurrency ______________________
# 日志记录的时间范围
# Time range: Sun Jul 7 20:31:56 2019 to Sun Jul 7 20:33:21 2019
# 属性 总计 最小 最大 平均 95% 标准 中等 其中95%的意思指前95%的查询所耗费的平均时间,中等是指查询时间的中位数
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# 语句执行时间
# Exec time 14ms 14ms 14ms 14ms 14ms 0 14ms
# 锁占用时间
# Lock time 7ms 7ms 7ms 7ms 7ms 0 7ms
# 发送到客户端的行数
# Rows sent 4 4 4 4 4 0 4
# select语句扫描行数
# Rows examine 4 4 4 4 4 0 4
# 查询的字符数
# Query size 34 34 34 34 34 0 34
第二部分:
# Profile
# Rank Query ID Response time Calls R/Call V/M
# ==== ================================== ============= ===== ====== =====
# 1 0x3AA3139EF4FB742C4889339B364E8843 0.0140 100.0% 1 0.0140 0.00 SHOW COLUMNS
Rank:所有语句的排名,默认按查询时间降序排列,通过–order-by指定
Query ID:语句的ID,(去掉多余空格和文本字符,计算hash值)
Response:总的响应时间
time:该查询在本次分析中总的时间占比
calls:执行次数,即本次分析总共有多少条这种类型的查询语句
R/Call:平均每次执行的响应时间
V/M:响应时间Variance-to-mean的比率
Item:查询对象
第三部分:
# Query 1: 0 QPS, 0x concurrency, ID 0x3AA3139EF4FB742C4889339B364E8843 at byte 0
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 100 1
# Exec time 100 14ms 14ms 14ms 14ms 14ms 0 14ms
# Lock time 100 7ms 7ms 7ms 7ms 7ms 0 7ms
# Rows sent 100 4 4 4 4 4 0 4
# Rows examine 100 4 4 4 4 4 0 4
# Query size 100 34 34 34 34 34 0 34
# String:
# Hosts localhost
# Users root
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms ################################################################
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `sakila` LIKE 'store'\G
# SHOW CREATE TABLE `sakila`.`store`\G
SHOW COLUMNS FROM `sakila`.`store`\G
具体参数可参考第一部分。
-
用法示例
(1)直接分析慢查询文件:pt-query-digest slow.log > slow_report.log(2)分析最近12小时内的查询:pt-query-digest --since=12h slow.log > slow_report2.log
(3)分析指定时间范围内的查询:pt-query-digest slow.log --since ‘2014-04-17 09:30:00’ --until ‘2014-04-17 10:00:00’> > slow_report3.log
(4)分析指含有select语句的慢查询:pt-query-digest–filter ‘$event->{fingerprint} =~ m/^select/i’ slow.log> slow_report4.log
(5) 针对某个用户的慢查询:pt-query-digest–filter ‘($event->{user} || “”) =~ m/^root/i’ slow.log> slow_report5.log
(6) 查询所有所有的全表扫描或full join的慢查询:pt-query-digest–filter ‘(( e v e n t − > F u l l s c a n ∣ ∣ " " ) e q " y e s " ) ∣ ∣ ( ( event->{Full_scan} || "") eq "yes") ||(( event−>Fullscan∣∣"")eq"yes")∣∣((event->{Full_join} || “”) eq “yes”)’ slow.log> slow_report6.log
(7)把查询保存到query_review表:pt-query-digest --user=root –password=abc123 --review h=localhost,D=test,t=query_review–create-review-table slow.log
(8)把查询保存到query_history表
pt-query-digest --user=root –password=abc123 --review h=localhost,D=test,t=query_ history–create-review-table slow.log_20140401
pt-query-digest --user=root –password=abc123–review h=localhost,D=test,t=query_history–create-review-table slow.log_20140402(9)通过tcpdump抓取mysql的tcp协议数据,然后再分析
tcpdump -s 65535 -x -nn -q -tttt -i any -c 1000 port 3306 > mysql.tcp.txt
pt-query-digest --type tcpdump mysql.tcp.txt> slow_report9.log(10)分析binlog
mysqlbinlog mysql-bin.000093 > mysql-bin000093.sql
pt-query-digest --type=binlog mysql-bin000093.sql > slow_report10.log(11)分析general log
pt-query-digest --type=genlog localhost.log > slow_report11.log -
如何通过慢查询日志发现问题
从何处入手分析SQL?
A:查询次数多且每次查询占用时间长的SQL,通常为pt-query-digest分析结果的前几个查询。
如下图,注意查看一个查询的总执行次数(total)以及占总次数的百分比(pct),如果一个SQL执行次数少占用时间(Exec time)长,那么这就是一个值得关注的SQL,其他几行属性也依照此逻辑查看即可。
B:IO大的SQL,注意pt-query-digest分析结果中的Rows examine字段。
Rows examine越大说明扫描行数多、IO大,数据库最主要的瓶颈在于IO,所以IO大的SQL值得重点关注。C:未命中索引的SQL,注意pt-query-digest分析结果中Rows examine与Rows send的对比。
扫描行数(Rows examine)远远大于发送行数(Rows send)说明使用的索引不合理导致了大范围的扫描。找到问题SQL后如何优化?
请查看《基于MySQL的SQL优化》的其他博文,后续还会继续更新该系列。