阿里云-云小站(无限量代金券发放中)
【腾讯云】云服务器、云数据库、COS、CDN、短信等热卖云产品特惠抢购

MySQL慢查询功能详解

221次阅读
没有评论

共计 9796 个字符,预计需要花费 25 分钟才能阅读完成。

有人的地方就有江湖,数据库也是,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:是表示按照何种方式排序,子参数如下:

    c、t、l、r:分别是按照记录次数、时间、查询时间、返回的记录数来排序,

    ac、at、al、ar:表示相应的倒叙;

-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)、json、json-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 关闭)

正文完
星哥玩云-微信公众号
post-qrcode
 0
星锅
版权声明:本站原创文章,由 星锅 于2022-01-22发表,共计9796字。
转载说明:除特殊说明外本站文章皆由CC-4.0协议发布,转载请注明出处。
【腾讯云】推广者专属福利,新客户无门槛领取总价值高达2860元代金券,每种代金券限量500张,先到先得。
阿里云-最新活动爆款每日限量供应
评论(没有评论)
验证码
【腾讯云】云服务器、云数据库、COS、CDN、短信等云产品特惠热卖中