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