mysql slowlog 的一些细节

原创王运亮 2023-05-30

564

关于mysql常规优化，我们一般会使用工具对slowlog汇总分析后，优化重点SQL。
在使用过程中，有一些细节问题，在此记录：

SQL始终没有记录到slowlog中？
一条慢SQL的开始和结束时间？
错误的SQL是否会被记录？
中断的SQL是否会被记录？
Rows_exmained的含义？

关于上述5个问题，我们以mysql8.0.31为例，逐个验证：

测试数据如下：

-- 创建表
CREATE TABLE `test` (
  `id` int NOT NULL AUTO_INCREMENT,
  `name` varchar(50) DEFAULT NULL,
  `date` datetime DEFAULT NULL,
  `cusno` varchar(50) DEFAULT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `uix_cusno` (`cusno`),
  KEY `ix_date_cusno` (`date`,`cusno`)
) ENGINE=InnoDB;

-- 插入数据
insert into test(name, date, cusno)
select 'wyl', '2023-05-30', uuid()
from information_schema.columns
limit 150;

SQL始终没有记录到slowlog中？
mysql按下面顺序决定一条SQL是否记录到slowlog中：
1. 查询不是管理语句，或者开启了log_slow_admin_statements。
2. 查询执行耗时必须超过long_query_time值，或者开启了log_queries_not_using_indexes参数且查询未使用索引。
3. 查询必须扫描了至少min_examined_row_limit行。
4. 不能设置log_throttle_queries_not_using_indexes参数。此参数和log_queries_not_using_indexes联用，表示每分钟允许记录到slowlog中未使用索引的SQL次数。

-- 设置当前session的慢查询阈值,目标是记录所有SQL
mysql> set long_query_time=0;
Query OK, 0 rows affected (0.00 sec)

-- 查看slow log相关参数
mysql> show variables like '%slow%';
+-----------------------------+---------------------------------+
| Variable_name               | Value                           |
+-----------------------------+---------------------------------+
| log_slow_admin_statements   | ON                              |
| log_slow_extra              | ON                              |
| log_slow_replica_statements | ON                              |
| log_slow_slave_statements   | ON                              |
| slow_launch_time            | 2                               |
| slow_query_log              | ON                              |
| slow_query_log_file         | /data/mysql/mysql_3307/slow.log |
+-----------------------------+---------------------------------+
7 rows in set (0.06 sec)

-- 执行SQL，发现并未记录到slowlog中
mysql> select * from test limit 99;
+----+------+---------------------+--------------------------------------+
| id | name | date                | cusno                                |
+----+------+---------------------+--------------------------------------+
|  1 | wyl  | 2023-05-30 00:00:00 | d98d2376-fe6c-11ed-92a3-000c291479a8 |
|  2 | wyl  | 2023-05-30 00:00:00 | d9907a71-fe6c-11ed-92a3-000c291479a8 |
......
| 99 | wyl  | 2023-05-30 00:00:00 | d9ad5e73-fe6c-11ed-92a3-000c291479a8 |
+----+------+---------------------+--------------------------------------+
99 rows in set (0.00 sec)

-- 根据记录慢日志规则逐步分析，发现是在第3步出的问题
mysql> show variables like 'min_examined_row_limit';
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| min_examined_row_limit | 100   |
+------------------------+-------+
1 row in set (0.07 sec)

-- 查询100条记录，发现SQL已经记录到slowlog中
mysql> select * from test limit 100;
+-----+------+---------------------+--------------------------------------+
| id  | name | date                | cusno                                |
+-----+------+---------------------+--------------------------------------+
|   1 | wyl  | 2023-05-30 00:00:00 | d98d2376-fe6c-11ed-92a3-000c291479a8 |
|   2 | wyl  | 2023-05-30 00:00:00 | d9907a71-fe6c-11ed-92a3-000c291479a8 |
......
| 100 | wyl  | 2023-05-30 00:00:00 | d9adbfac-fe6c-11ed-92a3-000c291479a8 |
+-----+------+---------------------+--------------------------------------+
100 rows in set (0.01 sec)

-- 相关慢日志如下
/*
# Time: 2023-05-30T06:40:03.968027+08:00
# User@Host: root[root] @  [192.168.199.130]  Id:   128
# Query_time: 0.002606  Lock_time: 0.000103 Rows_sent: 100  Rows_examined: 100 Thread_id: 128 Errno: 0 Killed: 0 Bytes_received: 35 Bytes_sent: 6990 Read_first: 1 Read_last: 0 Read_key: 1 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 100 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2023-05-30T06:40:03.965421+08:00 End: 2023-05-30T06:40:03.968027+08:00
SET timestamp=1685400003;
select * from test limit 100;
*/
--

