Mysqldumpslow的用法匯總

mysqldumpslow --help可顯示其參數的使用

 

經常使用的參數：

-s，是order的順序

al   平均鎖定時間

ar   平均返回記錄時間

at   平均查詢時間（默認）

c    計數

l    鎖定時間

r    返回記錄

t    查詢時間

 

-t，是top n的意思，即為返回前面多少條的數據

-g，后邊可以寫一個正則匹配模式，大小寫不敏感的

例子：

mysqldumpslow -t 10 -s t -g “left join” host-slow.log

使用mysqldumpslow的分析結果不會顯示具體完整的sql語句，說明：

1：假如真正的sql語句如下：

SELECT * FROM sms_send WHERE service_id=10 GROUP BY content LIMIT 0, 1000;

 

mysqldumpslow顯示的結果會是：

Count: 1  Time=1.91s (1s)  Lock=0.00s (0s)  Rows=1000.0 (1000), vgos_dba[vgos_dba]@[10.130.229.196]
SELECT * FROM sms_send WHERE service_id=N GROUP BY content LIMIT N, N;

 

2：如果我們再執行一條

SELECT * FROM sms_send WHERE service_id=20 GROUP BY content LIMIT 10000, 1000;

mysqldumpslow顯示的結果會是：

Count: 2  Time=2.79s (5s)  Lock=0.00s (0s)  Rows=1.0 (2), vgos_dba[vgos_dba]@[10.130.229.196]

SELECT * FROM sms_send WHERE service_id=N GROUP BY content LIMIT N, N;

 

雖然這兩條語句條件不一樣，

1：一個是server_id=10,一個是server_id=20

2：一個是LIMIT 0, 1000,一個是LIMIT 10000, 1000

但是mysqldumpslow分析會認為這是一種類型的語句，會合並顯示。

 

3：假設我們執行

SELECT * FROM sms_send WHERE service_id<=10 GROUP BY content LIMIT 0, 1000;

執行mysqldumpslow結果是

Count: 1  Time=2.91s (2s)  Lock=0.00s (0s)  Rows=1000.0 (1000), vgos_dba[vgos_dba]@[10.130.229.196]

SELECT * FROM sms_send WHERE service_id<=N GROUP BY content LIMIT N, N;

可以看出它和上面我們寫的sql語句是兩種類型

mysqldumpslow的分析結果

Count會告訴我們這種類型的語句執行了幾次

Time會告訴我們這種類型的語句執行的最大時間

Time=2.79s (5s)中（5s）是指這類型的語句執行總共花費的時間

例：

Count: 2  Time=2.79s (5s)  Lock=0.00s (0s)  Rows=1.0 (2), vgos_dba[vgos_dba]@[10.130.229.196]

 

告訴我們執行了2次

最大時間是2.79s

總共花費時間5s

lock時間0s

單次返回的結果數是1條記錄

2次總共返回2條記錄

mysqldumpslow -s t -t 10 slow.log

查詢的結果是10條執行時間最慢的sql語句，其中-s t是指此類類型的語句的執

行總時長

Count: 1  Time=2.91s (2s)  Lock=0.00s (0s)  Rows=1000.0 (1000), vgos_dba[vgos_dba]@[10.130.229.196]

和
Count: 2  Time=2.79s (5s)  Lock=0.00s (0s)  Rows=1.0 (2), vgos_dba[vgos_dba]@[10.130.229.196]

比較的結果是

Count: 2  Time=2.79s (5s)  Lock=0.00s (0s)  Rows=1.0 (2), vgos_dba[vgos_dba]@[10.130.229.196]

排在前面，因為比較的時長是(5s)和(2s)，而不是2.79s和2.91s

-s at比較的也是(5s)/count:2和(2s)/Count: 1

所以：-s at是

Count: 1  Time=2.91s (2s)  Lock=0.00s (0s)  Rows=1000.0 (1000), vgos_dba[vgos_dba]@[10.130.229.196]

排在前面。

 

 Rows=1.0 (2) 是按照以下邏輯展示的

（2）是指在Count: 2次數總共返回了2條記錄集；row=1.0顯示（2）/Count: 2，

如果此時Count是3，那么row的計算方式是Rows=2/3,Rows=0.67

 

主要功能是, 統計不同慢sql的出現次數(Count),執行最長時間(Time),累計總耗費時間(Time),等待鎖的時間(Lock),發送給客戶端的行總數(Rows),掃描的行總數(Rows)

 

 

---------------------

 

緣起： 實際生產環境中MySQL出現查詢慢的問題，為了分析慢查詢，開啟慢查詢日志，並對日志進行分析。 
為了避免在生成環境中產生誤操作，把記錄的慢查詢日志copy回來，到自己的電腦中進行分析。 
分析結果：

 

[root@dras-test local]#mysqldumpslow -a -s t -t 2 /opt/slow_query_log.txt 

