0 日志分类

常用的日志包括错误日志、慢日志和二进制日志。错误日志默认开启；慢日志是有关性能，优化时会用到此日志；二进制日志在备份恢复和主从架构当中都要用到该日志。
第9章-日志管理 - 图1

1 错误日志

作用：排查MySQL运行过程的故障
配置：
默认就开启了
默认路径和名字：datadir/HOSTNAME.err，数据目录下
自定义错误日志文件位置：
log_error=/tmp/mysql3306.log
重启生效

  1. [mysqld]
  2. user=mysql
  3. basedir=/app/mysql
  4. datadir=/data/mysql/instance01
  5. socket=/tmp/mysql.sock
  6. server_id=6
  7. port=3306
  8. log_error=/data/mysql/instance01/db01_instance01.log
  9. sql_mode=STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION
  10. [mysql]
  11. socket=/tmp/mysql.sock

命令行查看日志位置：
select @@log_error;
image.png

2 二进制日志（binlog）

2.1 作用

  • 主从要依赖二进制日志
  • 数据恢复时需要依赖二进制日志

    2.2 配置

    1）参数介绍
    默认没有开启
    server_id=6 此值小于65535
    log_bin=/data/mysql/instance01/mysql-bin
    说明：
    /data/mysql/instance01：提前定制好的目录，而且要有mysql.mysql的权限
    mysql-bin：二进制日志文件名的前缀
    例如：mysql-bin.00001，mysql-bin.00002…..
    binlog_format=row —->5.7版本默认配置为row，可以省略
    sync_binlog=1 每次事务提交都立即刷写binlog到磁盘，双”1”中的另外一个参数
    2）参数配置
    server_id=6
    log_bin=/data/mysql/instance01/mysql-bin
    binlog_format=row
    3）创建目录和授权
    mkdir -p /data/binlog/
    chown -R mysql.mysql /data
    4）重启生效
    /etc/init.d/mysqld restart

    2.3 二进制文件记录了什么

    记录了数据库所有变更类的操作日志，包括DDL、DCL、DML
    1、DDL和DCL
    以语句的方式，原模原样的记录
    2、DML
    1）它记录的是已提交的事务
    2）DML记录格式（statement,row,mixed）,通过binlog_format=row参数控制
    说明：
    statement：SBR，语句模式记录日志，做什么命令就记录什么命令
    row ：RBR，行模式，记录的是数据行的变化，常使用此模式，也是默认模式
    mixed ：MBR，混合模式，一般不使用此模式
    面试问题：SBR和RBR的区别，怎么选择
    SBR：可读性比较强，日志量少，但是可能出现记录不准确的情况
    例如：insert into t1 values(1,’zs’,now()); 这种情况比如这行数据丢失，在恢复时就会导致时间不准确。
    RBR：可读性较弱，对于范围操作日志大，不会出现记录错误，高可用环境中新特性要求依赖于RBR，通常采用此模式

    2.4 二进制日志记录单元

    1、event事件
    event是二进制日志的最小记录单元
    DDL：create database oldguo; 对于DDL和DCL而言，每一行语句就是一个事件
    DML：一个事务包含了多个语句
    begin; 事件1
    a 事件2
    b 事件3
    commit； 事件4
    2、event事件的开始和结束号码
    作用，方便我们从日志中截取我们想要的日志事件

    2.5 二进制日志的管理

    1、查看二进制日志位置
    show variables like “%log_bin%”;
    select @@log_bin_basename
    2、查看所有已存在的二进制日志
    show binary logs;
    flush logs; 运行此命令会立即生成一个新的二进制日志文件
    3、查看正在使用的二进制日志
    show master status; mysql只能使用一个binlog文件，通常是最后一个
    4、查看二进制日志事件
    create database binlog charset utf8mb4;
    use binlog
    create table t1(id int);
    insert into t1 values(1);
    未commit之前
    show master status 查看当前mysql使用的binlog文件是哪一个
    show binlog events in ‘mysql-bin.000005’ 查看binlog中event事件
    未提交之前，只记录了ddl语句，且每一个ddl语句即是一个事件；
    image.png
    commit之后
    DML语句只有在被commit之后，才会被记录到binlog当中
    image.png
    5、查看二进制日志的内容
    ]# mysqlbinlog mysql-bin.00001 这种方式显示阅读性不强
    ]# mysqlbinlog —base64-output=decode-rows -vvv mysql-bin.00001 阅读性较好的方式显示
    ]# mysqlbinlog -d test mysql-bin.0001 查询指定数据库日志 ```sql [root@db01 ~]# mysqlbinlog /data/mysql/instance01/mysql-bin.000005
    /!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1/; /!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0/; DELIMITER /!/;

    at 4

    220212 10:26:12 server id 6 end_log_pos 123 CRC32 0x513008f7 Start: binlog v 4, server v 5.7.26-log created 220212 10:26:12

    Warning: this binlog is either in use or was not closed properly.

    BINLOG ‘ xBoHYg8GAAAAdwAAAHsAAAABAAQANS43LjI2LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA AfcIMFE= ‘/!/;

    at 123

    220212 10:26:12 server id 6 end_log_pos 154 CRC32 0x6d205c0a Previous-GTIDs

    [empty]

    at 154

    220212 10:26:19 server id 6 end_log_pos 219 CRC32 0x200ee4ef Anonymous_GTID last_committed=0 sequence_number=1 rbr_only=no

    SET @@SESSION.GTID_NEXT= ‘ANONYMOUS’/!/;

    at 219

    220212 10:26:19 server id 6 end_log_pos 335 CRC32 0x32959b45 Query thread_id=3 exec_time=0 error_code=0

    SET TIMESTAMP=1644632779/!/; SET @@session.pseudo_thread_id=3/!/; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/!/; SET @@session.sql_mode=1436549120/!/; SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/!/; /!\C utf8 //!/; SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/!/; SET @@session.lc_time_names=0/!/; SET @@session.collation_database=DEFAULT/!/; create database binlog charset utf8mb4 /!/;

    at 335

    220212 10:26:19 server id 6 end_log_pos 400 CRC32 0x753e2f74 Anonymous_GTID last_committed=1 sequence_number=2 rbr_only=no

    SET @@SESSION.GTID_NEXT= ‘ANONYMOUS’/!/;

    at 400

    220212 10:26:19 server id 6 end_log_pos 501 CRC32 0xa2e66a68 Query thread_id=3 exec_time=0 error_code=0

    use binlog/!/; SET TIMESTAMP=1644632779/!/; create table t1(id int) /!/;

    at 501

    220212 10:28:57 server id 6 end_log_pos 566 CRC32 0x057f2fb8 Anonymous_GTID last_committed=2 sequence_number=3 rbr_only=yes

    /!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED//!/; SET @@SESSION.GTID_NEXT= ‘ANONYMOUS’/!/;

    at 566

    220212 10:26:20 server id 6 end_log_pos 640 CRC32 0xbcb65eb5 Query thread_id=3 exec_time=0 error_code=0

    SET TIMESTAMP=1644632780/!/; BEGIN /!/;

    at 640

    220212 10:26:20 server id 6 end_log_pos 687 CRC32 0xcea3599d Table_map: binlog.t1 mapped to number 111

    at 687

    220212 10:26:20 server id 6 end_log_pos 727 CRC32 0x73377524 Write_rows: table id 111 flags: STMT_END_F

BINLOG ‘ zBoHYhMGAAAALwAAAK8CAAAAAG8AAAAAAAEABmJpbmxvZwACdDEAAQMAAZ1Zo84= zBoHYh4GAAAAKAAAANcCAAAAAG8AAAAAAAEAAgAB//4BAAAAJHU3cw== ‘/!/;

at 727

220212 10:28:57 server id 6 end_log_pos 758 CRC32 0xddd56696 Xid = 26

COMMIT/!/; SET @@SESSION.GTID_NEXT= ‘AUTOMATIC’ / added by mysqlbinlog / /!/; DELIMITER ;

End of log file

/!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE/; /!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0/; [root@db01 ~]# mysqlbinlog —base64-output=decode-rows -vvv /data/mysql/instance01/mysql-bin.000005 /!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1/; /!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0/; DELIMITER /!/;

at 4

220212 10:26:12 server id 6 end_log_pos 123 CRC32 0x513008f7 Start: binlog v 4, server v 5.7.26-log created 220212 10:26:12

Warning: this binlog is either in use or was not closed properly.

at 123

220212 10:26:12 server id 6 end_log_pos 154 CRC32 0x6d205c0a Previous-GTIDs

[empty]

at 154

220212 10:26:19 server id 6 end_log_pos 219 CRC32 0x200ee4ef Anonymous_GTID last_committed=0 sequence_number=1 rbr_only=no

