MySQL慢查询日志全解析

发表于 2024-10-11 分类于 MySQL 阅读次数：本文字数： 2.4k 阅读时长 ≈ 9 分钟

前言

慢查询日志在日常数据库运维中经常会用到，我们可以通过查看慢查询日志来获得效率较差的 SQL ，然后可以进行 SQL 优化。本篇文章我们一起来学习下慢查询日志相关知识。

慢查询日志简介

慢查询日志（Slow Query Log），主要用来记录在 MySQL 中执行时间超过指定时间的 SQL 语句。通过慢查询日志，可以查找出哪些语句的执行效率低，以便进行优化。

默认情况下，MySQL 并没有开启慢查询日志，可以通过修改 slow_query_log 参数来打开慢查询日志。与慢查询日志相关的参数介绍如下：

slow_query_log：是否启用慢查询日志，默认为0，可设置为0、1，1表示开启。
slow_query_log_file：指定慢查询日志位置及名称，默认值为host_name-slow.log，可指定绝对路径。
long_query_time：慢查询执行时间阈值，超过此时间会记录，默认为10，单位为秒(s)。
log_output：慢查询日志输出目标，默认为file，即输出到文件。
log_timestamps：主要是控制 error log、slow log、genera log 日志文件中的显示时区，默认使用UTC时区，建议改为 SYSTEM 系统时区。
log_queries_not_using_indexes：是否记录所有未使用索引的查询语句，默认为off。
min_examined_row_limit：对于查询扫描行数小于此参数的SQL，将不会记录到慢查询日志中，默认为0。
log_slow_admin_statements：慢速管理语句是否写入慢查询日志中，管理语句包含 alter table、create index 等，默认为 off 即不写入。

一般情况下，我们只需开启慢查询日志记录，配置下阈值时间，其余参数可按默认配置。对于阈值时间，可灵活调整，比如说可以设置为 1s 或 3s 。

慢查询日志实战

在配置文件中，我们可以设置以下几个慢查询日志相关参数：

# 慢查询日志相关配置，可根据实际情况修改
vim /etc/my.cnf 
[mysqld] 
slow_query_log = 1
slow_query_log_file = /data/mysql/logs/slow.log
long_query_time = 1
log_timestamps = SYSTEM
log_output = FILE

下面我们具体看下，慢查询日志会记录哪些内容？我们执行一条较慢的查询 SQL ，来看下在慢查询日志中的体现。

# 该条SQL执行时间超过阈值

# Time: 2021-05-13T17:38:03.687811+08:00
# User@Host: root[root] @  [192.168.85.0]  Id: 2604943
# Query_time: 1.099889  Lock_time: 0.000144 Rows_sent: 39  Rows_examined: 45305
SET timestamp=1620898683;
select * from test_table where col_name like '%测试%';

如果启用了慢速查询日志，并且选择了 FILE 作为输出目标，则写入日志的每个语句都以 # 字符开头。对于每一组慢SQL，第一行记录的是该条 SQL 执行的时刻（如果 log_timestamps 参数为 UTC ，则改时间会显示 UTC 时区时间），第二行记录的是执行该语句的用户和 IP 以及链接 id ，第三行的几个字段解释如下：

Query_time: duration 语句执行时间，以秒为单位。
Lock_time: duration 获取锁的时间(以秒为单位)。
Rows_sent: N 发送给 Client 端的行数。
Rows_examined: N 服务器层检查的行数(不计算存储引擎内部的任何处理)。

下面两行分别是此语句执行时候的时间戳和具体慢 SQL 。

在实际环境下，不建议开启 log_queries_not_using_indexes 参数，此参数打开后可能导致慢查询日志迅速增长。对于慢查询日志的筛选与分析，我们可以借助 mysqldumpslow、pt-query-digest 等工具来分析。对于慢查询日志文件，要定期进行归档处理，比如可以暂时关闭慢查询日志，然后将旧文件重命名，之后再开启慢查询日志，这样就会写入新的日志文件中，有效减小日志体积。

慢查询日志分析

安装使用`pt-query-digest`

Windows

Windows环境使用pt-query-digest分析mysql慢查询日志

下载安装：`perl`

pt-query-digest是一个perl语言编写的脚本，windows环境默认不支持perl，因此需要安装perl脚本的依赖程序。
从官网下载草莓perl(完全开源) http://strawberryperl.com/
winget.exe install --id "StrawberryPerl.StrawberryPerl" --exact --source winget --accept-source-agreements --disable-interactivity --silent --accept-package-agreements --force
scoop install Main/perl

下载`pt-query-digest.pl`

打开页面https://www.percona.com/get/pt-query-digest
复制所有页面上的内容，保存到mysql/bin目录下，文件名为pt-query-digest.pl

工具使用说明

1、先安装下载的perl程序。安装完成后打开cmd窗口执行: perl -version
如果命令不能正确执行，请配置环境变量。
2、将pt-query-digest.pl放到mysql/bin目录，然后打开cmd窗口进入mysql/bin目录载执行per脚本。
3、执行perl脚本分析慢查询日志。常用的命令如下：

功能说明	脚本命令
直接分析慢查询文件	`perl pt-query-digest.pl “D:\software\MySQL\MySQL Server 5.7\Data\WIN-1OU3SGBLNIN-slow.log” > slow_report1.log`
只分析最近12小时的日志	`perl pt-query-digest.pl --since=12h “D:\software\MySQL\MySQL Server 5.7\Data\WIN-1OU3SGBLNIN-slow.log” > slow_report2.log`
分析某段时间的日志	`perl pt-query-digest.pl –since ‘2019-10-01 00:00:00.000’ --until ‘2019-12-31 08:00:00.000’ “D:\software\MySQL\MySQL Server 5.7\Data\WIN-1OU3SGBLNIN-slow.log” > slow_report3.log`
分析select语句的日志	`perl pt-query-digest.pl --filter ‘$event->{fingerprint} =~ m/^select/i’ “D:\software\MySQL\MySQL Server 5.7\Data\WIN-1OU3SGBLNIN-slow.log” > slow_report4.log`
分析binlog	`mysqlbinlog mysql-bin.000093 > mysql-bin000093.sql` `perl pt-query-digest --type=binlog mysql-bin000093.sql > slow_report10.log`

Linux

yum -y install perl-DBD-MySQL
yum -y install perl-Digest-MD5

# 进入安装目录
cd /usr/local/src
# 下载percona-toolkit 工具包
wget percona.com/get/percona-toolkit.tar.gz
# 解压
tar zxf percona-toolkit.tar.gz
# 进入解压文件夹
cd /usr/local/src/percona-toolkit-3.1.0
# 安装perl模块，制定依赖路径
perl Makefile.PL PREFIX=/usr/local/percona-toolkit
make && make install

发现没找到pt-query-digest命令，是因为bash命令默认是从/usr/bin下找的。

如果rpm安装，会默认添加到/usr/bin下。

而我们现在是编译二进制安装到，并且默认是装到了/usr/local/percona-toolkit下，发现本文件夹下有个bin目录，pt工具都在其下。

本次使用到主力工具，pt-query-digest，执行命令，进行慢日志分析

# 文档说明 https://docs.percona.com/percona-toolkit/pt-query-digest.html#cmdoption-pt-query-digest

# 直接分析慢查询文件
./pt-query-digest /usr/local/mysql/data/slow.log

# 通过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

分析结果参考如下

第一部分
该工具执行日志分析的用户时间，系统时间，物理内存占用大小，虚拟内存占用大小
# 360ms user time, 10ms system time, 22.56M rss, 187.09M vsz
工具执行时间
# Current date: Fri Mar 20 22:54:14 2020
运行分析工具的主机名    
# Hostname: iZ2zebthf35ejlps5v87ksZ
被分析的文件名
# Files: /usr/local/src/slowsqlExample/slow0312.log
语句总数量，唯一的语句数量，QPS，并发数
# Overall: 906 total, 21 unique, 0.02 QPS, 0.07x concurrency _____________
日志记录的时间范围
# Time range: 2020-03-11 12:22:13 to 2020-03-12 00:16:57
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
语句执行时间
# Exec time          2991s      2s     10s      3s      5s      1s      3s
锁占用时间
# Lock time          552ms    24us   371ms   609us   103us    12ms    57us
发送到客户端的行数
# Rows sent        167.53k       0  17.99k  189.35  487.09   1.22k       0
select语句扫描行数
# Rows examine     980.73M     238   1.96M   1.08M   1.95M 757.80k 753.18k
查询的字符数
# Query size       258.71k      17   1.77k  292.41  463.90  202.02  329.68


第二部分
# Profile
Rank：所有语句的排名，默认按查询时间降序排列，通过--order-by指定
Query ID：语句的ID，（去掉多余空格和文本字符，计算hash值）
Response：总的响应时间
time：该查询在本次分析中总的时间占比
calls：执行次数，即本次分析总共有多少条这种类型的查询语句
R/Call：平均每次执行的响应时间
V/M：响应时间Variance-to-mean的比率
Item：查询对象
# Rank Query ID                        Response time   Calls R/Call V/M   
# ==== =============================== =============== ===== ====== ===== 
#    1 0xABD1DCCCCD5AA5128E10C27B34... 1246.6948 41.7%   283 4.4053  0.04 UPDATE ziweidashi_deviceinfo
#    2 0x6914B81AAD1785E50708ABD113...  877.6900 29.3%   339 2.5891  0.09 SELECT birthDay_notify
#    3 0x44D9474C6D5C58DD07B5FEEA0D...  299.4193 10.0%    71 4.2172  0.05 SELECT tmall_product_orders
#    4 0xA9BE84CBE3DAA9B1CDD9B5A9EC...  127.0137  4.2%    46 2.7612  0.04 SELECT daily_user_action_log
#    5 0xCF0E12117C971C3013142E3717...  118.3138  4.0%    49 2.4146  0.05 SELECT tmall_user_take_coupon_record
#    6 0x94263184D24186330B13193534...   97.0805  3.2%    35 2.7737  0.56 SELECT tgg_users
#    7 0xC51165F1287A2ECDA221AC1F54...   52.5870  1.8%    22 2.3903  0.04 SELECT util_user_task_log
#    8 0xB8004D6D8A7A7967E04CD81E26...   43.7895  1.5%    16 2.7368  0.08 SELECT daily_user_action_log
#    9 0x910E19224F33DAA6391927B8E8...   41.3720  1.4%    15 2.7581  1.17 SELECT qifugong_tianbi_record
# MISC 0xMISC                            86.7871  2.9%    30 2.8929   0.0 <12 ITEMS>


第三及后续部分，第一条查询语句 query id：0xABD1DCCCCD5AA5128E10C27B34BC04E7
# Query 1: 0.01 QPS, 0.03x concurrency, ID 0xABD1DCCCCD5AA5128E10C27B34BC04E7 at byte 355748
# Scores: V/M = 0.04
# Time range: 2020-03-11 12:24:03 to 2020-03-12 00:16:13
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         31     283
# Exec time     41   1247s      4s      8s      4s      5s   437ms      4s
# Lock time     69   386ms    24us   371ms     1ms    93us    21ms    44us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine  18 180.00M 651.14k 651.45k 651.29k 650.62k       0 650.62k
# Query size    10  27.64k     100     100     100     100       0     100
# String:
数据库名
# Databases    taxen_ziweidashi
执行主机
# Hosts        118.190.93.166
执行用户
# Users        devAccount
查询时间占比
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `taxen_ziweidashi` LIKE 'ziweidashi_deviceinfo'\G
#    SHOW CREATE TABLE `taxen_ziweidashi`.`ziweidashi_deviceinfo`\G
UPDATE ziweidashi_deviceinfo
         SET expired = 1 
        WHERE createTime   <=   1583942580685\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select  expired = 1 from ziweidashi_deviceinfo where  createTime   <=   1583942580685\G

# Query 2: 0.03 QPS, 0.07x concurrency, ID 0x6914B81AAD1785E50708ABD11319E02E at byte 13829
# Scores: V/M = 0.09
# Time range: 2020-03-11 12:22:13 to 16:05:47
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         37     339
# Exec time     29    878s      2s      4s      3s      4s   472ms      2s
# Lock time      5    29ms    31us     4ms    86us    98us   229us    66us
# Rows sent      0      24       0       2    0.07       0    0.32       0
# Rows examine  67 665.20M   1.96M   1.96M   1.96M   1.96M       0   1.96M
# Query size    59 154.47k     462     467  466.60  463.90    2.07  463.90
# String:
# Hosts        10.66.186.115
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+
# Tables
#    SHOW TABLE STATUS LIKE 'birthDay_notify'\G
#    SHOW CREATE TABLE `birthDay_notify`\G
# EXPLAIN /*!50100 PARTITIONS*/
select birthdayno0_.id as id1_1_, birthdayno0_.index_card_show_date as index_ca2_1_, birthdayno0_.userId as userId3_1_, birthdayno0_.push_content as push_con4_1_, birthdayno0_.card_content as card_con5_1_, birthdayno0_.birthday_userId as birthday6_1_, birthdayno0_.birthday_contactId as birthday7_1_, birthdayno0_.need_push as need_pus8_1_ from birthDay_notify birthdayno0_ where birthdayno0_.userId=1304747 and birthdayno0_.index_card_show_date='2020-03-11 00:00:00'\G

……省略

前言