有人的地方就有江湖, 数据库也是, sql 优化这个问题, 任重道远, 我们总是禁不住有烂 sql 怎么办呢, 还好各大数据库都有相关烂 sql 的收集功能, 而 MySQL 的慢查询收集也是异曲同工, 配合分析 sql 的执行计划, 这个优化就有了搞头了
开启 MySQL 慢查询日志
1. 查看当前慢查询设置情况
- # 查看慢查询时间, 默认 10s, 建议降到 1s 或以下,
- mysql> show variables like "long_query_time";
- +-----------------+----------+
- | Variable_name | Value |
- +-----------------+----------+
- | long_query_time | 1.000000 |
- +-----------------+----------+
- 1 row in set (0.00 sec)
- # 查看慢查询配置情况
- mysql> show variables like "%slow%";
- +-----------------------------------+----------------------+
- | Variable_name | Value |
- +-----------------------------------+----------------------+
- | log_slow_admin_statements | OFF |
- | log_slow_filter | |
- | log_slow_rate_limit | 1 |
- | log_slow_rate_type | session |
- | log_slow_slave_statements | OFF |
- | log_slow_sp_statements | ON |
- | log_slow_verbosity | |
- | max_slowlog_files | 0 |
- | max_slowlog_size | 0 |
- | slow_launch_time | 2 |
- | slow_query_log | ON |
- | slow_query_log_always_write_time | 10.000000 |
- | slow_query_log_file | /tmp/slow_querys.log |
- | slow_query_log_use_global_control | |
- +-----------------------------------+----------------------+
- 14 rows in set (0.01 sec)
其中, slow_query_log 的值是 on 就是已开启功能了
2. 如何开启慢查询功能
方法一: 在服务器上找到 mysql 的配置文件 my.cnf , 然后再 mysqld 模块里追加一下内容, 这样的好处是会一直生效, 不好就是需要重启 mysql 进程
- vim my.cnf
- [mysqld]
- slow_query_log = ON
- # 定义慢查询日志的路径
- slow_query_log_file = /tmp/slow_querys.log
- # 定义查过多少秒的查询算是慢查询, 我这里定义的是 1 秒, 5.6 之后允许设置少于 1 秒, 例如 0.1 秒
- long_query_time = 1
- # 用来设置是否记录没有使用索引的查询到慢查询记录, 默认关闭, 看需求开启, 会产生很多日志, 可动态修改
- #log-queries-not-using-indexes
管理指令也会被记录到慢查询比如 OPTIMEZE TABLE, ALTER TABLE, 默认关闭, 看需求开启, 会产生很多日志, 可动态修改
#log-slow-admin-statements
然后重启 mysql 服务器即可, 这是通过一下命令看一下慢查询日志的情况:
tail -f /tmp/slow_querys.log
方法二: 通过修改 mysql 的全局变量来处理, 这样做的好处是, 不用重启 mysql 服务器, 登陆到 mysql 上执行一下 sql 脚本即可, 不过重启后就失效了
- # 开启慢查询功能, 1 是开启, 0 是关闭
- mysql> set global slow_query_log=1;
- # 定义查过多少秒的查询算是慢查询, 我这里定义的是 1 秒, 5.6 之后允许设置少于 1 秒, 例如 0.1 秒
- mysql> set global long_query_time=1;
- # 定义慢查询日志的路径
- mysql> set global slow_query_log_file='/tmp/slow_querys.log';
- # 关闭功能: set global slow_query_log=0;
然后通过一下命令查看是否成功
- mysql> show variables like 'long%';
- mysql> show variables like 'slow%';
- # 设置慢查询记录到表中
- #set global log_output='TABLE';
当然了, 你也可以两者合一, 一方面不用重启 mysql 进程就能生效, 另一方面也不用怕重启后参数失效, 效果也是一致的
特别要注意的是 long_query_time 的设置, 5.6 之后支持设置低于 0.1 秒, 所以记录的详细程度, 就看你自己的需求, 数据库容量比较大的, 超过 0.1 秒还是比较多, 所以就变得有点不合理了
慢查询日志的记录定义
直接查看 mysql 的慢查询日志分析, 比如我们可以 tail -f slow_query.log 查看里面的内容
- tail -f slow_query.log
- # Time: 110107 16:22:11
- # User@Host: root[root] @ localhost []
- # Query_time: 9.869362 Lock_time: 0.000035 Rows_sent: 1 Rows_examined: 6261774
- SET timestamp=1294388531;
- select count(*) from ep_friends;
字段意义解析:
第一行, SQL 查询执行的时间
第二行, 执行 SQL 查询的连接信息, 用户和连接 IP
第三行, 记录了一些我们比较有用的信息, 如下解析
Query_time, 这条 SQL 执行的时间, 越长则越慢
Lock_time, 在 MySQL 服务器阶段 (不是在存储引擎阶段) 等待表锁时间
Rows_sent, 查询返回的行数
Rows_examined, 查询检查的行数, 越长就当然越费时间
第四行, 设置时间戳, 没有实际意义, 只是和第一行对应执行时间
第五行及后面所有行(第二个# Time: 之前), 执行的 sql 语句记录信息, 因为 sql 可能会很长
分析慢查询的软件
虽然慢查询日志已经够清晰, 但是往往我们的日志记录到的不是只有一条 sql, 可能有很多很多条, 如果不加以统计, 估计要看到猴年马月, 这个时候就需要做统计分析了
方法一: 使用 mysql 程序自带的 mysqldumpslow 命令分析, 例如:
mysqldumpslow -s c -t 10 /tmp/slow-log
这会输出记录次数最多的 10 条 SQL 语句, 得出的结果和上面一般慢查询记录的格式没什么太大差别, 这里就不展开来详细解析了
参数解析:
-s: 是表示按照何种方式排序, 子参数如下:
ctlr: 分别是按照记录次数时间查询时间返回的记录数来排序,
acatalar: 表示相应的倒叙;
-t: 返回前面多少条的数据, 这里意思就是返回 10 条数据了(也可以说是前十)
-g: 后边可以写一个正则匹配模式, 大小写不敏感的, 比如:
/path/mysqldumpslow -s r -t 10 /tmp/slow-log, 得到返回记录集最多的 10 个查询
/path/mysqldumpslow -s t -t 10 -g left join /tmp/slow-log, 得到按照时间排序的前 10 条里面含有左连接的查询语句
方法二: 使用 pt(Percona Toolkit)工具的 pt-query-digest 进行统计分析这个是由 Percona 公司出品的一个用 perl 编写的脚本, 只有安装上 pt 工具集才会存在, 有兴趣的朋友就要先安装 pt 工具了直接分析慢查询文件, 执行如下:
pt-query-digest slow_querys.log>t.txt
因为记录里还是可能有很多 sql 在, 看起来还是费劲, 所以建议输出到文件来看了输出的信息会分成三部分,
第一部分: 总体统计结果
- # 580ms user time, 0 system time, 35.46M rss, 100.01M vsz
- # Current date: Wed Jul 19 14:32:40 2017
- # Hostname: yztserver1
- # Files: slow_querys.log
- # Overall: 2.63k total, 36 unique, 0.03 QPS, 0.03x concurrency ___________
- # Time range: 2017-07-18T03:17:17 to 2017-07-19T06:30:18
- # Attribute total min max avg 95% stddev median
- # ============ ======= ======= ======= ======= ======= ======= =======
- # Exec time 3145s 1s 5s 1s 2s 258ms 1s
- # Lock time 677ms 0 64ms 257us 260us 2ms 144us
- # Rows sent 8.44k 0 5.50k 3.29 0.99 108.92 0.99
- # Rows examine 1.06G 0 2.12M 421.02k 619.64k 155.33k 419.40k
- # Rows affecte 0 0 0 0 0 0 0
- # Bytes sent 9.00M 11 6.24M 3.51k 13.78k 119.76k 65.89
- # Query size 735.85k 6 2.19k 286.72 463.90 128.05 246.02
记录这个慢日志文件里面的所有慢查询统计信息, 通常粗略看看就好了:
Overall: 这个文件里总共有多少条查询, 上例为总共 2.63k 个查询, 也就是 2.63k 条慢查询
Time range: 查询执行的时间范围
unique: 唯一查询数量, 即对查询条件进行参数化以后, 统计的总共有多少个不同的查询, 该例为 36 也就是说这 2.63K 条慢查询, 实际归类为 36 条
Attribute: 属性解析, 其他子项:
total: 总计, min: 最小, max: 最大, avg: 平均,
95%: 把所有值从小到大排列, 位置位于 95% 的那个数, 这个数一般最具有参考价值,
median: 中位数, 把所有值从小到大排列, 位置位于中间那个数
其他就字面意思, 去翻译一下就好
第二部分: 查询分组统计结果
- # Profile
- # Rank Query ID Response time Calls R/Call V/M Item
- # ==== ================== =============== ===== ====== ===== =============
- # 1 0x8965CC929FB1C7B2 2080.0546 66.1% 1816 1.1454 0.03 SELECT 1
- # 2 0x9C57D04CEA1970B4 228.4754 7.3% 131 1.7441 0.10 SELECT 2
- # 3 0x94B4D7AA44982464 138.5964 4.4% 112 1.2375 0.05 SELECT 3
- # 4 0x6BD09392D1D0B5D7 84.1681 2.7% 70 1.2024 0.03 SELECT 4
- # 5 0x1E9926677DBA3657 81.2260 2.6% 68 1.1945 0.03 SELECT 5
- # 6 0xBBCE31227D8C6A93 69.6594 2.2% 56 1.2439 0.05 SELECT 6
- # 7 0x9A691CB1A14640F4 60.4517 1.9% 51 1.1853 0.04 SELECT 7
- # 8 0xDA99A20C8BE81B9C 55.7751 1.8% 46 1.2125 0.05 SELECT 8
- # 9 0x1F53AC684A365326 55.6378 1.8% 45 1.2364 0.03 SELECT 9_
- # 10 0x664E0C18531443A5 38.6894 1.2% 31 1.2480 0.05 SELECT way_bill_main
- # 11 0xF591153EC390D8CA 32.5370 1.0% 28 1.1620 0.01 SELECT way_bill_main
- # 12 0xA3A82D5207F1BC2E 24.6582 0.8% 20 1.2329 0.06 SELECT way_bill_main
- # 13 0xFCED276145371CE4 22.2543 0.7% 18 1.2363 0.05 SELECT way_bill_main
- # 14 0x4895DF4252D5A600 21.3184 0.7% 17 1.2540 0.07 SELECT way_bill_main
- # 16 0xA4DD833DF8C96D04 14.6107 0.5% 13 1.1239 0.01 SELECT way_bill_main
- # 17 0x0426A3C3538CBBA8 13.9799 0.4% 13 1.0754 0.00 SELECT way_bill_main
- # 18 0x2C52F334EF3D8D2D 12.5960 0.4% 10 1.2596 0.03 SELECT way_bill_main
- # MISC 0xMISC 110.2030 3.5% 83 1.3277 0.0 <19 ITEMS>
这部分对查询进行参数化并分组, 然后对各类查询的执行情况进行分析, 结果按总执行时长, 从大到小排序, 恕我改了些显示
Response: 总的响应时间
time: 该查询在本次分析中总的时间占比
calls: 执行次数, 即本次分析总共有多少条这种类型的查询语句
R/Call: 平均每次执行的响应时间
Item : 查询对象
第三部分: 每一种查询的详细统计结果, 这是其中一个
- # Query 1: 0.02 QPS, 0.02x concurrency, ID 0x8965CC929FB1C7B2 at byte 868609
- # This item is included in the report because it matches --limit.
- # Scores: V/M = 0.03
- # Time range: 2017-07-18T03:17:56 to 2017-07-19T06:30:18
- # Attribute pct total min max avg 95% stddev median
- # ============ === ======= ======= ======= ======= ======= ======= =======
- # Count 69 1816
- # Exec time 66 2080s 1s 4s 1s 1s 189ms 1s
- # Lock time 51 349ms 67us 19ms 192us 194us 760us 144us
- # Rows sent 21 1.77k 1 1 1 1 0 1
- # Rows examine 71 771.37M 262.54k 440.03k 434.96k 419.40k 24.34k 419.40k
- # Rows affecte 0 0 0 0 0 0 0 0
- # Bytes sent 1 120.49k 65 68 67.94 65.89 0.35 65.89
- # Query size 60 443.31k 248 250 249.97 246.02 0.00 246.02
- # String:
- # Databases ytttt
- # Hosts 10.25.28.2
- # Last errno 0
- # Users gztttttt
- # Query_time distribution
- # 1us
- # 10us
- # 100us
- # 1ms
- # 10ms
- # 100ms
- # 1s ################################################################
- # 10s+
- # Tables
- # SHOW TABLE STATUS FROM `ytttt` LIKE 'way_bill_main'\G
- # SHOW CREATE TABLE `ytttt`.`way_bill_main`\G
- # SHOW TABLE STATUS FROM `ytttt` LIKE 'scheduler_task'\G
- # SHOW CREATE TABLE `ytttt`.`scheduler_task`\G
- # EXPLAIN /*!50100 PARTITIONS*/
SELECT COUNT(1) FROM 1 as w inner join ..... 此处省略
这部分的上面一部分和第一部分信息类似, 统计该记录 sql 的总运行效率信息, 下面一部分的解析如下:
Databases: 库名
Users: 各个用户执行的次数(占比), 现在只有一个用户, 因为我授权的就是一个库一个独立用户
Query_time distribution : 查询时间分布, 长短体现区间占比, 本例中基本上都是 1s
Tables: 查询中涉及到的表
Explain: 示例, 也就是这条 sql 本身的信息
后面其他信息也大体和这个类似, 只是显示不同的 sql 信息而已, 都属于这个第三部分
pt-query-digest 参数说明:
--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)jsonjson-anon, 一般使用 report, 以便于阅读
--since 从什么时间开始分析, 值为字符串, 可以是指定的某个 yyyy-mm-dd [hh:mm:ss]格式的时间点, 也可以是简单的一个时间值: s(秒)h(小时)m(分钟)d(天), 如 12h 就表示从 12 小时前开始统计
--until 截止时间, 配合 since 可以分析一段时间内的慢查询
其他命令示例:
1. 分析最近 12 小时内的查询:
pt-query-digest --since=12h slow.log> slow_report2.log
2. 分析指定时间范围内的查询:
pt-query-digest slow.log --since '2014-04-17 09:30:00' --until '2014-04-17 10:00:00'>>slow_report3.log
3. 分析指含有 select 语句的慢查询
pt-query-digest--filter '$event->{fingerprint} =~ m/^select/i' slow.log> slow_report4.log
4. 针对某个用户的慢查询
pt-query-digest--filter '($event->{user} ||"") =~ m/^root/i' slow.log> slow_report5.log
5. 查询所有所有的全表扫描或 full join 的慢查询
pt-query-digest--filter '(($event->{Full_scan} ||"") eq "yes") ||(($event->{Full_join} || "") eq"yes")' slow.log> slow_report6.log
6. 把查询保存到 query_review 表
pt-query-digest --user=root password=abc123 --review h=localhost,D=test,t=query_review--create-review-table slow.log
7. 把查询保存到 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
8. 通过 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
9. 分析 binlog
- mysqlbinlog mysql-bin.000093> mysql-bin000093.sql
- pt-query-digest --type=binlog mysql-bin000093.sql> slow_report10.log
10. 分析 general log
pt-query-digest --type=genlog localhost.log> slow_report11.log
其实 pt-query-digest 虽然信息很多, 但是输出的有用信息不见得就比 mysqldumpslow 好很多, 反而眼花缭乱的, 而且还要装多个工具才能用不过可以甩问题给开发看到效率有多差也算是一个好事, 可以说清楚着个 sql 执行了多少次慢查询, 所以实际使用上还是见仁见智, 自己看着办
题外话
一般慢查询日志解决不了问题的话, 就建议开查询日志 general-log 来跟踪 sql 了
大体和上面操作差不多, 先查看当前状态
show variables like 'general%';
可以在 my.cnf 里添加
general-log = 1 开启(0 关闭)
log = /log/mysql_query.log 路径
也可以设置变量那样更改
set global general_log=1 开启(0 关闭)
来源: http://www.linuxidc.com/Linux/2018-03/151340.htm