MySQL如何快速定位慢SQL的實戰

2022-03-22 13:01:44

開啟慢查詢紀錄檔

在專案中我們會經常遇到慢查詢，當我們遇到慢查詢的時候一般都要開啟慢查詢紀錄檔，並且分析慢查詢紀錄檔，找到慢sql，然後用explain來分析

系統變數

MySQL和慢查詢相關的系統變數如下

引數	含義
slow_query_log	是否啟用慢查詢紀錄檔， ON為啟用，OFF為沒有啟用，預設為OFF
log_output	紀錄檔輸出位置，預設為FILE，即儲存為檔案，若設定為TABLE，則將紀錄檔記錄到mysql.show_log表中，支援設定多種格式
slow_query_log_file	指定慢查詢紀錄檔檔案的路徑和名字
long_query_time	執行時間超過該值才記錄到慢查詢紀錄檔，單位為秒，預設為10

執行如下語句看是否啟用慢查詢紀錄檔，ON為啟用，OFF為沒有啟用

show variables like "%slow_query_log%"

可以看到我的沒有啟用，可以通過如下兩種方式開啟慢查詢

修改組態檔

修改組態檔my.ini，在[mysqld]段落中加入如下引數

[mysqld]
log_output='FILE,TABLE'
slow_query_log='ON'
long_query_time=0.001

需要重啟 MySQL 才可以生效，命令為 service mysqld restart

設定全域性變數

我在命令列中執行如下2句開啟慢查詢紀錄檔，設定超時時間為0.001s，並且將紀錄檔記錄到檔案以及mysql.slow_log表中

set global slow_query_log = on;
set global log_output = 'FILE,TABLE';
set global long_query_time = 0.001;

想要永久生效得到組態檔中設定，否則資料庫重啟後，這些設定失效

分析慢查詢紀錄檔

因為mysql慢查詢紀錄檔相當於是一個流水賬，並沒有彙總統計的功能，所以我們需要用一些工具來分析一下

mysqldumpslow

mysql內建了mysqldumpslow這個工具來幫我們分析慢查詢紀錄檔。

常見用法

# 取出使用最多的10條慢查詢
mysqldumpslow -s c -t 10 /var/run/mysqld/mysqld-slow.log

# 取出查詢時間最慢的3條慢查詢
mysqldumpslow -s t -t 3 /var/run/mysqld/mysqld-slow.log 

# 得到按照時間排序的前10條裡面含有左連線的查詢語句
mysqldumpslow -s t -t 10 -g 「left join」 /database/mysql/slow-log

pt-query-digest

pt-query-digest是我用的最多的一個工具，功能非常強大，可以分析binlog、General log、slowlog，也可以通過show processlist或者通過tcpdump抓取的MySQL協定資料來進行分析。pt-query-digest是一個perl指令碼，只需下載並賦權即可執行

下載和賦權

wget www.percona.com/get/pt-query-digest
chmod u+x pt-query-digest
ln -s /opt/soft/pt-query-digest /usr/bin/pt-query-digest

用法介紹

// 檢視具體使用方法 
pt-query-digest --help
// 使用格式
pt-query-digest [OPTIONS] [FILES] [DSN]

常用OPTIONS

--create-review-table 當使用--review引數把分析結果輸出到表中時，如果沒有表就自動建立。
--create-history-table 當使用--history引數把分析結果輸出到表中時，如果沒有表就自動建立。
--filter 對輸入的慢查詢按指定的字串進行匹配過濾後再進行分析
--limit限制輸出結果百分比或數量，預設值是20,即將最慢的20條語句輸出，如果是50%則按總響應時間佔比從大到小排序，輸出到總和達到50%位置截止。
--host mysql伺服器地址
--user mysql使用者名稱
--password mysql使用者密碼
--history 將分析結果儲存到表中，分析結果比較詳細，下次再使用--history時，如果存在相同的語句，且查詢所在的時間區間和歷史表中的不同，則會記錄到資料表中，可以通過查詢同一CHECKSUM來比較某型別查詢的歷史變化。
--review 將分析結果儲存到表中，這個分析只是對查詢條件進行引數化，一個型別的查詢一條記錄，比較簡單。當下次使用--review時，如果存在相同的語句分析，就不會記錄到資料表中。
--output 分析結果輸出型別，值可以是report(標準分析報告)、slowlog(Mysql slow log)、json、json-anon，一般使用report，以便於閱讀。
--since 從什麼時間開始分析，值為字串，可以是指定的某個”yyyy-mm-dd [hh:mm:ss]”格式的時間點，也可以是簡單的一個時間值：s(秒)、h(小時)、m(分鐘)、d(天)，如12h就表示從12小時前開始統計。
--until 截止時間，配合—since可以分析一段時間內的慢查詢。

常用DSN

A 指定字元集
D 指定連線的資料庫
P 連線資料庫埠
S 連線Socket file
h 連線資料庫主機名
p 連線資料庫的密碼
t 使用--review或--history時把資料儲存到哪張表裡
u 連線資料庫使用者名稱

DSN使用key=value的形式設定；多個DSN使用,分隔

使用範例

# 展示slow.log中最慢的查詢的報表
pt-query-digest slow.log

# 分析最近12小時內的查詢
pt-query-digest --since=12h slow.log

# 分析指定範圍內的查詢
pt-query-digest slow.log --since '2020-06-20 00:00:00' --until '2020-06-25 00:00:00'

