自学内容网 自学内容网
自学内容网 > 正文

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

🕗 发布于 2024-03-25 07:49 sql  adb  android  数据库  

在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.1 创建测试表及数据

创建测试表及测试数据，便于后续测试。本次通过创建一张1000W记录的表进行测试，快速生成数据的方式请查看历史文章：效率提升16800倍的连续整数生成方法

然后再添加个字段

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

1.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各个版本查看的方法均一样09039fba013b6205765f830ac4969a0a.png

另外和慢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)

fe18dbc7c6649525196b89df9a8d7483.png

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

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

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

4.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<=5;

Query OK, 5 rows affected (7.85 sec)

Rows matched: 5  Changed: 5  Warnings: 0

mysql> 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<3;

ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

mysql> select now();

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

| now()               |

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

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

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

1 row in set (0.00 sec)

mysql> select  * from mysql.slow_log\G

*************************** 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<=5

     thread_id: 2

1 row in set (0.00 sec)

mysql> select  * from mysql.slow_log\G

*************************** 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<=5

     thread_id: 2

1 row in set (0.00 sec)

从测试情况来看，MySQL5.7的锁等待超时的SQL是没有被记录在慢SQL日志中的

ed4488b40fec51e79cbbe2631d12951d.png

4.2 MySQL8.0中测试

事务1
事务2

mysql> 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<=5;

Query OK, 5 rows affected (12.67 sec)

Rows matched: 5  Changed: 5  Warnings: 0


mysql> 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_log\G

*************************** 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<=5



mysql> 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<3;

ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction


mysql> 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_log\G

*************************** 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<=5

*************************** 2. row ***************************

    start_time: 2024-03-24 21:03:31.882874

     user_host: root[root] @ localhost []

    query_time: 00:01:00.006259

     lock_time: 00:01:00.005760

     rows_sent: 0

 rows_examined: 1

            db: testdb

last_insert_id: 0

     insert_id: 0

     server_id: 1

      sql_text: 0x757064617465207465737464622E6E756D73207365742063313D69642077686572652069643C33

     thread_id: 88

     sql_text2: update testdb.nums set c1=id where id<3

2 rows in set (0.00 sec)

MySQL8.0中，锁等待超时的SQL也会被记录在慢SQL记录中了，这与MySQL8.0后续新版中慢SQL的计算方式有调整有关系。

1483af99e7694aed5652c5091afd01e2.png

5. 管理类SQL

管理类SQL指的是alter table、alter user等,默认情况下，此类操作虽然比较慢，超过了慢SQL日志监控的阈值，但是也不会记录在慢SQL日志中。不过可以调整参数log_slow_admin_statements来控制是否记录此类SQL。

5.1 默认情况

mysql> use testdb;
Database changed
mysql> 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日志表里无此记录

a63df0751049926d423b93d2e5593f7e.png

MySQL8.0 中同样如此

19ce71b909d8c01e9fd199c9001b0e73.png

5.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_log\G
*************************** 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)

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

513d4edcc5c7c7d277b0017382b859c0.png

MySQL8.0中同样适用

d752f4f4e5b0d618ac9cddd834819aae.png

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

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

6.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<=999，可以隐式转换导致无法走索引，使其变慢，便于测试
mysql> select count(*) from testdb.nums where c1<=999;
+----------+
| count(*) |
+----------+
|        0 |
+----------+
1 row in set (1.70 sec)


mysql> select * from mysql.slow_log\G
*************************** 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<=999
     thread_id: 8

7780e0fab7bab171d5c9e22afe50cc28.png

此时慢SQL会被记录。MySQL8.0中同样如此。

cb7f5c11843aeb67186d8478c34d9326.png

6.2 修改参数

为了测试，此时将min_examined_row_limit值设置为20000000，然后测试是否还会被记录。

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


mysql> select count(*) from testdb.nums where c1<=999;
+----------+
| count(*) |
+----------+
|        0 |
+----------+
1 row in set (1.70 sec)


mysql> select * from mysql.slow_log\G
*************************** 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<=999
     thread_id: 8
1 row in set (0.00 sec)

54d9465bd4f5152d59a30064bc3be84e.png

可见，此时的慢SQL还是之前的，即修改后，即使SQL运行时间超过了慢SQL阈值，但是扫描行数低于min_examined_row_limit参数指定的值，此时也不会被记录。MySQL同样如此

bd9d73875b24e36651a35ab4b4073f1e.png

7. 其他SQL

