*本文章使用数据均来自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优化》的其他博文，后续还会继续更新该系列。
643
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
