慢SQL探秘之为什么我的SQL很慢却没记录在慢查询日志里

2024年 3月 25日 55.1k 0

在MySQL数据库中,想了解数据库运行情况的重要指标之一是慢SQL。而并非如某些人所说的所有运行慢的SQL都会被记录在慢SQL日志(或日志表)里,抑或是没有慢SQL就代表没有运行慢的SQL。本文将总结一些比较常见的运行比较慢但不会被记录在慢SQL日志里的情况。另外,慢SQL的计算方式在MySQL8.0新版本中有变化,因此,将通过对比MySQL5.7(MySQL5.7.38)与MySQL8.0(MySQL8.0.33)进行总结。

1.  准备工作

部署了两套环境,分别是MySQL5.7(MySQL5.7.38)版本及MySQL8.0(MySQL8.0.33)版本。另外为了后续进行慢SQL测试,此时先创建一张测试表并清空慢SQL日志表。

(1)创建测试表及数据

创建测试表及测试数据,便于后续测试。本次通过创建一张1000W记录的表进行测试。

然后再添加个字段。

mysql> call sp_createNum(10000000);
Query OK, 1611392 rows affected (38.70 sec)
mysql> select  count(*) from  testdb.nums;
+----------+
| count(*) |
+----------+
| 10000000 |
+----------+
1 row in set (3.70 sec)
mysql> alter table testdb.nums add c1 varchar(20);
Query OK, 0 rows affected (17.83 sec)
Records: 0  Duplicates: 0  Warnings: 0

(2)清空慢SQL日志表

测试前先清空慢SQL日志表mysql.slow_log,清空方法如下:

mysql> select  count(*) from mysql.slow_log;
+----------+
| count(*) |
+----------+
|        2 |
+----------+
1 row in set (0.00 sec)
# 需先关闭慢SQL监控开关
mysql> set global slow_query_log=0;
Query OK, 0 rows affected (0.00 sec)
# truncate 方式清空慢SQL日志表
mysql> truncate table  mysql.slow_log;
Query OK, 0 rows affected (0.00 sec)
mysql> select  count(*) from mysql.slow_log;
+----------+
| count(*) |
+----------+
|        0 |
+----------+
1 row in set (0.00 sec)
# 清理完毕后开启慢SQL监控
mysql> set global slow_query_log=1;
Query OK, 0 rows affected (0.00 sec)

2.  未开启慢SQL监控

查看MySQL是否开启MySQL的方法如下:

mysql> SHOW GLOBAL VARIABLES LIKE 'slow_query_log';
+----------------+-------+
| Variable_name  | Value |
+----------------+-------+
| slow_query_log | ON    |
+----------------+-------+
1 row in set (0.00 sec)

其中value值为ON (或1),则代表开启了慢SQL监控。MySQL各个版本查看的方法均一样。

另外和慢SQL相关的其他主要参数如下:

  • slow_query_log: 这个参数用于启用或禁用慢SQL监控。设置为1表示启用,0表示禁用。默认值为0(禁用)。
  • log_output:日志存储方式(不仅仅是慢SQL日志),默认值为'FILE'。当log_output='FILE'表示将日志存入文件;当log_output='TABLE'表示将日志存入数据库中的mysql.slow_log表里;当log_output='FILE,TABLE'表示既存储到日志文件又存储到mysql.slow_log表里。
  • slow_query_log_file: 慢SQL日志文件的路径和文件名(5.5等低版本参数为log_slow_queries)。可以不设置该参数,系统则会默认给一个缺省的文件host_name-slow.log。
  • long_query_time: 用于定义慢SQL的阈值时间,单位为秒。执行时间超过该阈值的SQL语句将被记录到慢SQL日志中。默认值为10秒。
  • log_queries_not_using_indexes:如果设置为1,则将未使用索引的查询也记录到慢查询日志中。默认值为0(禁用)。
  • log_slow_admin_statements: 如果设置为1,则会记录部分管理命令(例如ALTER TABLE)到慢SQL日志中。默认值为0(禁用),本文后续也会继续演示介绍。
  • log_slow_extra: 如果设置为1,则除了慢SQL日志的标准输出之外,还将在日志中包括额外的信息,如用户、主机、客户端命令等。默认值为0(禁用)。
  • log_slow_slave_statements: 如果设置为1,则将从服务器执行的慢SQL记录到主服务器的慢SQL日志中。默认值为0(禁用)。
  • min_examined_row_limit: 仅在查询的行数超过指定值时,才记录到慢SQL日志中。默认值为0,表示不限制。

3.  SQL运行时间小于慢SQL监控阈值时间