一条慢SQL的开始和结束时间？
慢日志中SQL的开始和执行时间和mysql版本有关系：
1. 8.0.14之前的版本：# Time: =记录慢日志时间，SET timestamp=结束时间
2. 8.0.14之后的版本：# Time: =记录慢日志时间，SET timestamp=开始时间

-- mysql5.7.39测试
-- 连续执行下面2条SQL
mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2023-05-30 07:04:24 |
+---------------------+
1 row in set (0.00 sec)

mysql> select sleep(0.1) from test limit 100;
+------------+
| sleep(0.1) |
+------------+
|          0 |
......
|          0 |
+------------+
100 rows in set (10.06 sec)

-- 可以看出，日志中并未记录SQL的开始时间，但可以通过"结束时间-执行时长"得到
/*
# Time: 2023-05-30T07:04:24.921103+08:00
# User@Host: root[root] @  [192.168.199.130]  Id:     5
# Query_time: 0.000424  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1685401464;  -- 2023-05-30 07:04:24
select now();
# Time: 2023-05-30T07:04:35.313487+08:00
# User@Host: root[root] @  [192.168.199.130]  Id:     5
# Query_time: 10.064031  Lock_time: 0.000425 Rows_sent: 100  Rows_examined: 100
SET timestamp=1685401475;  -- 2023-05-30 07:04:35
select sleep(0.1) from test limit 100;
*/

-- mysql8.0.31测试
mysql> select sleep(0.1) from test limit 100;
+------------+
| sleep(0.1) |
+------------+
|          0 |
......
|          0 |
+------------+
100 rows in set (10.08 sec)

-- 可以看出，SQL的开始时间和结束时间相差约10秒，与SQL执行时长吻合
/*
# Time: 2023-05-30T07:00:04.418101+08:00
# User@Host: root[root] @  [192.168.199.130]  Id:   129
# Query_time: 10.076529  Lock_time: 0.000274 Rows_sent: 100  Rows_examined: 100 Thread_id: 129 Errno: 0 Killed: 0 Bytes_received: 44 Bytes_sent: 652 Read_first: 1 Read_last: 0 Read_key: 1 Read_next: 99 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2023-05-30T06:59:54.341572+08:00 End: 2023-05-30T07:00:04.418101+08:00
SET timestamp=1685401194;  -- 2023-05-30 06:59:54
select sleep(0.1) from test limit 100;
*/
-- 转换时间戳为日期
mysql> select FROM_UNIXTIME(1685401194);
+---------------------------+
| FROM_UNIXTIME(1685401194) |
+---------------------------+
| 2023-05-30 06:59:54       |
+---------------------------+
1 row in set (0.00 sec)

错误的SQL是否会被记录？
未开始执行的SQL，不会被记录到slowlog中；已经开始执行的SQL，即使出错，只要符合条件，也会被记录到慢日志中。

-- 设置当前session参数，记录所有SQL
mysql> set long_query_time=0;
Query OK, 0 rows affected (0.00 sec)

mysql> set min_examined_row_limit=0;
Query OK, 0 rows affected (0.02 sec)

-- 执行错误SQL
mysql> insert into test(date) values('2023-05-32');
ERROR 1292 (22007): Incorrect datetime value: '2023-05-32' for column 'date' at row 1

-- 错误SQL也会记录到慢日志, 但注意Rows_sent: 0 Rows_examined: 0
/*
# Time: 2023-05-30T07:31:28.117018+08:00
# User@Host: root[root] @  [192.168.199.130]  Id:   130
# Query_time: 0.056029  Lock_time: 0.000104 Rows_sent: 0  Rows_examined: 0 Thread_id: 130 Errno: 1292 Killed: 0 Bytes_received: 50 Bytes_sent: 78 Read_first: 0 Read_last: 0 Read_key: 0 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2023-05-30T07:31:28.060989+08:00 End: 2023-05-30T07:31:28.117018+08:00
SET timestamp=1685403088;
insert into test(date) values('2023-05-32');
*/

中断的SQL是否会被记录？
如果SQL执行过程中被强制中断，只要符合条件，也会被记录到慢日志中。但要注意：
1. kill id; 不会记录到慢日志中
2. kill query id; 会记录到慢日志中

-- kill id直接断开连接，不会记录慢日志
-- session1中执行慢SQL
mysql> select /*+ no_bnl() */ a.* from test a left join test b on a.name=b.name left join test c on b.name=c.name left join test d on c.name=d.name;
ERROR 2013 (HY000): Lost connection to MySQL server during query

