MySQL中的慢查詢日誌

程序猿集錦 發佈 2021-08-03T07:47:33.968154+00:00

關注《程序猿集錦》,獲取更多分享。

關注《程序猿集錦》,獲取更多分享。

  • 背景
  • 什麼是慢查詢日誌
  • 如何開啟慢查詢日誌
  • 慢查詢日誌的參數
  • 如何讀懂慢查詢日誌
    • 慢查詢日誌文件中的日誌
    • 慢查詢日誌表中的日誌
  • 如何分析慢查詢日誌
  • 總結


背景

你是否有這樣的疑問:我還如何定位當前MySQL數據中的一些執行特別耗時的SQL語句,那些特別慢的SQL都有哪些?我怎麼樣把他們都給篩選出來呢?MySQL中是否可以記錄這些執行特別慢的SQL?

MySQL中的慢查詢日誌就是來滿足上面的這些需求而設計的。


什麼是慢查詢日誌

MySQL中提供了一個記錄耗時特別長的SQL語句的功能,這個功能就是我們平時聽說的慢查詢日誌。

你可能會問這些日誌記錄在哪裡呢?我平時怎麼沒有看到過。這個慢查詢日誌的功能,在默認情況下是不會自動開啟的。也是需要我們自行的選項性的打開這個功能才可以記錄慢查詢的SQL語句。打開之後,可以選擇把這個日誌記錄在伺服器上面的某個目錄下面(默認是記錄在日誌文件中),當然也可以記錄在MySQL的表中,還可以選擇及記錄日誌文件中還記錄在表中。具體如何配置,下面會詳細介紹。

打開之後,肯定都會對資料庫的性能是有一定的影響的,但是這個影響也是我們可以接受的範圍內的。同時,它還會占用一定的磁碟存儲空間。我們一般情況下,不會在生產環境上開啟這個記錄慢查詢日誌的功能的。我們只會在DEV、SIT、UAT等環境下面才會開啟這個功能,把所有的慢查詢的SQL在這些環境中給篩選出來,解決掉,這樣在生產環境中就沒有必要開啟慢查詢的功能了。


如何開啟慢查詢日誌

在開啟之前,首先需要檢查一下當前的MySQL是否已經開啟了慢查詢日誌記錄的功能,如果開啟了,就不需要再次執行了,如果沒有開啟,在參考下面的配置開啟慢查詢的功能。可以通過如下命令查看是否開啟了慢查詢日誌:


mysql> set global slow_query_log = 1; /*開啟慢查詢日誌的命令*/
Query OK, 0 rows affected (0.03 sec)

mysql> show variables like "slow_%";
+---------------------+------------------------------+
| Variable_name       | Value                        |
+---------------------+------------------------------+
| slow_launch_time    | 2                            |
| slow_query_log      | ON                           |/*ON, 此時表示已經開啟了慢查詢日誌記錄的功能*/
| slow_query_log_FILE | /var/lib/mysql/test-slow.log |
+---------------------+------------------------------+
3 rows in set (0.02 sec)

mysql> show variables like 'long_query_time';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 3.000000 |
+-----------------+----------+
1 row in set (0.01 sec)

如果要開啟慢查詢日誌,可以在MySQL的配置文件中配置如下參數:


mysql> select sleep(11);
+----------+
| sleep(11) |
+----------+
|        0 |
+----------+
1 row in set (11.00 sec)

配置這個參數之後,重啟MySQL實例之後,就可以了。如果不想重啟MySQL資料庫實例,可以直接在MySQL的terminal窗口中,執行如下的SQL命令來開啟慢查詢日誌,但是同時也需要在配置文件中配置上上面的參數,否則MySQL示例重啟後,慢查詢日誌又關閉了。為了避免重啟MySQL數據實例之後失效,所以上面的修改配置文件的步驟也不可以省略。


root@test:/# tail -6 /var/lib/mysql/test-slow.log
# Time: 2020-12-30T08:42:25.599835Z
# User@Host: root[root] @  [172.19.0.1]  Id:     2
# Query_time: 3.001212  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
use feng;
SET timestamp=1609317745;
select sleep(11);
root@test:/#

