记一次slowlog不记录insert 情况

前几天在和朋友一起看一个问题的时候，出现一个关于慢日志没有达到预期额现象。原因是一个平时没有关注的参数导致没将需要的 SQL
 记录到日志里。

当时的是为了讨论的问题是：一条SQL
插入2000行数据(SQL为insert into t values()..*2000..()
)。当并发是500的时候导致出现 10S
的慢SQL。然后就去模拟这种场景，我的环境出现了无法将这个SQL记录到慢日志的问题

场景再现：版本：MySQL8.0.27（单实例）

数据库信息

mysql> show global variables like 'long_query%';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 0.000100 |
+-----------------+----------+


mysql> desc sbtest11;
+-------+-----------+------+-----+---------+----------------+
| Field | Type      | Null | Key | Default | Extra          |
+-------+-----------+------+-----+---------+----------------+
| id    | int       | NO   | PRI | NULL    | auto_increment |
| k     | int       | NO   | MUL | 0       |                |
| c     | char(120) | NO   |     |         |                |
| pad   | char(60)  | NO   |     |         |                |
+-------+-----------+------+-----+---------+----------------+
4 rows in set (0.00 sec)

mysql> desc sbtest2;
+-------+-----------+------+-----+---------+----------------+
| Field | Type      | Null | Key | Default | Extra          |
+-------+-----------+------+-----+---------+----------------+
| id    | int       | NO   | PRI | NULL    | auto_increment |
| k     | int       | NO   | MUL | 0       |                |
| c     | char(120) | NO   |     |         |                |
| pad   | char(60)  | NO   |     |         |                |
+-------+-----------+------+-----+---------+----------------+
4 rows in set (0.00 sec)

// 插入数据
mysql> insert into sbtest2(k,c,pad) select k,c,pad from sbtest11 where id> 100 ;
Query OK, 1124 rows affected (0.03 sec)
Records: 1124  Duplicates: 0  Warnings: 0

查看slowlog
,记录没有问题

[root@VM-24-17-centos slowlog]# tailf slow.log
# Time: 2022-04-23T16:50:27.152696+08:00
# User@Host: root[root] @ localhost []  Id:    52
# Query_time: 0.022854  Lock_time: 0.000154 Rows_sent: 0  Rows_examined: 1124 Thread_id: 52 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 57 Read_first: 0 Read_last: 0 Read_key: 1 Read_next: 1124 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: 2022-04-23T16:50:27.129842+08:00 End: 2022-04-23T16:50:27.152696+08:00
SET timestamp=1650703827;
insert into sbtest2(k,c,pad) select k,c,pad from sbtest11 where id> 100;

模拟场景使用的SQL: 插入N行(insert into values()
),插入1024行

INSERT INTO `sbtest2` (`k`, `c`, `pad`) VALUES 
(4002729,'78909470060-68707784978-87433654651-10228932347-27717021126-58875853500-84985374891-35648420586-58162012032-16546887289','00270200437-84000504935-75407649257-08022008568-21827418702'),
........
3-25863394902-66264487986-39762575966-94009549717-28427349077-65663626240-75191798583-81674702765','53902681002-90859526092-51440182280-74812561083-20881676043');
Query OK, 1024 rows affected (0.03 sec)
Records: 1024  Duplicates: 0  Warnings: 0

这个时候就思考为什么这种SQL不记录到日志中，猜测方向：

1. 时间设置不够短
2.  insert into
    类型的SQL被某个参数排除在外

• 将long_query_time
  设置为0 重连会话后再试

mysql> show global variables like 'long_query_time';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 0.000000 |
+-----------------+----------+
1 row in set (0.00 sec)

结果依然不记录到日志中 测试短时间SQL

# Time: 2022-04-23T17:16:08.610641+08:00
# User@Host: root[root] @ localhost []  Id:    55
# Query_time: 0.004142  Lock_time: 0.000115 Rows_sent: 1  Rows_examined: 12187 Thread_id: 55 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 58 Read_first: 1 Read_last: 0 Read_key: 1 Read_next: 12187 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: 2022-04-23T17:16:08.606499+08:00 End: 2022-04-23T17:16:08.610641+08:00
SET timestamp=1650705368;
select count(1) from sbtest2 where id like '%23%';

• 有参数将案例中SQL排除在外

在此先将所有参数列出

long_query_time
slow_query_log
log_output
log_slow_admin_statements 
log_queries_not_using_indexes
log_slow_admin_statements
min_examined_row_limit
log_slow_replica_statements
log_slow_slave_statements 

这里就不一一介绍参数的作用了。在经过排查后发现问题原因是min_examined_row_limit
。

先看下文档的介绍

Queries that examine fewer than this number of rows are not logged to the slow query log.

As of MySQL 8.0.27, setting the session value of this system variable is a restricted operation. 
The session user must have  privileges sufficient to set restricted session variables

大意是当SQL在执行时examine
行数少于该值时不记录到slowlog中。

再看下文档关于slow querylog中Rows_examined
列的介绍

Rows_examined:

The number of rows examined by the server layer (not counting any processing internal to
storage engines).

Enabling the log_slow_extra system variable (available as of MySQL 8.0.14) causes the server to write
the following extra fields to FILE output in addition to those just listed (TABLE output is
unaffected).Some field descriptions refer to status variable names. Consult the status variable 
descriptions for more information. However, in the slow query log, the counters are per-statement 
values, not cumulative per-session values.

参数的作用比较简单，这里只做一些SQL会有什么的结果进行一次列举，不对该参数做过多的解读（这里涉及到某些查询的OPTIMIZER_TRACE
，explain中的rows
不在本次讨论范围内）。

如果想从源码层面了解关于min_examined_row_limit
参数的介绍可以参考下面的两篇文章《MySQL源码学习：关于慢查询日志中的Rows_examined=0》 https://developer.aliyun.com/article/8820

《MySQL：排序（filesort）详细解析》：https://www.jianshu.com/p/069428a6594e#:~:text=%E6%80%BB%E7%BB%934%EF%BC%9A%E5%85%B3%E4%BA%8E,%E7%9A%84%E8%A1%8C%E6%95%B0%E3%80%82

References

[1]
 5.4.5 The Slow Query Log :https://dev.mysql.com/doc/refman/8.0/en/slow-query-log.html