【MySQL】配置慢查詢日誌來紀錄耗時的查詢

日期：

https://www.flickr.com/photos/8058098@N07/2718571627/

透過慢查詢日誌，可以讓 MySQL 紀錄平常是哪些指令的執行速度太慢，做為日後進行性能優化的依據。

本文首先會說明如何配置慢查詢日誌。接著準備大量測試資料，並搭配查詢指令，確認耗時長的查詢是否有被紀錄下來。



一、配置慢查詢日誌

（一）配置參數

執行 SHOW VARIABLES LIKE "slow_query_log"; 指令，可確認慢查詢日誌的功能是否有開啟（預設為關閉）。範例結果如下：

Variable_nameValue
slow_query_logOFF

若想進行配置，需編輯 MySQL 的配置文件。假設讀者是在 Docker 容器或 Linux 作業系統運行 MySQL，那麼該檔案的位置是「/etc/my.cnf」。

在配置文件中找到「[mysql]」的文字，在其下方添加參數進行設定。

[mysql]
slow_query_log=1
long_query_time=2
slow_query_log_file=/var/lib/mysql/test-slow-query.log

這三個參數的用途如下。

  • slow_query_log：開啟或關閉慢查詢日誌功能。1 是開啟，0 是關閉。
  • long_query_time：查詢超過一定時間，會被視為慢查詢。單位為秒，預設值為 10。
  • slow_query_log_file：慢查詢日誌的位置。本身有預設值，讀者也可定義自己的檔案路徑。

透過修改配置文件的做法，是永久生效的。

（二）修改配置檔權限

編輯完，需重新啟動 MySQL 服務，才會生效。但在這之前，請確認該檔案的權限是否變成 777（rwxrwxrwx）。是的話，應修改為 644（rw-r--r--）。

chmod 644 /etc/my.cnf

這麼做是因為 MySQL 認為配置文件的開放權限太大，是不安全的，於是忽略該檔案，還會出現警告訊息。

Warning: World-writable config file `/etc/my.cnf` is ignored

若讀者是使用 Docker，將配置文件掛載到 MySQL 容器，那麼後續又修改內容的話，其權限又會變回 777。這點要特別留意。

參考資料：mysql啟動時，提示/etc/my.cnf 被忽略的問題處理

（三）確認配置生效

重新啟動服務後，可執行下列指令，查看目前參數是否生效。

SHOW VARIABLES LIKE "slow_query_log";
Variable_nameValue
slow_query_logON
SHOW VARIABLES LIKE "long_query_time";
Variable_nameValue
long_query_time2
SHOW VARIABLES LIKE "slow_query_log_file";
Variable_nameValue
slow_query_log_file/var/lib/mysql/test-slow-query.log

二、準備測試資料

為了確認執行過久的查詢，能否被確實紀錄到慢查詢日誌，本節讓我們準備測試資料。若讀者目前不想準備資料，可跳到第三節繼續閱讀，筆者會提到替代方案。

以下是產品資料表的定義。

以下的預存程序，會在產品資料表中插入約 1048 萬筆資料。筆者執行了約 26 分鐘。

以下是類別資料表的定義與測試資料。


三、查看慢查詢日誌

上一節準備好 1048 萬筆測試資料後，在沒有索引的情況下，請試著執行以下兩組查詢指令。

計算類別名稱為「A」的產品之平均價格：

將產品以類別編號與價格來排序：

或是讀者若沒有測試資料，也可執行以下指令，強制延遲指定的秒數（此處為 3 秒）。

SELECT SLEEP(3);

讀者應該感受到花了好幾秒鐘。接著回到 Linux 或 Docker 容器的環境，查看慢查詢日誌的內容。

cat /var/lib/mysql/test-slow-query.log

範例內容如下。

# Time: 2024-02-28T10:25:31.435808Z
# User@Host: root[root] @  [172.17.0.1]  Id:    14
# Query_time: 4.987936  Lock_time: 0.000016 Rows_sent: 1  Rows_examined: 10485770
SET timestamp=1709115926;
SELECT AVG(`price`)
FROM `test_product` AS `p`
JOIN `test_category` AS `c` ON `p`.`categoryId` = `c`.`id`
WHERE `c`.`name` = "A"
LIMIT 0, 1000;

# Time: 2024-02-28T10:25:55.676230Z
# User@Host: root[root] @  [172.17.0.1]  Id:    14
# Query_time: 6.367919  Lock_time: 0.000004 Rows_sent: 1000  Rows_examined: 10486760
SET timestamp=1709115949;
SELECT *
FROM `test_product`
ORDER BY `categoryId` ASC, `price` DESC
LIMIT 0, 1000;

# Time: 2024-02-28T10:30:41.899383Z
# User@Host: root[root] @  [172.17.0.1]  Id:    14
# Query_time: 3.002177  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 1
SET timestamp=1709116238;
SELECT SLEEP(3)
LIMIT 0, 1000;

能看到剛剛的指令被列在上面，包含執行的時間點、耗時與指令內容等。


四、確認索引的成效

因為上述查詢指令的花費時間比較長，本節會建立索引，確認相同規模的資料，在執行相同指令的查詢下，能否帶來耗時上的改善。

以下是挑選「類別編號」與「價格」這兩個欄位，建立聯合索引（compounded index）。

CREATE INDEX `idx_test_product_cateogry_price` ON `test_product`(`categoryId`, `price`);

接著再執行相同的查詢後，讀者應該不會在慢查詢日誌看到新的紀錄了。


上一篇：【MySQL】索引的建立、刪除與閱讀資訊

下一篇：【MySQL】透過閱讀執行計劃來確認索引效果

留言

張貼留言