這裡需要先了解3個參數:

  • long_query_time:決定一個SQL語句是否是慢查詢的閾值。如果一個SQL的執行時間超過這個閾值,則認定這個SQL為慢查詢的SQL語句,將其記錄在慢查詢日誌中,否則不記錄。默認值為10s,如果設置為0s,則表示記錄所有的SQL語句。
  • slow_query_log:慢查詢日誌是否開啟的標識,ON或者1表示開啟,OFF或者0表示沒有開啟。
  • slow_query_log_file:慢查詢日誌存放目錄,對應到MySQL資料庫伺服器上面的一個日誌文件。默認的日誌文件名稱為伺服器主機名稱-slow.log。默認的日誌存儲的路徑為變量:datadir的值所指向的目錄。

上面我們已經開啟了慢查詢日誌的功能,下面我們來驗證開啟後的效果。

我們在MySQL的命令行中執行一個慢查詢SQL,然後看下這個SQL語句是否被記錄在了MySQL的慢查詢日誌中。因為我們上面使用的默認慢查詢的閾值為10s,所以我們執行下面的一個執行11s的SQL語句。


root@test:/# tail -6 /var/lib/mysql/test-slow.log
select sleep(11);
# Time: 2020-12-30T16:48:49.137716+08:00
# User@Host: root[root] @  [172.19.0.1]  Id:     2
# Query_time: 4.000988  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1609318129;
select sleep(12);
root@test:/#

現在去查看日誌文件,查看的結果如下:


[mysqld]
# 設置日誌中記錄日誌記錄的時候使用的時間,避免和系統時間差8個小時的問題。
log_timestamps=system

############### 慢查詢日誌配置相關 #######################################
slow_query_log=1
# 慢查詢日誌記錄在mysql.slow_log表中
log_output=table,file
slow_query_log_file=/var/lib/mysql/test-slow.log
# 慢查詢日誌的SQL耗時的閾值
long_query_time=10
# 對沒有使用索引的SQL,即便是查詢耗時低於10s,也記錄日誌
#log_queries_not_using_indexes=1
# 對沒有使用索引的SQL,即便是查詢耗時低於10s,也記錄日誌,但是一分鐘內置記錄1次。
#log_throttle_queries_not_using_indexes=1
# 沒有使用索引的SQL,如果掃描的行數低於1000,則不記錄到慢查詢日誌中
#min_examined_row_limit=1000
# alter,analyze語句,如果超過慢查詢的閾值,也記錄在慢查詢日誌中
#log_slow_admin_statements=1
############### 慢查詢日誌配置相關 #######################################



通過上面的查詢結果,我們可以確認我們的開啟已經生效了,但是有一個小的問題,日誌的記錄時間對不上,我執行的時間是2020-12-30 16:42:25,但是上面記錄的時間是:2020-12-30T08:42:25.599835Z。這是因為我們的記錄日誌的參數log_timestamps沒有配置正確導致的。我們修改一下這個參數的配置,然後再次驗證一下。


mysql> show global variables like 'log_timestamps';
+----------------+-------+
| Variable_name  | Value |
+----------------+-------+
| log_timestamps | UTC   |
+----------------+-------+
1 row in set (0.01 sec)

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

mysql> show global variables like 'log_timestamps';
+----------------+--------+
| Variable_name  | Value  |
+----------------+--------+
| log_timestamps | SYSTEM |
+----------------+--------+
1 row in set (0.01 sec)

mysql> select sleep(12);
+----------+
| sleep(12) |
+----------+
|        0 |
+----------+
1 row in set (12.00 sec)

mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2020-12-30 16:51:26 |
+---------------------+
1 row in set (0.02 sec)

此時我們再次去看下慢查詢日誌中記錄的時間是否正確:


# Time: 2020-12-30T18:00:51.995777+08:00
# User@Host: root[root] @  [172.19.0.1]  Id:     2
# Query_time: 12.006039  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1609322451;
select sleep(12);


慢查詢日誌的參數

