mysqldumpslow使用概要
缘起:実际の生产环境の中でMySQLはクエリの遅い问题が现れて、遅いクエリを分析するため、遅いクエリのログを开いて、そしてログに対して分析を行います.生成環境で誤操作が発生しないように,記録されたスロークエリーログcopyを戻し,自分のパソコンで分析する.解析結果:
問題が発生し、よく見た学生はすでに手がかりを見て、Time、Lock、Rowsの統計データはすべて0です.
mysqldumpslowはperlスクリプトで、正規表現を使用してlogファイルを行単位でマッチングし、マッチングが完了した後にマッチングした値を抽出し、動作全体を置き換えます.
単独でテストした結果、この式は問題なく、正しく一致します.しかしmysqldumpslowではマッチングに成功せず、検索、比較を経て、本番環境からcopyが下りてきたログフォーマットとmysqldumpslowで解析するフォーマットが一致せず、ログに1行増えていることが分かった.
このうち19行目は多く、mysqldumpslowは一致と置換が空であるため、行ごとに一致すると行が間違っている.スクリプトを変更し、19行目の一致と置換を追加します.
一致するQuery_time:行の式の上に、105行目がSchema行に一致するように追加し、空に置き換えます.
それから分析して、やっと正常になりました.問題の原因:生成環境は私のローカルのMySQLバージョンと一致しなくて、その生成するログのフォーマットは違います.
mysqldumpslow構文は簡単です.
例:
4、スロークエリーログのフォーマット
[sql] view plain
copy
構造化されたスロー・クエリー・ログは、スロー・クエリー・ログの重要な情報を読みやすく、特定のソート方法でSQLを抽出することです.この方法は、oracleのtraceファイルをフォーマットするためにOracleにtkprofがあるのと似ています.
前の遅いクエリー・ログではmysqldumpslowを使用して、を抽出しました.
suse11b:~ # mysqldumpslow -s at,al /var/lib/mysql/suse11b-slow.log Reading mysql slow query log from /var/lib/mysql/suse11b-slow.log
Count: 4 Time=16.87s (67s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@localhost insert into tb_slow select * from tb_slow
Count: 1 Time=0.20s (0s) Lock=0.00s (0s) Rows=1.0 (1), root[root]@localhost
select count(*) from tb_slow
Count: 1 Time=1.57s (1s) Lock=0.00s (0s) Rows=83.0 (83), root[root]@localhost select table_schema,table_name,count(*) from tb_slow
group by table_schema,table_name order by N,N
#以下は、最大消費時間列の最後に2つだけ表示するようにログファイルをフォーマットする. suse11b:~ # mysqldumpslow -r -t 2 /var/lib/mysql/suse11b-slow.log
Reading mysql slow query log from /var/lib/mysql/suse11b-slow.log Count: 1 Time=1.57s (1s) Lock=0.00s (0s) Rows=83.0 (83), root[root]@localhost
select table_schema,table_name,count(*) from tb_slow group by table_schema,table_name order by N,N
Count: 4 Time=16.87s (67s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@localhost
insert into tb_slow select * from tb_slow
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:もう1つ実行すると
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;
この2つの文の条件は違いますが、
1:1つはserver_id=10、1つは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文と2種類あることがわかります
mysqldumpslowの分析結果
Countはこのタイプの文を何回実行したか教えてくれます
Timeは、このタイプの文が実行される最大時間を教えてくれます.
Time=2.79 s(5 s)中(5 s)とは、このタイプの文の実行にかかる合計時間のことです
例:
Count: 2 Time=2.79s (5s) Lock=0.00s (0s) Rows=1.0 (2), vgos_dba[vgos_dba]@[10.130.229.196]
2回実行したと教えてくれました
最大時間は2.79 sです
全部で5 sかかります
ロック時間0 s
1回に返された結果の数は1レコードです
2回合計2レコードを返します
mysqldumpslow -s t -t 10 slow.log
クエリの結果は、実行時間が最も遅いsql文10個で、-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.79 s(5 s)Lock=0.00 s(0 s)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]
2.79 sと2.91 sではなく(5 s)と(2 s)を比較するため、前に並んでいます.
-s at比較も(5 s)/count:2と(2 s)/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)/Clount:2,
このときCountが3である場合、rowの算出方式はRows=2/3、Rows=0.67となる
主な機能は,異なるスローsqlの出現回数(Count),実行最長時間(Time),累積総消費時間(Time),ロック待ち時間(Lock),クライアントに送信されるロー総数(Rows),スキャンされるロー総数(Rows)である.
正しい結果は次のとおりです.
[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.]+).*
//;単独でテストした結果、この式は問題なく、正しく一致します.しかしmysqldumpslowではマッチングに成功せず、検索、比較を経て、本番環境からcopyが下りてきたログフォーマットとmysqldumpslowで解析するフォーマットが一致せず、ログに1行増えていることが分かった.
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+.*
//;
106
107 s/^# Query_time: ([0-9.]+)\s+Lock_time: ([0-9.]+)\s+Rows_sent: ([0-9.]+).*
//;一致する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 。4、スロークエリーログのフォーマット
[sql] view plain
copy
構造化されたスロー・クエリー・ログは、スロー・クエリー・ログの重要な情報を読みやすく、特定のソート方法でSQLを抽出することです.
前の遅いクエリー・ログではmysqldumpslowを使用して、を抽出しました.
suse11b:~ # mysqldumpslow -s at,al /var/lib/mysql/suse11b-slow.log
Count: 4 Time=16.87s (67s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@localhost
select count(*) from tb_slow
Count: 1 Time=1.57s (1s) Lock=0.00s (0s) Rows=83.0 (83), root[root]@localhost
group by table_schema,table_name order by N,N
#以下は、最大消費時間列の最後に2つだけ表示するようにログファイルをフォーマットする.
Reading mysql slow query log from /var/lib/mysql/suse11b-slow.log
select table_schema,table_name,count(*) from tb_slow
insert into tb_slow select * from tb_slow
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:もう1つ実行すると
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;
この2つの文の条件は違いますが、
1:1つはserver_id=10、1つは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文と2種類あることがわかります
mysqldumpslowの分析結果
Countはこのタイプの文を何回実行したか教えてくれます
Timeは、このタイプの文が実行される最大時間を教えてくれます.
Time=2.79 s(5 s)中(5 s)とは、このタイプの文の実行にかかる合計時間のことです
例:
Count: 2 Time=2.79s (5s) Lock=0.00s (0s) Rows=1.0 (2), vgos_dba[vgos_dba]@[10.130.229.196]
2回実行したと教えてくれました
最大時間は2.79 sです
全部で5 sかかります
ロック時間0 s
1回に返された結果の数は1レコードです
2回合計2レコードを返します
mysqldumpslow -s t -t 10 slow.log
クエリの結果は、実行時間が最も遅いsql文10個で、-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.79 s(5 s)Lock=0.00 s(0 s)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]
2.79 sと2.91 sではなく(5 s)と(2 s)を比較するため、前に並んでいます.
-s at比較も(5 s)/count:2と(2 s)/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)/Clount:2,
このときCountが3である場合、rowの算出方式はRows=2/3、Rows=0.67となる
主な機能は,異なるスローsqlの出現回数(Count),実行最長時間(Time),累積総消費時間(Time),ロック待ち時間(Lock),クライアントに送信されるロー総数(Rows),スキャンされるロー総数(Rows)である.
正しい結果は次のとおりです.
[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