除了以上的情况外，复制线程的查询、被DBAkill的正在运行的SQL或部分未运行完毕的SQL也不会记录在慢SQL日志中（不过部分情况再MySQL8.0中有所变更），因此需要大家根据实际情况多总结及测试。

555d38f6c5f4605b79c9b7941ae3cc26.png

往期精彩回顾

1.  MySQL高可用之MHA集群部署

2.  mysql8.0新增用户及加密规则修改的那些事

3.  比hive快10倍的大数据查询利器-- presto

4.  监控利器出鞘：Prometheus+Grafana监控MySQL、Redis数据库

5.  PostgreSQL主从复制--物理复制

6.  MySQL传统点位复制在线转为GTID模式复制

7.  MySQL敏感数据加密及解密

8.  MySQL数据备份及还原（一）

9.  MySQL数据备份及还原（二）

b4241217ed7438bfcc33d1d351e10fac.png

扫码关注     

ebb5adbabba267ffecfa48604e1fcfcb.jpeg

7c24fb4ee2f408223c4881b82770a1fd.png

0622da6685fe49acd61f36bb79410be5.png


原文地址：https://blog.csdn.net/gjc592/article/details/137000287

免责声明：本站文章内容转载自网络资源，如本站内容侵犯了原著者的合法权益，可联系本站删除。更多内容请关注自学内容网（zxcms.com）！

相关文章

  • 【循环神经网络】

    RNN是一种强大的序列建模工具，适合处理各种时间序列和自然语言数据。然而，传统RNN在处理长序列时存在梯度消失问题，随着LSTM和GRU等改进模型的引入，RNN的性能得到了极大提升。无论是在自然语言处

    阅读更多2024-11-17
  • Linux---shell脚本

    希望通过本文的学习，你能够掌握Shell脚本的基本知识和实用技巧，将Shell脚本融入到你的日常工作中，成为你提高工作效率、实现自动化任务的得力助手。让我们一起踏上这段探索Shell脚本的旅程，开启一

    阅读更多2024-11-17
  • Linux-DNS

    Linux中配置DNS服务，包括DNS工作流程、配置等、以及其他的一些需要注意的配置文件

    阅读更多2024-11-17
  • DLL注入

    在DLL注入的时候，起的是远程的线程在上面的参数中，lpStartAddress就是线程的函数，使用LoadLibrary的地址作为线程函数的地址，这样我们就可以用LoadLibrary来起lpPar

    阅读更多2024-11-17
  • 力扣62.不同路径

    所以有 从左上角到右下角的过程中，我们需要移动 m+n−2 次，其中有 m−1 次向下移动，n−1 次向右移动。由于我们每一步只能从向下或者向右移动一步，因此要想走到 (i,j)，如果向下走一步，那么

    阅读更多2024-11-17
  • 【JAVA毕业设计】基于Vue和SpringBoot的冬奥会科普平台

    本文首先介绍了冬奥会科普管理的技术发展背景与发展现状，然后遵循软件常规开发流程，首先针对平台选取适用的语言和开发平台，根据需求分析制定模块并设计数据库结构，再根据平台总体功能模块的设计绘制平台的功能模

    阅读更多2024-11-17
  • 基于Spring Boot的电商系统开发策略

    现代经济快节奏发展以及不断完善升级的信息化技术，让传统数据信息的管理升级为软件存储，归纳，集中处理数据信息的管理方式。网上商城系统的设计方案比如功能框架的设计，比如数据库的设计的好坏也就决定了该系统在

    阅读更多2024-11-17
  • C++创建型模式之原型模式

    通过原型设计模式，我们可以轻松地复制现有角色，避免了重复的构造代码，并且可以根据需要对克隆的角色进行微调。这种模式在复杂的游戏场景中非常有用，特别是在需要创建多个相似角色时。相似性：原型模式和拷贝构造

    阅读更多2024-11-17
  • 【C语言】前端未来

    WebXR：WebXR是Web Reality Experience的缩写，它通过AR和VR技术提供沉浸式的交互体验，预计在未来会成为构建虚拟现实应用的重要平台，特别是结合混合现实设备如手机和头戴设备

    阅读更多2024-11-17
  • ASUS/华硕灵耀X双屏Pro UX8402Z 原厂Win11-22H2系统 工厂文件 带ASUS Recovery恢复

    系统 ，安装结束后带隐藏分区，一键恢复，以及机器所有驱动软件。请注意：仅支持以上型号专用，其他华硕机器切勿使用。需准备一个20G以上u盘进行恢复。系统版本：windows11。

    阅读更多2024-11-17
自学内容网
Copyright © 2015-2024