慢SQL探秘之為什么我的SQL很慢卻沒記錄在慢查詢日志里

作者：懂點IT的耿小廚 2024-03-25 07:30:03

本文將總結一些比較常見的運行比較慢但不會被記錄在慢SQL日志里的情況。另外，慢SQL的計算方式在MySQL8.0新版本中有變化，因此，將通過對比MySQL5.7（MySQL5.7.38）與MySQL8.0（MySQL8.0.33）進行總結。

在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<=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日志中的

（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的計算方式有調整有關系。

5. 管理類SQL

管理類SQL指的是alter table、alter user等,默認情況下，此類操作雖然比較慢，超過了慢SQL日志監控的閾值，但是也不會記錄在慢SQL日志中。不過可以調整參數log_slow_admin_statements來控制是否記錄此類SQL。

（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日志表里無此記錄。

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_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)

此時，添加索引的操作將被記錄。

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

此時慢SQL會被記錄。MySQL8.0中同樣如此。

（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)

可見，此時的慢SQL還是之前的，即修改后，即使SQL運行時間超過了慢SQL閾值，但是掃描行數低于min_examined_row_limit參數指定的值，此時也不會被記錄。MySQL同樣如此。

7. 其他SQL

除了以上的情況外，復制線程的查詢、被DBAkill的正在運行的SQL或部分未運行完畢的SQL也不會記錄在慢SQL日志中（不過部分情況再MySQL8.0中有所變更），因此需要大家根據實際情況多總結及測試。

責任編輯：姜華來源：數據庫干貨鋪

事務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)

事務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)