开发者社区> 云深知何处> 正文
阿里云
为了无法计算的价值
打开APP
阿里云APP内打开

mysql慢查询日志解析

简介: MySQL数据库中慢查询日志是常用的性能诊断手段,mysqldumpslow和percona的pt-query-digest是常用的MySQL慢日志解析工具,本文中也包含了怎样用docker使用sysbench创建测试数据和运行oltp测试
+关注继续查看

1 打开及设置MySQL的慢查询日志

慢查询日志是MySQL中常用的性能诊断工具,通过慢查询日志把执行时间超过一定时间限制(默认10秒)的sql语句记录下来,通过收集一个时间段内(数据库出现性能问题)性能运行欠佳的sql语句,进行统一的分析和诊断,是DBA解决MySQL数据库常用的方法之一。

慢查询日志默认是关闭的。

mysql> show variables like '%slow_query%';
    +---------------------------+---------------------------------------------+
    | Variable_name             | Value                                       |
    +---------------------------+---------------------------------------------+                                         |
    | slow_query_log            | OFF                                         |
    | slow_query_log_file       | /mysqldata/iZ2ze0t8khaprrpfvmevjiZ-slow.log |
    +---------------------------+---------------------------------------------+
    5 rows in set (0.01 sec)

要想打开慢查询日志,可以编辑MySQL数据库配置文件,在[mysqld]部分 加入slow_query_log=on,重启数据库。如果不想重启数据库,可以登录数据库直接设置slow_query_log全局变量。

mysql> set global slow_query_log=on;
    Query OK, 0 rows affected (0.14 sec)

这样设置对于设置后新建的连接有效,对于当前已连接会话是无效的,退出当前会话后重新登录数据库

mysql> show global variables like '%slow_query%';
    +---------------------------+---------------------------------------------+
    | Variable_name             | Value                                       |
    | slow_query_log            | ON                                          |
    | slow_query_log_file       | /mysqldata/iZ2ze0t8khaprrpfvmevjiZ-slow.log |
    +---------------------------+---------------------------------------------+

慢查询日志已经打开,捕获的慢查询日志存储在文件 /mysqldata/iZ2ze0t8khaprrpfvmevjiZ-slow.log中,这个文件是数据库的默认设置,/mysqldataMySQL的数据目录,iZ2ze0t8khaprrpfvmevjiZ是数据库服务器的主机名。

慢查询日志有2个常用的选项需要调整,一个是long_query_time,设置多长时间之上的查询需要捕获,另一个是log_queries_not_using_indexes,这个选项默认是off,如果设置为on,会捕获所有没有使用索引的sql语句。这一点对于DBA来说很有用,众所周知的是MySQL只支持嵌套连接,而索引对于嵌套连接有十分重要,如果能一次性获取数据库中所有没有使用索引的sql给DBA提供了很大的方便。

mysql> set global log_queries_not_using_indexes=on;
    Query OK, 0 rows affected (0.00 sec)
mysql> set  long_query_time=0.1;
    Query OK, 0 rows affected (0.00 sec)

2 用sysbench(docker)方式创建测试数据

使用docker运行sysbench的原因一个是安装配置十分简单,不用在操作系统安装sysbench以及依赖包,只要拉取镜像,运行容器即可,另一个是这样使用对现有的操作系统环境几乎没什么影响,要删除也十分方便,只要把容器删除即可。

2.1 安装docker

docker的安装十分简单,这里只列出步骤

[root]# yum install -y yum-utils 
[root]# yum-config-manager --add-repo http://mirrors.aliyun.com/docker-ce/linux/centos/docker-ce.repo
    Adding repo from: http://mirrors.aliyun.com/docker-ce/linux/centos/docker-ce.repo
[root]# yum makecache fast && yum -y install docker-ce
[root@ ~]# systemctl start docker
[root@ ~]# systemctl status docker
    ● docker.service - Docker Application Container Engine
       Loaded: loaded (/usr/lib/systemd/system/docker.service; disabled; vendor preset: disabled)
       Active: active (running) since Mon 2022-08-15 09:51:47 CST; 8s ago

2.2 拉取sysbench映像

搜索sysbench映像

[root@ ~]# docker search sysbench
   NAME                             DESCRIPTION                                     STARS     OFFICIAL   AUTOMATED
   severalnines/sysbench            Sysbench 1.0                                    18                   [OK]

拉取搜到的第一个映像

[root@ ~]# docker pull severalnines/sysbench
    Using default tag: latest
    latest: Pulling from severalnines/sysbench
    e79bb959ec00: Pull complete
    6f6da6c9c901: Pull complete
    206bc115af8c: Pull complete
    ba6ac542f035: Pull complete
    1f1dcb85e92e: Pull complete
    Digest: sha256:64cd003bfa21eaab22f985e7b95f90d21a970229f5f628718657dd1bae669abd
    Status: Downloaded newer image for severalnines/sysbench:latest
    docker.io/severalnines/sysbench:latest

映像拉取成功,查看以下本地映像

[root@ ~]# docker images
    REPOSITORY              TAG       IMAGE ID       CREATED       SIZE
    severalnines/sysbench   latest    0e71335a2211   3 years ago   429MB

2.3 创建sysbench数据库及账号

本地已经有sysbench映像了,在MySQL中创建一个sysbench数据库及用来连接这个数据库的账号和密码

mysql> create database sysbenchdb;
    Query OK, 1 row affected (0.00 sec)
    
mysql> grant all privileges on sysbenchdb.* to u_sysbench@'%' identified by '123456';
    Query OK, 0 rows affected, 1 warning (0.00 sec)
mysql> flush privileges;
    Query OK, 0 rows affected (0.00 sec)

创建账号密码后不要忘了刷新权限,否则会登录不到数据库。

2.4 创建测试数据

使用下面命令创建测试数据。

[root@ ~]# docker run --rm=true --name=sb-prepare 0e71335a2211 sysbench --test=/usr/share/sysbench/oltp_read_only.lua --mysql-host=172.20.11.244 --mysql-port=3306 --mysql-db=sysbenchdb --mysql-user="u_sysbench"  --mysql-password='123456' --tables=4 --table_size=10000000 --threads=2 --time=300 --report-interval=3 --db-driver=mysql --db-ps-mode=disable --skip-trx=on --mysql-ignore-errors=6002,6004,4012,2013,4016,1062 prepare

这个命令很长,看起来稍稍有点复杂,这了略微解释以下,除了第一行之外,这个命令就是sysbench在操作系统下直接安装时创建测试数据的命令。第一行是用docker来运行sysbench,--name设置容器的名称,--rm=true是在创建测试数据完成后删除容器,这是个一次性的任务,完成了之后容器的使命也就结束了,留着也没啥用。0e71335a2211是我们拉取的sysbench映像的id,这个也可以用名称,后面跟的就是这个容器启动后要运行的命令。

--test是要运行的sysbench的脚本,后面几个是连接到数据库的信息,因为是sysbench是运行在docker中,这里不能用本地地址(127.0.0.1或者localhost)作为主机名,后面是表数量、线程数、表大小,时间,报道间隔,数据库驱动器、事务选项、要忽略的错误等,最后的prepare是sysbench要运行的命令。这里因为是测试慢查询,表设得大一点。这个命令的输出是这样的。

  WARNING: the --test option is deprecated. You can pass a script name or path on the command line without any options.
            sysbench 1.0.17 (using bundled LuaJIT 2.1.0-beta2)

            Initializing worker threads...

            Creating table 'sbtest2'...
            Creating table 'sbtest1'...
            Inserting 10000000 records into 'sbtest1'
            Inserting 10000000 records into 'sbtest2'
            Creating a secondary index on 'sbtest1'...
            Creating a secondary index on 'sbtest2'...
            Creating table 'sbtest3'...
            Inserting 10000000 records into 'sbtest3'
            Creating table 'sbtest4'...
            Inserting 10000000 records into 'sbtest4'
            Creating a secondary index on 'sbtest3'...
            Creating a secondary index on 'sbtest4'...  

不但创建了表,也创建了索引。

2.5 运行sysbench测试

[root@ ~]# docker run --name=sb-run 0e71335a2211 sysbench --test=/usr/share/sysbench/oltp_read_only.lua --mysql-host=172.20.11.244 --mysql-port=3306 --mysql-db=sysbenchdb --mysql-user="u_sysbench"  --mysql-password=123456 --tables=4 --table_size=10000000 --threads=4 --time=300 --report-interval=10 --db-driver=mysql --db-ps-mode=disable --skip-trx=on --mysql-ignore-errors=6002,6004,4012,2013,4016,1062 run

这个命令和创建测试数据的命令大部分是相同的,第一行没有了--rm=true,这个测试以后可能会还要做,所以运行完之后保留这个容器。sysbench

运行的命令是run,不是prepare。这个命令的输出如下:

  SQL statistics:
              queries performed:
                  read:                            1477406
                  write:                           0
                  other:                           0
                  total:                           1477406
              transactions:                        105529 (351.72 per sec.)
              queries:                             1477406 (4924.08 per sec.)
              ignored errors:                      0      (0.00 per sec.)
              reconnects:                          0      (0.00 per sec.)
          
          General statistics:
              total time:                          300.0350s
              total number of events:              105529
          
          Latency (ms):
                   min:                                    2.22
                   avg:                                   11.37
                   max:                                  349.88
                   95th percentile:                       15.00
                   sum:                              1199812.63
          
          Threads fairness:
              events (avg/stddev):           26382.2500/23.23
              execution time (avg/stddev):   299.9532/0.01

3 MySQL慢查询日志分析

3.1 使用文本工具

慢查询日志是文本文件,可以直接使用linux文本命令来查看

[root@ mysqldata]# cat iZ2ze0t8khaprrpfvmevjiZ-slow.log
    /usr/local/mysql/bin/mysqld, Version: 5.7.34 (MySQL Community Server (GPL)). started with:
    Tcp port: 3306  Unix socket: /tmp/mysql.sock
    Time                 Id Command    Argument
    /usr/local/mysql/bin/mysqld, Version: 5.7.34 (MySQL Community Server (GPL)). started with:
    Tcp port: 3306  Unix socket: /tmp/mysql.sock
    Time                 Id Command    Argument
    # Time: 2022-08-15T02:46:17.506869Z
    # User@Host: root[root] @ localhost []  Id:    34
    # Query_time: 22.707483  Lock_time: 0.000098 Rows_sent: 400000  Rows_examined: 800000
    use sysbenchdb;
    SET timestamp=1660531577;
    select * from sbtest1  union select * from sbtest2 union select * from sbtest3 union select * from sbtest4;
    # Time: 2022-08-15T02:52:41.908776Z
    # User@Host: root[root] @ localhost []  Id:    37
    # Query_time: 24.590315  Lock_time: 0.000109 Rows_sent: 1  Rows_examined: 1200000
    SET timestamp=1660531961;
    select count(*) from (select * from sbtest1  union select * from sbtest2 union select * from sbtest3 union select * from sbtest4) a;

慢查询日志中显示了每一个捕获的sql语句的时间,连接信息,查询时间、锁时间,发送的行数,扫描行数等,可以看,但是不太直观。

3.2 使用mysqldumpslow

mysqldumpslow是MySQL官方提供的慢查询日志查看工具,随着MySQL数据库一起安装,这个工具对慢查询日志做了一定的格式化,查看起来要方面一些。

[root@ mysqldata]# mysqldumpslow -v iZ2ze0t8khaprrpfvmevjiZ-slow.log
      
      Reading mysql slow query log from iZ2ze0t8khaprrpfvmevjiZ-slow.log
      Count: 1  Time=24.59s (24s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost
        select count(*) from (select * from sbtest1  union select * from sbtest2 union select * from sbtest3 union select * from sbtest4) a
      
      Count: 1  Time=22.71s (22s)  Lock=0.00s (0s)  Rows=400000.0 (400000), root[root]@localhost
        select * from sbtest1  union select * from sbtest2 union select * from sbtest3 union select * from sbtest4
      
      Count: 1  Time=0.41s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
        select pad from sbtest1 where c = "S"


显示的信息看起来更直观了一些,对每个sql的执行次数,查询时间,查询行数做了汇总。

4 使用percona的pt-query-digest分析慢查询日志

4.1 pt-query-digest的安装

使用pt-query-digest,需要安装percona-toolkit,这个工具有几个依赖包需要安装,这里列出安装命令,不做解释。

[root@ mysqldata]# yum -y install perl-IO-Socket-SSL
[root@ mysqldata]# yum -y install perl
[root@ mysqldata]# yum -y install perl-DBD-MySQL        
[root@ mysqldata]# yum install perl-Digest-MD5 -y

对于percona-toolkit,最简单的安装方式是yum源安装,首先下载percona-toolkit的官方yum源

[root@ mysqldata]# wget percona.com/get/percona-toolkit.rpm
    percona-toolkit.rpm               [  <=>                                             ]  51.08K   203KB/s    in 0.3s

    2022-08-15 11:20:59 (203 KB/s) - ‘percona-toolkit.rpm’ saved [52310]

下载的yum源是一个rpm包,安装一下

[root@~]# yum install https://repo.percona.com/yum/percona-release-latest.noarch.rpm

yum源安装完成之后,就可以安装percona-toolkit工具了

[root@ ~]# yum install percona-toolkit
Percona Original release/x86_64 YUM repository                                          1.9 MB/s | 8.7 MB     00:04
Percona Original release/noarch YUM repository                                          2.8 kB/s | 3.6 kB     00:01
Percona Release release/noarch YUM repository                                           1.4 kB/s | 1.8 kB     00:01
Dependencies resolved.
========================================================================================================================
 Package                      Architecture       Version                       Repository                          Size
========================================================================================================================
Installing:
 percona-toolkit              x86_64             3.4.0-3.el8                   percona-release-x86_64              20 M
Installing dependencies:
 perl-TermReadKey             x86_64             2.37-7.el8                    AppStream                           40 k
 perl-Time-HiRes              x86_64             4:1.9758-2.el8                AppStream                           61 k

Installed:
  percona-toolkit-3.4.0-3.el8.x86_64    perl-TermReadKey-2.37-7.el8.x86_64    perl-Time-HiRes-4:1.9758-2.el8.x86_64

Complete!

4.2 分析慢查询日志

pt-query-digest的使用非常简单,只有一个必须的参数,就是要分析的慢查询日志文件名。

这个命令的输出可以分为三个部分,第一部分是对整个慢查询日志作为分析,所有慢查询语句的执行时间,慢查询语句执行的最短时间,最长时间,平均时间,时间的中位值,标准差等,看了这个,对这个时间段的sql语句总体的运行情况就有了基本的了解。

[root@ mysqldata]# pt-query-digest iZ2ze0t8khaprrpfvmevjiZ-slow.log

        # 180ms user time, 30ms system time, 34.11M rss, 99.52M vsz
        # Current date: Mon Aug 15 14:54:31 2022
        # Hostname: iZ2ze0t8khaprrpfvmevjiZ
        # Files: iZ2ze0t8khaprrpfvmevjiZ-slow.log
        # Overall: 5 total, 5 unique, 0.02 QPS, 0.59x concurrency ________________
        # Time range: 2022-08-15T06:50:43 to 2022-08-15T06:54:04
        # Attribute          total     min     max     avg     95%  stddev  median
        # ============     ======= ======= ======= ======= ======= ======= =======
        # Exec time           119s   104ms     91s     24s     88s     34s   189ms
        # Lock time           50ms    24us    42ms    10ms    42ms    16ms    44us
        # Rows sent            201       0     100   40.20   97.36   47.53    0.99
        # Rows examine      20.40M     100  10.86M   4.08M  10.76M   4.94M  299.03
        # Query size           316      43      78   63.20   76.28   12.04   62.76

第二部分列出排在前列的慢查询语句,这里列出的语句应该是关注的重点。

# Profile
        # Rank Query ID                            Response time Calls R/Call  V/M
        # ==== =================================== ============= ===== ======= ===
        #    1 0xEE987693396E1A09E0A9089F9AFA861A  91.0625 76.5%     1 91.0625  0.00 SELECT UNION sbtest?
        #    2 0xB3461D1C50B98133F6292480060B3436  27.6287 23.2%     1 27.6287  0.00 SELECT sbtest?
        # MISC 0xMISC                               0.4052  0.3%     3  0.1351   0.0 <3 ITEMS>

第三部分是每条慢查询语句具体的信息

# Query 1: 0 QPS, 0x concurrency, ID 0xEE987693396E1A09E0A9089F9AFA861A at byte 1056
        # This item is included in the report because it matches --limit.
        # Scores: V/M = 0.00
        # Time range: all events occurred at 2022-08-15T06:54:04
        # Attribute    pct   total     min     max     avg     95%  stddev  median
        # ============ === ======= ======= ======= ======= ======= ======= =======
        # Count         20       1
        # Exec time     76     91s     91s     91s     91s     91s       0     91s
        # Lock time     16     8ms     8ms     8ms     8ms     8ms       0     8ms
        # Rows sent      0       0       0       0       0       0       0       0
        # Rows examine  53  10.86M  10.86M  10.86M  10.86M  10.86M       0  10.86M
        # Query size    23      74      74      74      74      74       0      74
        # String:
        # Hosts        localhost
        # Users        root
        # Query_time distribution
        #   1us
        #  10us
        # 100us
        #   1ms
        #  10ms
        # 100ms
        #    1s
        #  10s+  ################################################################
        # Tables
        #    SHOW TABLE STATUS LIKE 'sbtest1'\G
        #    SHOW CREATE TABLE `sbtest1`\G
        #    SHOW TABLE STATUS LIKE 'sbtest2'\G
        #    SHOW CREATE TABLE `sbtest2`\G
        # EXPLAIN /*!50100 PARTITIONS*/
        select count(*) from (select * from sbtest1 union select * from sbtest2) a\G

        # Query 2: 0 QPS, 0x concurrency, ID 0xB3461D1C50B98133F6292480060B3436 at byte 816
        # This item is included in the report because it matches --limit.
        # Scores: V/M = 0.00
        # Time range: all events occurred at 2022-08-15T06:50:56
        # Attribute    pct   total     min     max     avg     95%  stddev  median
        # ============ === ======= ======= ======= ======= ======= ======= =======
        # Count         20       1
        # Exec time     23     28s     28s     28s     28s     28s       0     28s
        # Lock time     82    42ms    42ms    42ms    42ms    42ms       0    42ms
        # Rows sent      0       0       0       0       0       0       0       0
        # Rows examine  46   9.54M   9.54M   9.54M   9.54M   9.54M       0   9.54M
        # Query size    13      43      43      43      43      43       0      43
        # String:
        # Hosts        localhost
        # Users        root
        # Query_time distribution
        #   1us
        #  10us
        # 100us
        #   1ms
        #  10ms
        # 100ms
        #    1s
        #  10s+  ################################################################
        # Tables
        #    SHOW TABLE STATUS LIKE 'sbtest1'\G
        #    SHOW CREATE TABLE `sbtest1`\G
        # EXPLAIN /*!50100 PARTITIONS*/
        select pad from sbtest1 where c = 'changan'\G

从上面的输出来看,对每一条语句都进行了分析,一眼就可以看到各个指标的最大值、最小值,平均值,均值、查询事件分布等,给性能诊断提供了丰富的信息。

版权声明:本文内容由阿里云实名注册用户自发贡献,版权归原作者所有,阿里云开发者社区不拥有其著作权,亦不承担相应法律责任。具体规则请查看《阿里云开发者社区用户服务协议》和《阿里云开发者社区知识产权保护指引》。如果您发现本社区中有涉嫌抄袭的内容,填写侵权投诉表单进行举报,一经查实,本社区将立刻删除涉嫌侵权内容。

相关文章
69
文章
0
问答
文章排行榜
最热
最新
相关电子书
更多
低代码开发师(初级)实战教程
立即下载
阿里巴巴DevOps 最佳实践手册
立即下载
冬季实战营第三期:MySQL数据库进阶实战
立即下载