第一部分已经介绍了和慢SQL相关的参数中的long_query_time,即慢SQL阈值。所以,当SQL运行时间小于该阈值时,对于的SQL将不会记录在慢SQL日志中。查看和修改慢SQL监控阈值的方法如下:

# 查看慢SQL阈值
mysql> SHOW GLOBAL VARIABLES LIKE 'long_query_time';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 0.500000 |
+-----------------+----------+
1 row in set (0.00 sec)
# 设置慢SQL阈值
mysql> set global long_query_time=0.6;
Query OK, 0 rows affected (0.00 sec)
# 设置完成后可以查看全局的阈值
mysql> SHOW GLOBAL VARIABLES LIKE 'long_query_time';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 0.600000 |
+-----------------+----------+
1 row in set (0.01 sec)
# 但是当前会话的慢SQL阈值是没变的,这个同其他包含全局和会话级的参数类似
mysql> SHOW  VARIABLES LIKE 'long_query_time';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 0.500000 |
+-----------------+----------+
1 row in set (0.00 sec)

注:对于不同的数据库需按照实际情况设置慢SQL监控的阈值,例如TP业务的实例且配置相对较好时,建议阈值设置的较低;如果是AP类型业务,则适当放宽慢SQL的阈值。

4. 锁等待或事务等待的SQL

开启2个事务,然后模拟锁等待情况。

(1)MySQL5.7 中测试

首先测试MySQL5.7版本的情况:

事务1

事务2

mysql> begin;

Query OK, 0 rows affected (0.00 sec)

mysql> select now();

+---------------------+

| now()               |

+---------------------+

| 2024-03-24 20:40:47 |

+---------------------+

1 row in set (0.00 sec)

mysql> update testdb.nums set c1=id where id select now();

+---------------------+

| now()               |

+---------------------+

| 2024-03-24 20:41:07 |

+---------------------+

1 row in set (0.00 sec)

mysql> begin;

Query OK, 0 rows affected (0.00 sec)

mysql> select now();

+---------------------+

| now()               |

+---------------------+

| 2024-03-24 20:41:20 |

+---------------------+

1 row in set (0.00 sec)

mysql> update testdb.nums set c1=id where id select now();

+---------------------+

| now()               |

+---------------------+

| 2024-03-24 20:42:55 |

+---------------------+

1 row in set (0.00 sec)

mysql> select  * from mysql.slow_logG

*************************** 1. row ***************************

    start_time: 2024-03-24 20:41:03.204598

     user_host: root[root] @ localhost []

    query_time: 00:00:07.853949

     lock_time: 00:00:00.000089

     rows_sent: 0

 rows_examined: 10000000

            db: testdb

last_insert_id: 0

     insert_id: 0

     server_id: 1

      sql_text: update testdb.nums set c1=id where id select  * from mysql.slow_logG

*************************** 1. row ***************************

    start_time: 2024-03-24 20:41:03.204598

     user_host: root[root] @ localhost []

    query_time: 00:00:07.853949

     lock_time: 00:00:00.000089

     rows_sent: 0

 rows_examined: 10000000

            db: testdb

last_insert_id: 0

     insert_id: 0

     server_id: 1

      sql_text: update testdb.nums set c1=id where id begin;

Query OK, 0 rows affected (0.00 sec)

mysql> select now();

+---------------------+

| now()               |

+---------------------+

| 2024-03-24 20:59:20 |

+---------------------+

1 row in set (0.00 sec)

mysql> update testdb.nums set c1=id where id select now();

+---------------------+

| now()               |

+---------------------+

| 2024-03-24 21:00:01 |

+---------------------+

1 row in set (0.00 sec)

mysql> select  *,CONVERT(sql_text USING utf8mb4)sql_text2  from mysql.slow_logG

*************************** 1. row ***************************

    start_time: 2024-03-24 20:59:55.819649

     user_host: root[root] @ localhost []

    query_time: 00:00:12.676771

     lock_time: 00:00:00.000003

     rows_sent: 0

 rows_examined: 10000000

            db: testdb

last_insert_id: 0

     insert_id: 0

     server_id: 1

      sql_text: 0x757064617465207465737464622E6E756D73207365742063313D69642077686572652069643C3D35

     thread_id: 87

     sql_text2: update testdb.nums set c1=id where id begin;

Query OK, 0 rows affected (0.00 sec)

mysql> select now();

+---------------------+

| now()               |

+---------------------+

| 2024-03-24 21:02:21 |

+---------------------+

1 row in set (0.00 sec)

mysql> update testdb.nums set c1=id where id select now();

+---------------------+

