[[389615]]

開啟慢查詢日志

在項目中我們會經常遇到慢查詢，當我們遇到慢查詢的時候一般都要開啟慢查詢日志，并且分析慢查詢日志，找到慢sql，然后用explain來分析

系統(tǒng)變量

MySQL和慢查詢相關的系統(tǒng)變量如下： 

執(zhí)行如下語句看是否啟用慢查詢日志，ON為啟用，OFF為沒有啟用 

show variables like "%slow_query_log%" 

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

修改配置文件

修改配置文件my.ini，在[mysqld]段落中加入如下參數(shù) 

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

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

設置全局變量

我在命令行中執(zhí)行如下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; 

「想要永久生效得到配置文件中配置，否則數(shù)據(jù)庫重啟后，這些配置失效」

分析慢查詢日志

因為mysql慢查詢日志相當于是一個流水賬，并沒有匯總統(tǒng)計的功能，所以我們需要用一些工具來分析一下

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協(xié)議數(shù)據(jù)來進行分析。pt-query-digest是一個perl腳本，只需下載并賦權即可執(zhí)行

下載和賦權 

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參數(shù)把分析結果輸出到表中時，如果沒有表就自動創(chuàng)建。 
--create-history-table  當使用--history參數(shù)把分析結果輸出到表中時，如果沒有表就自動創(chuàng)建。 
--filter  對輸入的慢查詢按指定的字符串進行匹配過濾后再進行分析 
--limit限制輸出結果百分比或數(shù)量，默認值是20,即將最慢的20條語句輸出，如果是50%則按總響應時間占比從大到小排序，輸出到總和達到50%位置截止。 
--host  mysql服務器地址 
--user  mysql用戶名 
--password  mysql用戶密碼 
--history 將分析結果保存到表中，分析結果比較詳細，下次再使用--history時，如果存在相同的語句，且查詢所在的時間區(qū)間和歷史表中的不同，則會記錄到數(shù)據(jù)表中，可以通過查詢同一CHECKSUM來比較某類型查詢的歷史變化。 
--review 將分析結果保存到表中，這個分析只是對查詢條件進行參數(shù)化，一個類型的查詢一條記錄，比較簡單。當下次使用--review時，如果存在相同的語句分析，就不會記錄到數(shù)據(jù)表中。 
--output 分析結果輸出類型，值可以是report(標準分析報告)、slowlog(Mysql slow log)、json、json-anon，一般使用report，以便于閱讀。 
--since 從什么時間開始分析，值為字符串，可以是指定的某個”yyyy-mm-dd [hh:mm:ss]”格式的時間點，也可以是簡單的一個時間值：s(秒)、h(小時)、m(分鐘)、d(天)，如12h就表示從12小時前開始統(tǒng)計。 
--until 截止時間，配合—since可以分析一段時間內的慢查詢。 

「常用DSN」 

A    指定字符集 
D    指定連接的數(shù)據(jù)庫 
P    連接數(shù)據(jù)庫端口 
S    連接Socket file 
h    連接數(shù)據(jù)庫主機名 
p    連接數(shù)據(jù)庫的密碼 
t    使用--review或--history時把數(shù)據(jù)存儲到哪張表里 
u    連接數(shù)據(jù)庫用戶名 

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協(xié)議數(shù)據(jù)，然后產生最慢查詢的報表 
# 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 

用法實戰(zhàn)

「編寫存儲過程批量造數(shù)據(jù)」

在實際工作中沒有測試性能，我們經常需要改造大批量的數(shù)據(jù)，手動插入是不太可能的，這時候就得用到存儲過程了 

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 存儲過程名稱 ([參數(shù)列表]) 
BEGIN 
    需要執(zhí)行的語句 
END 

舉個例子，插入id為1-100000的100000條數(shù)據(jù)

用Navicat執(zhí)行 

-- 刪除之前定義的 
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); 

存儲過程的三種參數(shù)類型 

用MySQL執(zhí)行

得用DELIMITER 定義新的結束符，因為默認情況下SQL采用(;)作為結束符，這樣當存儲過程中的每一句SQL結束之后，采用(;)作為結束符，就相當于告訴MySQL可以執(zhí)行這一句了。但是存儲過程是一個整體，我們不希望SQL逐條執(zhí)行，而是采用存儲過程整段執(zhí)行的方式，因此我們就需要定義新的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; 

「開始執(zhí)行慢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; 

可以執(zhí)行如下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 

執(zhí)行后的文件如下： 

# 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> 

從最上面的統(tǒng)計sql中就可以看到執(zhí)行慢的sql

可以看到響應時間，執(zhí)行次數(shù)，每次執(zhí)行耗時(單位秒)，執(zhí)行的sql

下面就是各個慢sql的詳細分析，比如，執(zhí)行時間，獲取鎖的時間，執(zhí)行時間分布，所在的表等信息

「不由得感嘆一聲，真是神器，查看慢sql超級方便」

最后說一個我遇到的一個有意思的問題，有一段時間線上的接口特別慢，但是我查日志發(fā)現(xiàn)sql執(zhí)行的很快，難道是網絡的問題?

為了確定是否是網絡的問題，我就用攔截器看了一下接口的執(zhí)行時間，發(fā)現(xiàn)耗時很長，考慮到方法加了事務，難道是事務提交很慢?

于是我用pt-query-digest統(tǒng)計了一下1分鐘左右的慢日志，發(fā)現(xiàn)事務提交的次很多，但是每次提交事務的平均時長是1.4s左右，果然是事務提交很慢。