-- session2中kill id
mysql> kill 393;
Query OK, 0 rows affected (0.00 sec)

-- kill query id，会记录慢日志
-- session1中执行慢SQL
mysql> select /*+ no_bnl() */ a.* from test a left join test b on a.name=b.name left join test c on b.name=c.name left join test d on c.name=d.name;
ERROR 1317 (70100): Query execution was interrupted

-- session2中kill query id
mysql> kill query 393;
Query OK, 0 rows affected (0.00 sec)

-- 查看慢日志
/*
# Time: 2023-05-30T15:49:50.412376+08:00
# User@Host: root[root] @  [192.168.199.130]  Id:   393
# Query_time: 25.882367  Lock_time: 0.000264 Rows_sent: 6403207  Rows_examined: 6446184 Thread_id: 393 Errno: 1317 Killed: 0 Bytes_received: 147 Bytes_sent: 429015088 Read_first: 42977 Read_last: 0 Read_key: 42977 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 6489157 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2023-05-30T15:49:24.530009+08:00 End: 2023-05-30T15:49:50.412376+08:00
SET timestamp=1685432964;
select /*+ no_bnl() */ a.* from test a left join test b on a.name=b.name left join test c on b.name=c.name left join test d on c.name=d.name;
*/

Rows_exmained的含义？
这个字段的含义是指：服务器层检查的行数(不包括存储引擎内部的任何处理)。它能带给我们的信息如下：
1. 如果Rows_examined值比较大，Rows_sent值比较小，一般说明SQL还存在一定的优化空间。
2. Rows_examined值是服务器层实际扫描的行数，我们可以手工计算出来
3. 可以根据Rows_examined字段值，结合explain analyze更深刻地理解整个SQL的执行过程。

-- Nested loop join 示例：
mysql> explain
    -> select a.id,a.cusno,a.date
    -> from test a
    -> inner join test b
    -> on a.id = b.id
    -> where b.cusno in(
    -> 'd98d2376-fe6c-11ed-92a3-000c291479a8',
    -> 'd9907a71-fe6c-11ed-92a3-000c291479a8',
    -> 'd9bcc739-fe6c-11ed-92a3-000c291479a8'
    -> )
    -> order by a.cusno desc;
	
-- explain 结果
+----+-------------+-------+------------+--------+-------------------+-----------+---------+-----------+------+----------+-----------------------------------------------------------+
| id | select_type | table | partitions | type   | possible_keys     | key       | key_len | ref       | rows | filtered | Extra                                                     |
+----+-------------+-------+------------+--------+-------------------+-----------+---------+-----------+------+----------+-----------------------------------------------------------+
|  1 | SIMPLE      | b     | NULL       | range  | PRIMARY,uix_cusno | uix_cusno | 203     | NULL      |    3 |   100.00 | Using where; Using index; Using temporary; Using filesort |
|  1 | SIMPLE      | a     | NULL       | eq_ref | PRIMARY           | PRIMARY   | 4       | modb.b.id |    1 |   100.00 | NULL                                                      |
+----+-------------+-------+------------+--------+-------------------+-----------+---------+-----------+------+----------+-----------------------------------------------------------+

-- explain analyze 结果
-> Sort: a.cusno DESC  (actual time=3.847..3.930 rows=3 loops=1)
    -> Stream results  (cost=1.92 rows=3) (actual time=1.430..3.603 rows=3 loops=1)
        -> Nested loop inner join  (cost=1.92 rows=3) (actual time=1.303..3.304 rows=3 loops=1)
            -> Filter: (b.cusno in ('d98d2376-fe6c-11ed-92a3-000c291479a8','d9907a71-fe6c-11ed-92a3-000c291479a8','d9bcc739-fe6c-11ed-92a3-000c291479a8'))  (cost=0.87 rows=3) (actual time=0.664..1.401 rows=3 loops=1)
                -> Covering index range scan on b using uix_cusno over (cusno = 'd98d2376-fe6c-11ed-92a3-000c291479a8') OR (cusno = 'd9907a71-fe6c-11ed-92a3-000c291479a8') OR (cusno = 'd9bcc739-fe6c-11ed-92a3-000c291479a8')  (cost=0.87 rows=3) (actual time=0.341..0.897 rows=3 loops=1)
            -> Single-row index lookup on a using PRIMARY (id=b.id)  (cost=0.28 rows=1) (actual time=0.431..0.457 rows=1 loops=3)