SET @@SESSION.GTID_NEXT= ‘ANONYMOUS’/!/;

at 219

220212 10:26:19 server id 6 end_log_pos 335 CRC32 0x32959b45 Query thread_id=3 exec_time=0 error_code=0

SET TIMESTAMP=1644632779/!/; SET @@session.pseudo_thread_id=3/!/; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/!/; SET @@session.sql_mode=1436549120/!/; SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/!/; /!\C utf8 //!/; SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/!/; SET @@session.lc_time_names=0/!/; SET @@session.collation_database=DEFAULT/!/; create database binlog charset utf8mb4 /!/;

at 335

220212 10:26:19 server id 6 end_log_pos 400 CRC32 0x753e2f74 Anonymous_GTID last_committed=1 sequence_number=2 rbr_only=no

SET @@SESSION.GTID_NEXT= ‘ANONYMOUS’/!/;

at 400

220212 10:26:19 server id 6 end_log_pos 501 CRC32 0xa2e66a68 Query thread_id=3 exec_time=0 error_code=0

use binlog/!/; SET TIMESTAMP=1644632779/!/; create table t1(id int) /!/;

at 501

220212 10:28:57 server id 6 end_log_pos 566 CRC32 0x057f2fb8 Anonymous_GTID last_committed=2 sequence_number=3 rbr_only=yes

/!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED//!/; SET @@SESSION.GTID_NEXT= ‘ANONYMOUS’/!/;

at 566

220212 10:26:20 server id 6 end_log_pos 640 CRC32 0xbcb65eb5 Query thread_id=3 exec_time=0 error_code=0

SET TIMESTAMP=1644632780/!/; BEGIN /!/;

at 640

220212 10:26:20 server id 6 end_log_pos 687 CRC32 0xcea3599d Table_map: binlog.t1 mapped to number 111

at 687

220212 10:26:20 server id 6 end_log_pos 727 CRC32 0x73377524 Write_rows: table id 111 flags: STMT_END_F

INSERT INTO binlog.t1

SET

@1=1 / INT meta=0 nullable=1 is_null=0 /

at 727

220212 10:28:57 server id 6 end_log_pos 758 CRC32 0xddd56696 Xid = 26

COMMIT/!/; SET @@SESSION.GTID_NEXT= ‘AUTOMATIC’ / added by mysqlbinlog / /!/; DELIMITER ;

End of log file