前面我們認識了幾個關於慢查詢日誌的參數,其實慢查詢日誌的參數還有很多。下面逐一介紹一下。可以根據自己的業務需求,選擇性的配置。

  • log_output:決定慢查詢日誌記錄在哪裡,是日誌文件中,還是表中,還是兩個地方都記錄。它的值我可以為:FILE、TABLE、FILE,TABLE中的一個。如果為TABLE表示記錄在表中,表的名稱為:mysql.slow_log。如果為FILE表示只記錄在日誌文件中,日誌路徑默認在datadir變量中所配置的路徑下,日誌文件名稱為主鍵名-slow.log,這個路徑和名稱都是可以在my.cnf配置文件中根據需求執行配置修改。如果是FILE,TABLE則表示在表和日誌中同時記錄慢查詢日誌。
  • slow_query_log_file:如果是使用日誌文件來存儲慢查詢日誌,可以通過這個參數配置具體的慢查詢日誌的存儲目錄,而不使用默認的存儲目錄和名稱。
  • log_queries_not_using_indexes:如果一個SQL語句沒有時候用到任何索引查詢,那麼將這個SQL語句也記錄在慢查詢日誌中。避免漏掉由於原先數據量小、SQL查詢語句執行比較快沒有超過慢查詢的閾值、且沒有使用任何索引的SQL,因為這些SQL語句有可能因為日後的表中的數據量增加,而導致他們的查詢效率急劇下降。
  • log_throttle_queries_not_using_indexes:控制每一分鐘內,那些因為沒有使用索引的SQL在慢查詢日誌中記錄的次數。避免一分鐘內頻繁記錄沒有使用索引的SQL的情況,從而減少了慢查詢日誌的大小,避免慢查詢日誌暴增的情況。
  • min_examined_row_limit:控制掃描記錄行數少於該值的SQL語句,不被記錄在慢查詢日誌中。前面介紹的參數,對沒有使用任何索引的SQL語句也記錄在慢查詢日誌中。但是有可能存在這樣的一些表,表中數據一種都是有幾十行,查詢的SQL沒有使用任何索引,查詢速度也很快。這些SQL即使沒有使用到索引,也可以不記錄在慢查詢日誌中。通過這個參數就可以避免把這些SQL也記錄在內。
  • log_slow_admin_statements:是否記錄一些管理命令使用的SQL到慢查詢日誌中。比如:alter table、analyze table的語句。

下面看一個比較全面的慢查詢日誌的配置參數,一般情況下不把沒有使用索引的SQL記錄進來。


mysql> select *, CONVERT(sql_text using utf8mb4) from mysql.slow_log\G
*************************** 7. row ***************************
                     start_time: 2020-12-30 18:00:51.995777
                      user_host: root[root] @  [172.19.0.1]
                     query_time: 00:00:12.006039
                      lock_time: 00:00:00.000000
                      rows_sent: 1
                  rows_examined: 0
                             db:
                 last_insert_id: 0
                      insert_id: 0
                      server_id: 100
                       sql_text: 0x73656C65637420736C65657028313229
                      thread_id: 2
CONVERT(sql_text using utf8mb4): select sleep(12)
7 rows in set (0.02 sec)
mysql>


如何讀懂慢查詢日誌


慢查詢日誌文件中的日誌

一條完整慢查詢日誌如下所示,我們來分析一些各個欄位的含義。


root@test:/# mysqldumpslow --help
Usage: mysqldumpslow [ OPTS... ] [ LOGS... ]

Parse and summarize the MySQL slow query log. Options are

  --verbose    verbose
  --debug      debug
  --help       write this text to standard output

  -v           verbose
  -d           debug
  -s ORDER     what to sort by (al, at, ar, c, l, r, t), 'at' is default
                al: average lock time
                ar: average rows sent
                at: average query time
                 c: count # SQL語句出現的次數
                 l: lock time # SQL語句鎖定表或行的時間
                 r: rows sent # SQL語句返回的結果集行數
                 t: query time # SQL語句執行鎖消耗的時間
  -r           reverse the sort order (largest last instead of first) # 倒序排列輸出結果
  -t NUM       just show the top n queries # 取top n個記錄
  -a           don't abstract all numbers to N and strings to 'S'
  -n NUM       abstract numbers with at least n digits within names
  -g PATTERN   grep: only consider stmts that include this string
  -h HOSTNAME  hostname of db server for *-slow.log filename (can be wildcard),
               default is '*', i.e. match all
  -i NAME      name of server instance (if using mysql.server startup script)
  -l           don't subtract lock time from total time

root@test:/#

  1. Time:表示這個慢查詢的SQL發生的時間。
  2. User@Host:表示這個SQL是由哪個用戶通過哪個IP位址訪問的。
  3. Query_time:表示這個SQL語句執行所花費的時間,單位是秒。
  4. Lock_time:表示這個SQL語句在執行的過程中,鎖定表或行的時間。
  5. Rows_sent:表示最後查詢的結果發送給客戶端的行數。
  6. Rows_examined:表示這個SQL語句在執行過程中,實際掃描的行數。
  7. SET timestamp=1609322451:記錄日誌的時間
  8. 最後就是SQL語句的具體內容。


慢查詢日誌表中的日誌

如果你選擇把慢查詢日誌記錄在表中,那麼會記錄在mysql.slow_log中。我們截取其中一條記錄如下所示:


mysql> select *, CONVERT(sql_text using utf8mb4) from mysql.slow_log\G
*************************** 7. row ***************************
                     start_time: 2020-12-30 18:00:51.995777
                      user_host: root[root] @  [172.19.0.1]
                     query_time: 00:00:12.006039
                      lock_time: 00:00:00.000000
                      rows_sent: 1
                  rows_examined: 0
                             db:
                 last_insert_id: 0
                      insert_id: 0
                      server_id: 100
                       sql_text: 0x73656C65637420736C65657028313229
                      thread_id: 2
CONVERT(sql_text using utf8mb4): select sleep(12)
7 rows in set (0.02 sec)
mysql>

  1. start_time:SQL語句執行的時間
  2. user_host:執行該SQL語句的用戶和IP位址
  3. query_time:該SQL語句執行所消耗的時間,單位是秒。
  4. lock_time:鎖表或行的時間。
  5. rows_sent:返回的結果集行數。
  6. rows_examined:實際掃描的記錄行數。
  7. db:該SQL語句的是在哪個schema下面執行的。
  8. server_id:在MySQL集群中,資料庫實例的編號。
  9. sql_text:SQL語句的具體內容,此處是BLOB欄位,不能直接查看,需要時候用CONVERT(sql_text using utf8mb4)函數轉換一下,再查看具體的SQL內容。
  10. thread_id:線程編號。


如何分析慢查詢日誌

最簡單也是最常用的一個工具就是MySQL自帶的mysqldumpslow。它的使用幫助如下:


root@test:/# mysqldumpslow --help
Usage: mysqldumpslow [ OPTS... ] [ LOGS... ]

Parse and summarize the MySQL slow query log. Options are

  --verbose    verbose
  --debug      debug
  --help       write this text to standard output

  -v           verbose
  -d           debug
  -s ORDER     what to sort by (al, at, ar, c, l, r, t), 'at' is default
                al: average lock time
                ar: average rows sent
                at: average query time
                 c: count # SQL語句出現的次數
                 l: lock time # SQL語句鎖定表或行的時間
                 r: rows sent # SQL語句返回的結果集行數
                 t: query time # SQL語句執行鎖消耗的時間
  -r           reverse the sort order (largest last instead of first) # 倒序排列輸出結果
  -t NUM       just show the top n queries # 取top n個記錄
  -a           don't abstract all numbers to N and strings to 'S'
  -n NUM       abstract numbers with at least n digits within names
  -g PATTERN   grep: only consider stmts that include this string
  -h HOSTNAME  hostname of db server for *-slow.log filename (can be wildcard),
               default is '*', i.e. match all
  -i NAME      name of server instance (if using mysql.server startup script)
  -l           don't subtract lock time from total time

root@test:/#

參數解釋:

序號參數名稱參數解釋1-s t按總query time排序2-s l按總locktime排序3-s s按總row send排序4-s c按count排序5-s at按平均query time排序6-s al按平均lock time排序7-s as按平均row send排序8-r倒序排列9-a不要將數字和字符串抽象成N和S。如果where id = 19 and name='張三'
mysqldumpslow工具會把這樣的SQL抽象為where id = N and name=S
而這個參數的功能就是不讓其進行這樣的轉換。10-t NUM只顯示結果的前NUM行結果。11-g後邊可以寫一個正則匹配模式,大小寫不敏感。

常用的mysqldumpslow命令使用組合有如下幾個:


root@test:# cd /var/lib/mysql
root@test:/var/lib/mysql# #按照query time排序查看日誌
root@test:/var/lib/mysql# mysqldumpslow -s t test-slow.log> slow.1.dat

root@test:/var/lib/mysql# #按照平均query time排序查看日誌
root@test:/var/lib/mysql# mysqldumpslow -s at test-slow.log > slow.2.dat

root@test:/var/lib/mysql# #按照平均query time排序並且不抽象數字的方式排序
root@test:/var/lib/mysql# mysqldumpslow -a -s at test-slow.log > slow.3.dat

root@test:/var/lib/mysql# #安裝執行次數排序
root@test:/var/lib/mysql# mysqldumpslow -a -s c test-slow.log > slow.4.dat


總結

在我們平時的開發和應用中,有必要排查出那些效率特別低的SQL語句,然後進行相應的優化,避免項目上線後,因為SQL語句的效率低拖慢整個應用系統。希望上面的這些總結可以對你使用慢查詢日誌的功能有所幫助。

關鍵字: