慢SQL探秘之為什么我的SQL很慢卻沒記錄在慢查詢?nèi)罩纠?/h1>
在MySQL數(shù)據(jù)庫中，想了解數(shù)據(jù)庫運行情況的重要指標(biāo)之一是慢SQL。而并非如某些人所說的所有運行慢的SQL都會被記錄在慢SQL日志（或日志表）里，抑或是沒有慢SQL就代表沒有運行慢的SQL。本文將總結(jié)一些比較常見的運行比較慢但不會被記錄在慢SQL日志里的情況。另外，慢SQL的計算方式在MySQL8.0新版本中有變化，因此，將通過對比MySQL5.7（MySQL5.7.38）與MySQL8.0（MySQL8.0.33）進行總結(jié)。
1. 準(zhǔn)備工作
部署了兩套環(huán)境，分別是MySQL5.7（MySQL5.7.38）版本及MySQL8.0（MySQL8.0.33）版本。另外為了后續(xù)進行慢SQL測試，此時先創(chuàng)建一張測試表并清空慢SQL日志表。
（1）創(chuàng)建測試表及數(shù)據(jù)
創(chuàng)建測試表及測試數(shù)據(jù)，便于后續(xù)測試。本次通過創(chuàng)建一張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)
# 需先關(guān)閉慢SQL監(jiān)控開關(guān)
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監(jiān)控
mysql> set global slow_query_log=1;
Query OK, 0 rows affected (0.00 sec)2. 未開啟慢SQL監(jiān)控
查看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監(jiān)控。MySQL各個版本查看的方法均一樣。
另外和慢SQL相關(guān)的其他主要參數(shù)如下：
- slow_query_log: 這個參數(shù)用于啟用或禁用慢SQL監(jiān)控。設(shè)置為1表示啟用，0表示禁用。默認值為0（禁用）。
- log_output：日志存儲方式（不僅僅是慢SQL日志），默認值為'FILE'。當(dāng)log_output='FILE'表示將日志存入文件；當(dāng)log_output='TABLE'表示將日志存入數(shù)據(jù)庫中的mysql.slow_log表里；當(dāng)log_output='FILE,TABLE'表示既存儲到日志文件又存儲到mysql.slow_log表里。
- slow_query_log_file: 慢SQL日志文件的路徑和文件名（5.5等低版本參數(shù)為log_slow_queries）?？梢圆辉O(shè)置該參數(shù)，系統(tǒng)則會默認給一個缺省的文件host_name-slow.log。
- long_query_time: 用于定義慢SQL的閾值時間，單位為秒。執(zhí)行時間超過該閾值的SQL語句將被記錄到慢SQL日志中。默認值為10秒。
- log_queries_not_using_indexes:如果設(shè)置為1，則將未使用索引的查詢也記錄到慢查詢?nèi)罩局?。默認值為0（禁用）。
- log_slow_admin_statements: 如果設(shè)置為1，則會記錄部分管理命令（例如ALTER TABLE）到慢SQL日志中。默認值為0（禁用）,本文后續(xù)也會繼續(xù)演示介紹。
- log_slow_extra: 如果設(shè)置為1，則除了慢SQL日志的標(biāo)準(zhǔn)輸出之外，還將在日志中包括額外的信息，如用戶、主機、客戶端命令等。默認值為0（禁用）。
- log_slow_slave_statements: 如果設(shè)置為1，則將從服務(wù)器執(zhí)行的慢SQL記錄到主服務(wù)器的慢SQL日志中。默認值為0（禁用）。
- min_examined_row_limit: 僅在查詢的行數(shù)超過指定值時，才記錄到慢SQL日志中。默認值為0，表示不限制。
3. SQL運行時間小于慢SQL監(jiān)控閾值時間
第一部分已經(jīng)介紹了和慢SQL相關(guān)的參數(shù)中的long_query_time，即慢SQL閾值。所以，當(dāng)SQL運行時間小于該閾值時，對于的SQL將不會記錄在慢SQL日志中。查看和修改慢SQL監(jiān)控閾值的方法如下：
# 查看慢SQL閾值
mysql> SHOW GLOBAL VARIABLES LIKE 'long_query_time';
+-----------------+----------+
| Variable_name | Value |
+-----------------+----------+
| long_query_time | 0.500000 |
+-----------------+----------+
1 row in set (0.00 sec)
# 設(shè)置慢SQL閾值
mysql> set global long_query_time=0.6;
Query OK, 0 rows affected (0.00 sec)
# 設(shè)置完成后可以查看全局的閾值
mysql> SHOW GLOBAL VARIABLES LIKE 'long_query_time';
+-----------------+----------+
| Variable_name | Value |
+-----------------+----------+
| long_query_time | 0.600000 |
+-----------------+----------+
1 row in set (0.01 sec)
# 但是當(dāng)前會話的慢SQL閾值是沒變的，這個同其他包含全局和會話級的參數(shù)類似
mysql> SHOW VARIABLES LIKE 'long_query_time';
+-----------------+----------+
| Variable_name | Value |
+-----------------+----------+
| long_query_time | 0.500000 |
+-----------------+----------+
1 row in set (0.00 sec)
注：對于不同的數(shù)據(jù)庫需按照實際情況設(shè)置慢SQL監(jiān)控的閾值，例如TP業(yè)務(wù)的實例且配置相對較好時，建議閾值設(shè)置的較低；如果是AP類型業(yè)務(wù)，則適當(dāng)放寬慢SQL的閾值。
4. 鎖等待或事務(wù)等待的SQL
開啟2個事務(wù)，然后模擬鎖等待情況。
（1）MySQL5.7 中測試
首先測試MySQL5.7版本的情況：
事務(wù)1 | 事務(wù)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中測試
事務(wù)1 | 事務(wù)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后續(xù)新版中慢SQL的計算方式有調(diào)整有關(guān)系。
5. 管理類SQL
管理類SQL指的是alter table、alter user等,默認情況下，此類操作雖然比較慢，超過了慢SQL日志監(jiān)控的閾值，但是也不會記錄在慢SQL日志中。不過可以調(diào)整參數(shù)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）調(diào)整log_slow_admin_statements
log_slow_admin_statements參數(shù)是控制記錄超時的管理操作SQL是否記錄到慢查詢?nèi)罩尽ＤJ情況下的值是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參數(shù)控制，默認值為0，即如果SQL掃描的行數(shù)少于此值時，將不會被記錄在慢SQL日志中，否則將會被記錄。由于默認值是0，因此掃描行數(shù)>=0的且符合其他記錄慢SQL的條件時便會被記錄。如果想忽略掃描數(shù)據(jù)量較少，但是又不想記錄超過閾值的SQL，則可以調(diào)整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，可以隱式轉(zhuǎn)換導(dǎo)致無法走索引，使其變慢，便于測試
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）修改參數(shù)
為了測試，此時將min_examined_row_limit值設(shè)置為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閾值，但是掃描行數(shù)低于min_examined_row_limit參數(shù)指定的值，此時也不會被記錄。MySQL同樣如此。
7. 其他SQL
除了以上的情況外，復(fù)制線程的查詢、被DBAkill的正在運行的SQL或部分未運行完畢的SQL也不會記錄在慢SQL日志中（不過部分情況再MySQL8.0中有所變更），因此需要大家根據(jù)實際情況多總結(jié)及測試。