| now()               |

+---------------------+

| 2024-03-24 21:03:41 |

+---------------------+

1 row in set (0.00 sec)

mysql>  select  *,CONVERT(sql_text USING utf8mb4)sql_text2  from mysql.slow_logG

*************************** 1. row ***************************

    start_time: 2024-03-24 20:59:55.819649

     user_host: root[root] @ localhost []

    query_time: 00:00:12.676771

     lock_time: 00:00:00.000003

     rows_sent: 0

 rows_examined: 10000000

            db: testdb

last_insert_id: 0

     insert_id: 0

     server_id: 1

      sql_text: 0x757064617465207465737464622E6E756D73207365742063313D69642077686572652069643C3D35

     thread_id: 87

     sql_text2: update testdb.nums set c1=id where id alter table testdb.nums add primary key (id);
Query OK, 0 rows affected (1 min 10.93 sec)
Records: 0 Duplicates: 0 Warnings: 0

mysql> select * from mysql.slow_log
-> G
Empty set (0.00 sec)

此时,虽然加主键的SQL运行了1分钟以上,但是慢SQL日志表里无此记录。

图片

MySQL8.0 中同样如此。

图片

(2)调整log_slow_admin_statements

log_slow_admin_statements参数是控制记录超时的管理操作SQL是否记录到慢查询日志。默认情况下的值是0,也就是不记录;而将值改为1时,此类SQL将会被记录。

mysql> set global  log_slow_admin_statements=1;
Query OK, 0 rows affected (0.00 sec)


mysql> alter table testdb.nums add key idx_c1(c1);
Query OK, 0 rows affected (16.54 sec)
Records: 0  Duplicates: 0  Warnings: 0


mysql> select * from mysql.slow_logG
*************************** 1. row ***************************
    start_time: 2024-03-24 21:39:43.181950
     user_host: root[root] @ localhost []
    query_time: 00:00:16.545439
     lock_time: 00:00:00.001927
     rows_sent: 0
 rows_examined: 0
            db: testdb
last_insert_id: 0
     insert_id: 0
     server_id: 1
      sql_text: alter table testdb.nums add key idx_c1(c1)
     thread_id: 8
1 row in set (0.00 sec)


mysql> select version();
+---------------+
| version()     |
+---------------+
| 5.7.38-41-log |
+---------------+
1 row in set (0.00 sec)

此时,添加索引的操作将被记录。

图片

MySQL8.0中同样适用。

图片

6.  扫描记录少于阈值的SQL

MySQL中扫描记录少于阈值由min_examined_row_limit参数控制,默认值为0,即如果SQL扫描的行数少于此值时,将不会被记录在慢SQL日志中,否则将会被记录。由于默认值是0,因此扫描行数>=0的且符合其他记录慢SQL的条件时便会被记录。如果想忽略扫描数据量较少,但是又不想记录超过阈值的SQL,则可以调整min_examined_row_limit来解决。

(1)默认情况

测试一下默认情况.

mysql> show global variables like 'min_examined_row_limit';
+------------------------+-------+
| Variable_name | Value |
+------------------------+-------+
| min_examined_row_limit | 0 |
+------------------------+-------+
1 row in set (0.00 sec)
#c1 select count(*) from testdb.nums where c1 select * from mysql.slow_logG
*************************** 1. row ***************************
start_time: 2024-03-24 21:48:46.005622
user_host: root[root] @ localhost []
query_time: 00:00:01.691788
lock_time: 00:00:00.000092
rows_sent: 1
rows_examined: 10000000
db: testdb
last_insert_id: 0
insert_id: 0
server_id: 25455
sql_text: select count(*) from testdb.nums where c1 set min_examined_row_limit=20000000;
Query OK, 0 rows affected (0.00 sec)
mysql> select count(*) from testdb.nums where c1 select * from mysql.slow_logG
*************************** 1. row ***************************
start_time: 2024-03-24 21:48:46.005622
user_host: root[root] @ localhost []
query_time: 00:00:01.691788
lock_time: 00:00:00.000092
rows_sent: 1
rows_examined: 10000000
db: testdb
last_insert_id: 0
insert_id: 0
server_id: 25455
sql_text: select count(*) from testdb.nums where c1

相关文章

Oracle如何使用授予和撤销权限的语法和示例
Awesome Project: 探索 MatrixOrigin 云原生分布式数据库
下载丨66页PDF,云和恩墨技术通讯(2024年7月刊)
社区版oceanbase安装
Oracle 导出CSV工具-sqluldr2
ETL数据集成丨快速将MySQL数据迁移至Doris数据库

发布评论