-- slow log 结果
# Time: 2023-05-30T18:46:23.604101+08:00
# User@Host: root[root] @  [192.168.199.130]  Id:   395
# Query_time: 0.008966  Lock_time: 0.000172 Rows_sent: 1  Rows_examined: 9 Thread_id: 395 Errno: 0 Killed: 0 Bytes_received: 255 Bytes_sent: 934 Read_first: 0 Read_last: 0 Read_key: 6 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 3 Sort_scan_count: 1 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2023-05-30T18:46:23.595135+08:00 End: 2023-05-30T18:46:23.604101+08:00
SET timestamp=1685443583;

-- Rows_examined: 9 如何计算？
1. b表扫描了3行，扫描了1次(rows=3 loops=1)
2. Nested loop 算法，循环了a表3次(loops=3)，每次扫描1行(rows=1)
3. 排序后(Sort)，扫描了3行返回给客户端
所以一共加起来是9行。

-- Nested loop时，内层循环的rows=1是如何计算出来的？
内层循环所有累计扫描的行数/循环次数，本例为3/3=1行。

-- Hash join 示例：
mysql> explain
    -> select a.id,a.cusno,b.date
    -> from test a
    -> left join test b
    -> on a.cusno = concat(b.cusno, '')
    -> order by b.id desc
    -> limit 3;

-- explain 结果
+----+-------------+-------+------------+-------+---------------+---------------+---------+------+------+----------+---------------------------------------------------------+
| id | select_type | table | partitions | type  | possible_keys | key           | key_len | ref  | rows | filtered | Extra                                                   |
+----+-------------+-------+------------+-------+---------------+---------------+---------+------+------+----------+---------------------------------------------------------+
|  1 | SIMPLE      | a     | NULL       | index | NULL          | uix_cusno     | 203     | NULL |  150 |   100.00 | Using index; Using temporary; Using filesort            |
|  1 | SIMPLE      | b     | NULL       | index | NULL          | ix_date_cusno | 209     | NULL |  150 |   100.00 | Using where; Using index; Using join buffer (hash join) |
+----+-------------+-------+------------+-------+---------------+---------------+---------+------+------+----------+---------------------------------------------------------+

-- explain analyze 结果
-> Limit: 3 row(s)  (actual time=59.847..59.989 rows=3 loops=1)
    -> Sort: b.id DESC, limit input to 3 row(s) per chunk  (actual time=59.759..59.800 rows=3 loops=1)
        -> Stream results  (cost=2250.35 rows=22500) (actual time=30.218..53.896 rows=150 loops=1)
            -> Left hash join (a.cusno = concat(b.cusno,''))  (cost=2250.35 rows=22500) (actual time=30.087..43.944 rows=150 loops=1)
                -> Covering index scan on a using uix_cusno  (cost=15.25 rows=150) (actual time=0.456..4.741 rows=150 loops=1)
                -> Hash
                    -> Covering index scan on b using ix_date_cusno  (cost=0.10 rows=150) (actual time=15.059..23.192 rows=150 loops=1)

-- slow log 结果
# Time: 2023-05-30T19:01:49.383210+08:00
# User@Host: root[root] @  [192.168.199.130]  Id:   396
# Query_time: 0.039852  Lock_time: 0.000335 Rows_sent: 1  Rows_examined: 303 Thread_id: 396 Errno: 0 Killed: 0 Bytes_received: 138 Bytes_sent: 741 Read_first: 2 Read_last: 0 Read_key: 2 Read_next: 300 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 3 Sort_scan_count: 1 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2023-05-30T19:01:49.343358+08:00 End: 2023-05-30T19:01:49.383210+08:00
SET timestamp=1685444509;

-- Rows_examined: 303 如何计算？
1. a表覆盖索引(uix_cusno)扫描，扫描了150行，扫描了1次(rows=150 loops=1)
2. b表覆盖索引(ix_date_cusno)扫描，构建hash桶，扫描了150行，扫描了1次(rows=150 loops=1)
3. 排序后(Sort)，扫描了3行返回给客户端(rows=3)
所以一共加起来是303行。

总结：

分析slowlog是我们常用的优化手段，有时甚至用于对历史负载的排查，所以要清楚它的含义。
slowlog中的一些细节参数，有助于对SQL优化的分析。
数据库性能优化，从slowlog做起。

参考：
https://dev.mysql.com/doc/refman/8.0/en/slow-query-log.html#slow-query-log-parameters

mysql slowlog

「喜欢这篇文章，您的关注和赞赏是给作者最好的鼓励」

关注作者

mysql slowlog 的一些细节

评论