Reading mysql slow query log from /opt/slow_query_log.txt
Count: 1  Time=0.00s (0s)  Lock=0.00s (0s) Rows=0.0 (0), LibSvr[LibSvr]@[10.1.202.57] # Schema: information_schema Last_errno: 0 Killed: 0 # Query_time: 11.257168 Lock_time: 0.000141 Rows_sent: 366777 Rows_examined: 366777 Rows_affected: 0 # Bytes_sent: 43251512 SET timestamp=1492111317; SELECT * FROM `INNODB_BUFFER_PAGE_LRU` Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=0.0 (0), LibSvr[LibSvr]@[10.1.122.132] # Schema: el Last_errno: 0 Killed: 0 # Query_time: 4.471143 Lock_time: 0.000097 Rows_sent: 1 Rows_examined: 8018065 Rows_affected: 0 # Bytes_sent: 1098 SET timestamp=1490682921; SELECT `UserID`,`FileName`,`AdjunctGuid`,`LiteratureGuid`,`NoteGuid`,`AdjunctType`,`Md5`,`ID`,`ServerModifyTime`,`FileSize` FROM `el_user_adjunct_info` WHERE (`AdjunctGuid` = '4528cef4139846678cddf0d00170af9f.caj') 

 

 

問題出現了，仔細看的同學已經看出了端倪，Time、Lock、Rows統計數據都為0。

 

mysqldumpslow是一個perl腳本，其中使用正則表達式對log文件進行逐行匹配，匹配完成后提取出匹配的值然后替換整行為空。

 

s/^# Query_time: ([0-9.]+)\s+Lock_time: ([0-9.]+)\s+Rows_sent: ([0-9.]+).*\n//;

 

 

經單獨測試，此表達式沒問題，可以正確匹配。但是在mysqldumpslow中卻未匹配成功，經過一番查找、對比，發現從生產環境中copy下來的日志格式和mysqldumpslow中要解析的格式不一致，日志中多了一行

 

 18 # User@Host: LibSvr[LibSvr] @ [10.1.122.131] Id: 10  19 # Schema: el Last_errno: 0 Killed: 0  20 # Query_time: 5.993656 Lock_time: 0.000078 Rows_sent: 1 Rows_examined: 8018014 Rows_affected: 0  21 # Bytes_sent: 1086 22 SET timestamp=1490682881; 23 SELECT `UserID`,`FileName`,`AdjunctGuid`,`LiteratureGuid`,`NoteGuid`,`AdjunctType`,`Md5`,`ID`,`ServerModifyTime`,`FileSize` FROM `el_user_adjunct_info` WHERE (`AdjunctGuid` = 'dbf1fc940ddd452d8d2af439438a cb07.caj');

 

 

其中，第19行是多出來的，mysqldumpslow為匹配和替換成空，因此逐行匹配時就匹配錯了行。 
於是修改腳本，添加對第19行的匹配和替換：

 

105     s/^#? Schema: \w+ Last_errno: \d+ Killed: \d+.*\n//; 106 107 s/^# Query_time: ([0-9.]+)\s+Lock_time: ([0-9.]+)\s+Rows_sent: ([0-9.]+).*\n//;

 

 

在匹配Query_time:行的表達式上邊，添加第105行匹配Schema行並替換成空。

 

然后再進行分析，終於正常了。 
問題原因：生成環境和我本地的MySQL版本不一致，其生成的日志格式有差異。

 

mysqldumpslow語法很簡單：

 

[root@dras-test local]# 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 l: lock time r: rows sent t: query time -r reverse the sort order (largest last instead of first) -t NUM just show the top n queries -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

 

 

示例：

 

mysqldumpslow -s r -t 10 /database/mysql/slow-log.txt 得到返回記錄集最多的10個查詢。 mysqldumpslow -s t -t 10 -g “left join” /database/mysql/slow-log.txt 得到按照時間排序的前10條里面含有左連接的查詢語句。 mysqldumpslow -a -s t -t 2 /opt/slow_query_log.txt -a 參數，說明不合並類似的SQL語句，顯示具體的SQL語句中的數字和字符串。

 

 

正確的結果如下：

 

[root@dras-test local]# mysqldumpslow -a -s t -t 2 /opt/slow_query_log.txt 

Reading mysql slow query log from /opt/slow_query_log.txt
Count: 60  Time=903.45s (54206s)  Lock=0.00s (0s) Rows=13271072.8 (796264367), LibSvr[LibSvr]@2hosts SELECT * FROM `el_user_litera_info` Count: 60 Time=335.23s (20113s) Lock=0.00s (0s) Rows=17128739.1 (1027724344), LibSvr[LibSvr]@2hosts SELECT * FROM `el_user_category_litera` [root@dras-test local]# mysqldumpslow -a -s t -t 5 /opt/slow_query_log.txt Reading mysql slow query log from /opt/slow_query_log.txt Count: 60 Time=903.45s (54206s) Lock=0.00s (0s) Rows=13271072.8 (796264367), LibSvr[LibSvr]@2hosts SELECT * FROM `el_user_litera_info` Count: 60 Time=335.23s (20113s) Lock=0.00s (0s) Rows=17128739.1 (1027724344), LibSvr[LibSvr]@2hosts SELECT * FROM `el_user_category_litera` Count: 60 Time=277.45s (16646s) Lock=0.00s (0s) Rows=13271097.1 (796265825), LibSvr[LibSvr]@2hosts SELECT * FROM `el_user_litera_reader_info` Count: 60 Time=153.27s (9196s) Lock=0.00s (0s) Rows=8943019.9 (536581195), LibSvr[LibSvr]@2hosts SELECT * FROM `el_user_adjunct_info` Count: 60 Time=91.95s (5516s) Lock=0.00s (0s) Rows=2036609.1 (122196547), LibSvr[LibSvr]@2hosts SELECT * FROM `el_user_note_content`