# 把slow.log中查詢儲存到query_history表
pt-query-digest --user=root --password=root123 --review h=localhost,D=test,t=query_history --create-review-table slow.log

# 連上localhost，並讀取processlist，輸出到slowlog
pt-query-digest --processlist h=localhost --user=root --password=root123 --interval=0.01 --output slowlog

# 利用tcpdump獲取MySQL協定資料，然後產生最慢查詢的報表
# tcpdump使用說明：https://blog.csdn.net/chinaltx/article/details/87469933
tcpdump -s 65535 -x -nn -q -tttt -i any -c 1000 port 3306 > mysql.tcp.txt
pt-query-digest --type tcpdump mysql.tcp.txt

# 分析binlog
mysqlbinlog mysql-bin.000093 > mysql-bin000093.sql
pt-query-digest  --type=binlog mysql-bin000093.sql

# 分析general log
pt-query-digest  --type=genlog  localhost.log

用法實戰

編寫儲存過程批次造資料

在實際工作中沒有測試效能，我們經常需要改造大批次的資料，手動插入是不太可能的，這時候就得用到儲存過程了

CREATE TABLE `kf_user_info` (
  `id` int(11) NOT NULL COMMENT '使用者id',
  `gid` int(11) NOT NULL COMMENT '客服組id',
  `name` varchar(25) NOT NULL COMMENT '客服名字'
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COMMENT='客戶資訊表';

如何定義一個儲存過程呢？

CREATE PROCEDURE 儲存過程名稱 ([參數列])
BEGIN
    需要執行的語句
END

舉個例子，插入id為1-100000的100000條資料

用Navicat執行

-- 刪除之前定義的
DROP PROCEDURE IF EXISTS create_kf;

-- 開始定義
CREATE PROCEDURE create_kf(IN loop_times INT) 
BEGIN
	DECLARE var INT;
	SET var = 1;
	WHILE var < loop_times DO    
		INSERT INTO kf_user_info (`id`,`gid`,`name`) 
		VALUES (var, 1000, var);
		SET var = var + 1;
	END WHILE; 
END;

-- 呼叫
call create_kf(100000);

儲存過程的三種引數型別

引數型別	是否返回	作用
IN	否	向儲存過程傳入引數，儲存過程中修改該引數的值，不能被返回
OUT	是	把儲存過程計算的結果放到該引數中，呼叫者可以得到返回值
INOUT	是	IN和OUT的結合，即用於儲存過程的傳入引數，同時又可以把計算結構放到引數中，呼叫者可以得到返回值

用MySQL執行

得用DELIMITER 定義新的結束符，因為預設情況下SQL採用（;）作為結束符，這樣當儲存過程中的每一句SQL結束之後，採用（；）作為結束符，就相當於告訴MySQL可以執行這一句了。但是儲存過程是一個整體，我們不希望SQL逐條執行，而是採用儲存過程整段執行的方式，因此我們就需要定義新的DELIMITER ，新的結束符可以用（//）或者（$$）

因為上面的程式碼應該就改為如下這種方式

DELIMITER //
CREATE PROCEDURE create_kf_kfGroup(IN loop_times INT)  
BEGIN  
	DECLARE var INT;
	SET var = 1;
	WHILE var <= loop_times DO    
		INSERT INTO kf_user_info (`id`,`gid`,`name`) 
		VALUES (var, 1000, var);
		SET var = var + 1;
	END WHILE;  
END //
DELIMITER ;

查詢已經定義的儲存過程

show procedure status;

開始執行慢sql

select * from kf_user_info where id = 9999;
select * from kf_user_info where id = 99999;
update kf_user_info set gid = 2000 where id = 8888;
update kf_user_info set gid = 2000 where id = 88888;

可以執行如下sql檢視慢sql的相關資訊。

SELECT * FROM mysql.slow_log order by start_time desc;

檢視一下慢紀錄檔儲存位置

show variables like "slow_query_log_file"

pt-query-digest /var/lib/mysql/VM-0-14-centos-slow.log

執行後的檔案如下

# Profile
# Rank Query ID                            Response time Calls R/Call V/M 
# ==== =================================== ============= ===== ====== ====
#    1 0xE2566F6154AFF41948FE497E53631B43   0.1480 56.1%     4 0.0370  0.00 UPDATE kf_user_info
#    2 0x2DFBC6DBF0D68EF2EC2AE954DC37A1A4   0.1109 42.1%     4 0.0277  0.00 SELECT kf_user_info
# MISC 0xMISC                               0.0047  1.8%     2 0.0024   0.0 <2 ITEMS>

從最上面的統計sql中就可以看到執行慢的sql

可以看到響應時間，執行次數，每次執行耗時（單位秒），執行的sql

下面就是各個慢sql的詳細分析，比如，執行時間，獲取鎖的時間，執行時間分佈，所在的表等資訊

不由得感嘆一聲，真是神器，檢視慢sql超級方便

最後說一個我遇到的一個有意思的問題，有一段時間線上的介面特別慢，但是我查紀錄檔發現sql執行的很快，難道是網路的問題？

為了確定是否是網路的問題，我就用攔截器看了一下介面的執行時間，發現耗時很長，考慮到方法加了事務，難道是事務提交很慢？

於是我用pt-query-digest統計了一下1分鐘左右的慢紀錄檔，發現事務提交的次很多，但是每次提交事務的平均時長是1.4s左右，果然是事務提交很慢。