/!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE/; /!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0/; [root@db01 ~]# 

  1. 6、截取二进制日志<br />]# mysqlbinlog --start-positon=219 --stop-positon=335 mysql-bin.0001 >/tmp/a.sql
  2. <a name="KXlOo"></a>
  3. ## 2.6 通过binlog恢复数据
  4. 1、模拟数据
  5. ```sql
  6. create database xiang charset utf8mb4;
  7. use xiang;
  8. create table t1 (id int);
  9. insert into t1 values(1);
  10. commit；

2、模拟故障

  1. drop database xiang;

3、基于binlog恢复日志

  1. show master status;                                                    --->确认使用的是哪一个日志
  2. show binlog events in 'mysql-bin.000005';        --->查看事件
  3. 说明：找到起点和终点，进行截取，注意binlog文件需要跟上路径
  4. ]# mysqlbinlog --start-position=219 --stop-position=808 mysql-bin.000005 >/tmp/bin.sql

4、恢复binlog

  1. set sql_log_bin=0;            --->临时关闭恢复时产生的新日志binlog,只影响此窗口
  2. source /tmp/bin.sql;
  3. set sql_log_bin=1;            --->将参数改回去

说明：通常binlog日志是配合mysql的备份文件来进行数据恢复的，因为完全靠binlog日志来恢复数据虽然能够做到，但是恢复的成本较高，人工操作较多，且相对复杂，比如每天对数据库做了备份，我们只需要将备份数据恢复，然后截取备份时间点后到到故障之前的binlog日志，然后进新数据恢复即可。

2.7 binlog的gtid记录模式的管理

2.7.1 gtid介绍

global transaction id，全局事务id，对于binlog中的每一个事务，都会生成一个GTID号码，DDL，DCL一个event就是一个事务，就会有一个GTID；对与DML语句来讲，从begin到commit就是一个事务，就是一个GTID号。

2.7.2 gitd的组成

由两部分组成，格式为：Server_uuid:TID
1、server_uuid
server-uuid存放的位置在数据库实例的数据目录下的auto.cnf文件，这个文件在数据库初始化完成时，被自动生成，当被删除时，重启数据库会生成新的文件和uuid号，建议不要修改或删除此文件

  1. # cat /data/mysql/instance01/auto.cnf
  2. [auto]
  3. server-uuid=9b72d814-5bc9-11eb-a144-000c2985474e

2、TID
TID是一个：自增长的数据，从1开始
server-uuid=9b72d814-5bc9-11eb-a144-000c2985474e:1-15

2.7.3 GTID的幂等性

如果拿到有GTID的日志去恢复时，检查当前系统中是否有相同的GTID号，有相同的就自动跳过，会影响到binlog恢复和主从复制

2.7.4 GTID的开启和配置

开启后，只是影响之后的binlog记录会使用gtid记录模式，此前的不影响。

  1. vim /etc/my.cnf
  2. #开启gtid模式
  3. gtid-mode=on
  4. #强制gtid一致性
  5. enforce-gtid-consistency=true

2.7.5 GTID信息查看

创建了一个数据库，可以看到一个ddl语句就有一个gtid号

  1. create database dbgtid charset utf8mb4 ;
  2. show master status ;

image.png

  1. use dbgtid ;
  2. create table t1(id int);
  3. insert into t1 values (1);
  4. commit;
  5. show master status;

我们明显可以看到，commit之前和之后其gtid号码是不一样的，commit之后，dml语句才算一个完整的事务，gtid号才会增加
image.png

2.7.6 使用gtid实现数据恢复

0、模拟故障

  1. drop database dbgtid ;

1、查看当前所在binlog，并分析binlog的events，选择截取哪一部分日志进行数据恢复
image.png
2、截取日志
]# cd /data/mysql/instane01/
因为binlog日志的滚动，出现了events需要在前后多个文件才能看完整的情况，所以在截取日志时，可能会涉及到跟多个文件的情况，这里在分析binlog的events事件时注意
]# mysqlbinlog —include-gtids=’8cbc8ba4-710d-11ec-b317-000c2920edea:1-3’ mysql-bin.000006 mysql-bin.000007 >/tmp/gtid.sql
3、恢复
set sql_log_bin=0;
source /tmp/gtid.sql
image.png
会报类似以上错误，因为幂等性的检查，mysql判断原1-3号事务已经做过，因此会报错
4、正确的做法
# mysqlbinlog —skip-gtids —include-gtids=’8cbc8ba4-710d-11ec-b317-000c2920edea:1-3’ mysql-bin.000006 mysql-bin.000007 >/tmp/gtid.sql
—skip-gtids作用：在导出binglog日志时，忽略原有的gtid信息，恢复时生成的新的gtid信息，这样就可以避免因为幂等性的检查，而导致已经做过的事务而报错
5、恢复
加上—skip-gtids选项后，恢复正常
set sql_log_bin=0;
soure /tmp/gtid.sql
set sql_log_bin=1;

  1. mysql> source /tmp/gtid.sql
  2. Query OK, 0 rows affected (0.00 sec)
  4. Query OK, 0 rows affected (0.00 sec)
  6. Query OK, 0 rows affected (0.00 sec)
  8. Query OK, 0 rows affected (0.00 sec)
  10. Query OK, 0 rows affected (0.00 sec)
  12. Query OK, 0 rows affected (0.00 sec)
  14. Query OK, 0 rows affected (0.00 sec)
  16. Query OK, 0 rows affected (0.00 sec)
  18. Query OK, 0 rows affected (0.00 sec)
  20. Query OK, 0 rows affected (0.00 sec)
  22. Charset changed
  23. Query OK, 0 rows affected (0.00 sec)
  25. Query OK, 0 rows affected (0.00 sec)
  27. Query OK, 0 rows affected (0.00 sec)
  29. Query OK, 0 rows affected, 1 warning (0.00 sec)
  31. Query OK, 1 row affected (0.00 sec)
  33. Database changed
  34. Query OK, 0 rows affected (0.00 sec)
  36. Query OK, 0 rows affected (0.01 sec)
  38. Query OK, 0 rows affected (0.00 sec)
  40. Query OK, 0 rows affected (0.00 sec)
  42. Query OK, 0 rows affected (0.01 sec)
  44. Query OK, 0 rows affected (0.00 sec)
  46. Query OK, 0 rows affected (0.00 sec)
  48. Query OK, 0 rows affected (0.00 sec)
  50. Query OK, 0 rows affected (0.00 sec)
  52. Query OK, 0 rows affected (0.00 sec)
  54. Query OK, 0 rows affected (0.00 sec)
  56. mysql> show databases;
  57. +--------------------+
  58. | Database           |
  59. +--------------------+
  60. | information_schema |
  61. | binlog             |
  62. | dbgtid             |
  63. | mysql              |
  64. | performance_schema |
  65. | school             |
  66. | stu_manage_system  |
  67. | sys                |
  68. | test               |
  69. | wordpress          |
  70. | world              |
  71. | xiang              |
  72. +--------------------+
  73. 12 rows in set (0.00 sec)

2.7.7 GTID相关的参数

—skip-gtids 忽略原有的gtid
—include-gtids 截取指定的gtid
—exclude-gtids= 跳过指定的gtid
当使用—include-gtids或者exclude-gtids时，如果想截取不连续或者排除不连续的gtid号时，书写的格式需要注意
—include-gtids=’8cbc8ba4-710d-11ec-b317-000c2920edea:1-3’, ‘8cbc8ba4-710d-11ec-b317-000c2920edea:9’
—exclude-gtids=’8cbc8ba4-710d-11ec-b317-000c2920edea:4’, ‘8cbc8ba4-710d-11ec-b317-000c2920edea:8’
即不连续的需要用逗号分开写，连续的可以用a-b这种格式即可

2.7.8 二进制日志清理

show variables like “%expire%”
自动
expire_logs_days=15
设置的依据：至少1轮全备周期长度的过期时间，生产中通常采用2轮全备周期长度的过期事件，如全备周期为每周备份一次，那建议设置15天
手工

  1. help purge
  2. Examples:
  3. PURGE BINARY LOGS TO 'mysql-bin.010';
  4. PURGE BINARY LOGS BEFORE '2008-04-02 22:46:26';

reset master;
执行此命令后，binlog日志将从1重新开始
image.png
日志如何滚动
1、flush logs;
2、数据库重启
3、达到文件最大大小后，也会触发滚动
image.png
——设置数据库日志文件最大值

3 慢日志（slow-log）

作用：
记录运行较慢的语句，优化过程中常用的工具日志

3.1 配置

1、开关
slow_query_log=1
2、文件位置及名字
slow_query_log_file=/data/mysql/instance01/slow.log
3、设定慢查询时间:
long_query_time=0.1
4、没走索引的语句也记录
log_queries_not_using_indexes

  1. vim /etc/my.cnf
  3. slow_query_log=1
  4. slow_query_log_file=/data/mysql/instance01/slow.log
  5. long_query_time=0.1
  6. log_queries_not_using_indexes

3.2 分析慢日志

1、模拟慢查询

  1. mysql> select * from t100w where num='100' group by k1;
  2. +--------+------+------+------+---------------------+
  3. | id     | num  | k1   | k2   | dt                  |
  4. +--------+------+------+------+---------------------+
  5. | 180470 |  100 | cY   | bcLM | 2019-08-12 11:43:18 |
  6. | 232003 |  100 | ou   | 67VW | 2019-08-12 11:43:52 |
  7. +--------+------+------+------+---------------------+
  8. 2 rows in set (0.25 sec)
  10. mysql> select * from t100w where num='1000' group by k1;
  11. Empty set (0.24 sec)
  13. mysql> select * from t100w where num='1003' group by k1; 
  14. Empty set (0.25 sec)
  16. mysql> select * from t100w where num='1003' order by  k1;
  17. Empty set (0.25 sec)
  19. mysql> select * from t100w where num='1003' limit 100;
  20. Empty set (0.25 sec)
  22. mysql> select * from t100w where num='100' limit 100,200; 
  23. Empty set (0.25 sec)

2、mysql自带命令分析整理查看
# mysqldumpslow -s c -t 10 /data/mysql/instance01/slow.log
通过这条命令，可以看出是哪些语句查询较慢，然后就可以针对这些查询语句进行优化，如执行计划分析，看是否有走索引，或者改写语句
-s sort排序
c 次数，这里指按照查询次数排序
-t top前多少个
image.png
3、第三方工具
https://www.percorna.com/downloads/percona-toolkit/LATEST/
1）安装相关依赖
yum install perl-DBI perl-DBD-MySQL perl-Time-HiRes perl-IO-Socket-SSL perl-Digest-MD5
2）下载percona包并安装
wget https://www.percona.com/downloads/percona-toolkit/2.2.14/RPM/percona-toolkit-2.2.14-1.noarch.rpm
rpm -ivh percona-toolkit-2.2.14-1.noarch.rpm
toolkit工具包中的命令：
pt-query-digest /data/mysql/instance01/slow.log

  1. [root@db01 ~]# pt-query-digest /data/mysql/instance01/slow.log 
  2. *******************************************************************
  3.  Using the default of SSL_verify_mode of SSL_VERIFY_NONE for client
  4.  is deprecated! Please set SSL_verify_mode to SSL_VERIFY_PEER
  5.  possibly with SSL_ca_file|SSL_ca_path for verification.
  6.  If you really don't want to verify the certificate and keep the
  7.  connection open to Man-In-The-Middle attacks please set
  8.  SSL_verify_mode explicitly to SSL_VERIFY_NONE in your application.
  9. *******************************************************************
  10.   at /usr/bin/pt-query-digest line 11832.
  11. *******************************************************************
  12.  Using the default of SSL_verify_mode of SSL_VERIFY_NONE for client
  13.  is deprecated! Please set SSL_verify_mode to SSL_VERIFY_PEER
  14.  possibly with SSL_ca_file|SSL_ca_path for verification.
  15.  If you really don't want to verify the certificate and keep the
  16.  connection open to Man-In-The-Middle attacks please set
  17.  SSL_verify_mode explicitly to SSL_VERIFY_NONE in your application.
  18. *******************************************************************
  19.   at /usr/bin/pt-query-digest line 11832.
  21. # A software update is available:
  22. #   * The current version for Percona::Toolkit is 3.0.5
  25. # 350ms user time, 60ms system time, 28.20M rss, 237.07M vsz
  26. # Current date: Sat Feb 12 17:03:31 2022
  27. # Hostname: db01
  28. # Files: /data/mysql/instance01/slow.log
  29. # Overall: 11 total, 4 unique, 0 QPS, 0x concurrency _____________________
  30. # Attribute          total     min     max     avg     95%  stddev  median
  31. # ============     ======= ======= ======= ======= ======= ======= =======
  32. # Exec time             3s   236ms   456ms   271ms   266ms    61ms   241ms
  33. # Lock time            2ms   117us   424us   183us   247us    83us   145us
  34. # Rows sent          3.08k       0    1000  286.27  964.41  422.71   15.36
  35. # Rows examine      10.34M 888.14k 976.57k 962.82k 961.27k  28.92k 961.27k
  36. # Query size           517      44      49      47   46.83    1.92   46.83
  38. # Profile
  39. # Rank Query ID           Response time Calls R/Call V/M   Item
  40. # ==== ================== ============= ===== ====== ===== ==========
  41. #    1 0x5E13CFADBC0D3343  1.4868 49.9%     5 0.2974  0.02 SELECT t?w
  42. #    2 0xEE8787FAD5B646C4  0.7439 25.0%     3 0.2480  0.00 SELECT t?w
  43. #    3 0xDCE0A979E8B6629B  0.4948 16.6%     2 0.2474  0.00 SELECT t?w
  44. #    4 0x773B1B236B5C9501  0.2513  8.4%     1 0.2513  0.00 SELECT t?w
  46. # Query 1: 0 QPS, 0x concurrency, ID 0x5E13CFADBC0D3343 at byte 0 ________
  47. # This item is included in the report because it matches --limit.
  48. # Scores: V/M = 0.02
  49. # Attribute    pct   total     min     max     avg     95%  stddev  median
  50. # ============ === ======= ======= ======= ======= ======= ======= =======
  51. # Count         45       5
  52. # Exec time     49      1s   236ms   456ms   297ms   455ms    82ms   253ms
  53. # Lock time     47   968us   117us   424us   193us   403us   109us   138us
  54. # Rows sent     99   3.07k      30    1000  629.40  964.41  438.62  964.41
  55. # Rows examine  44   4.62M 888.14k 976.56k 946.34k 961.27k  33.56k 915.49k
  56. # Query size    44     230      44      49      46   46.83    2.13   42.48
  57. # String:
  58. # Databases    test
  59. # Hosts        localhost
  60. # Time         2022-02-12... (1/20%), 2022-02-12... (1/20%)... 3 more
  61. # Users        root
  62. # Query_time distribution
  63. #   1us
  64. #  10us
  65. # 100us
  66. #   1ms
  67. #  10ms
  68. # 100ms  ################################################################
  69. #    1s
  70. #  10s+
  71. # Tables
  72. #    SHOW TABLE STATUS FROM `test` LIKE 't100w'\G
  73. #    SHOW CREATE TABLE `test`.`t100w`\G
  74. # EXPLAIN /*!50100 PARTITIONS*/
  75. select * from t100w where k1='aa' limit 1000\G
  77. # Query 2: 0 QPS, 0x concurrency, ID 0xEE8787FAD5B646C4 at byte 1403 _____
  78. # This item is included in the report because it matches --limit.
  79. # Scores: V/M = 0.00
  80. # Attribute    pct   total     min     max     avg     95%  stddev  median
  81. # ============ === ======= ======= ======= ======= ======= ======= =======
  82. # Count         27       3
  83. # Exec time     24   744ms   244ms   254ms   248ms   253ms     5ms   241ms
  84. # Lock time     28   575us   117us   259us   191us   247us    55us   194us
  85. # Rows sent      0       2       0       2    0.67    1.96    0.93       0
  86. # Rows examine  27   2.86M 976.56k 976.57k 976.56k 961.27k       0 961.27k
  87. # Query size    27     143      47      48   47.67   46.83       0   46.83
  88. # String:
  89. # Databases    test
  90. # Hosts        localhost
  91. # Time         2022-02-12... (1/33%), 2022-02-12... (1/33%)... 1 more
  92. # Users        root
  93. # Query_time distribution
  94. #   1us
  95. #  10us
  96. # 100us
  97. #   1ms
  98. #  10ms
  99. # 100ms  ################################################################
  100. #    1s
  101. #  10s+
  102. # Tables
  103. #    SHOW TABLE STATUS FROM `test` LIKE 't100w'\G
  104. #    SHOW CREATE TABLE `test`.`t100w`\G
  105. # EXPLAIN /*!50100 PARTITIONS*/
  106. select * from t100w where num='100' group by k1\G
  108. # Query 3: 0 QPS, 0x concurrency, ID 0xDCE0A979E8B6629B at byte 2375 _____
  109. # This item is included in the report because it matches --limit.
  110. # Scores: V/M = 0.00
  111. # Attribute    pct   total     min     max     avg     95%  stddev  median
  112. # ============ === ======= ======= ======= ======= ======= ======= =======
  113. # Count         18       2
  114. # Exec time     16   495ms   245ms   250ms   247ms   250ms     3ms   247ms
  115. # Lock time     17   359us   135us   224us   179us   224us    62us   179us
  116. # Rows sent      0       0       0       0       0       0       0       0
  117. # Rows examine  18   1.91M 976.56k 976.56k 976.56k 976.56k       0 976.56k
  118. # Query size    18      95      46      49   47.50      49    2.12   47.50
  119. # String:
  120. # Databases    test
  121. # Hosts        localhost
  122. # Time         2022-02-12... (1/50%), 2022-02-12... (1/50%)
  123. # Users        root
  124. # Query_time distribution
  125. #   1us
  126. #  10us
  127. # 100us
  128. #   1ms
  129. #  10ms
  130. # 100ms  ################################################################
  131. #    1s
  132. #  10s+
  133. # Tables
  134. #    SHOW TABLE STATUS FROM `test` LIKE 't100w'\G
  135. #    SHOW CREATE TABLE `test`.`t100w`\G
  136. # EXPLAIN /*!50100 PARTITIONS*/
  137. select * from t100w where num='1003' limit 100\G
  139. # Query 4: 0 QPS, 0x concurrency, ID 0x773B1B236B5C9501 at byte 2131 _____
  140. # This item is included in the report because it matches --limit.
  141. # Scores: V/M = 0.00
  142. # Attribute    pct   total     min     max     avg     95%  stddev  median
  143. # ============ === ======= ======= ======= ======= ======= ======= =======
  144. # Count          9       1
  145. # Exec time      8   251ms   251ms   251ms   251ms   251ms       0   251ms
  146. # Lock time      5   121us   121us   121us   121us   121us       0   121us
  147. # Rows sent      0       0       0       0       0       0       0       0
  148. # Rows examine   9 976.56k 976.56k 976.56k 976.56k 976.56k       0 976.56k
  149. # Query size     9      49      49      49      49      49       0      49
  150. # String:
  151. # Databases    test
  152. # Hosts        localhost
  153. # Time         2022-02-12T07:34:56.276237Z
  154. # Users        root
  155. # Query_time distribution
  156. #   1us
  157. #  10us
  158. # 100us
  159. #   1ms
  160. #  10ms
  161. # 100ms  ################################################################
  162. #    1s
  163. #  10s+
  164. # Tables
  165. #    SHOW TABLE STATUS FROM `test` LIKE 't100w'\G
  166. #    SHOW CREATE TABLE `test`.`t100w`\G
  167. # EXPLAIN /*!50100 PARTITIONS*/
  168. select * from t100w where num='1003' order by  k1\G
  169. [root@db01 ~]#

另外Anemometer可基于pt-query-digest将mysql慢查询可视化