Maatkit というMySQL 用のユーティリティプログラムがあります。詳しくは インフラ系エンジニア勉強会 "hbstudy"でMaatKitについて発表してきました - marqs blog とか maatkitを一通り使ってみたメモ - ククラフト とかをどうぞ。
mk-query-profiler という、 SQL のプロファイリングをするやつを少し使ってみたのでメモ。そもそもプロファイリングって何よ？というと、たぶん 漢(オトコ)のコンピュータ道: プロファイリングで快適MySQLチューニング生活 みたいな話です。 SET profiling=1; が使える環境ならばそっちを使ったほうが良いのかも。
以下、実行例。諸事情により一部伏せてます。 -vv は verbose の意で、これつけないと I/O Operations と InnoDB Data Operations が表示されない。 slow.sql にはプロファイリングしたい SQL が書いてある。複数の SQL を空行をはさんで書いておくと全部実行してまとめてプロファイリングしてくれます。
今回対象にしてるクエリは、初回だけ猛烈に遅いことがあって二度目からはさくさく、 EXPLAIN してインデックスを調整してみたけど効果出ず、 iostat を眺めてるとクエリ発行のタイミングで I/O が跳ね上がる、という感じで、ほぼ I/O がボトルネックで間違いなさそうなんだけどもう少し裏付けが欲しかったのでプロファイリングしてみた、という経緯です。
[kyanny@xxxx ~]$ mk-query-profiler -D xxxx -u xxxx -vv slow.sql
+----------------------------------------------------------+
| 1 (84.6154 sec) |
+----------------------------------------------------------+
__ Overall stats _______________________ Value _____________
Total elapsed time 84.615
Questions 5594
COMMIT 0
DELETE 0
DELETE MULTI 0
INSERT 0
INSERT SELECT 0
REPLACE 0
REPLACE SELECT 0
SELECT 1
UPDATE 0
UPDATE MULTI 0
Data into server 208
Data out of server 39153
Optimizer cost 16890.209
__ Table and index accesses ____________ Value _____________
Table locks acquired 4836
Table scans 0
Join 0
Index range scans 1
Join without check 0
Join with check 0
Rows sorted 0
Range sorts 0
Merge passes 0
Table scans 0
Potential filesorts 0
__ Row operations ____________________ Handler ______ InnoDB
Reads 87904 794908
Fixed pos (might be sort) 0
Next row (table scan) 0
Bookmark lookup 4
First in index (full scan?) 0
Next in index 0
Prev in index 87900
Writes
Delete 0 0
Update 0 212
Insert 0 156
Commit 0
InnoDB row locks
Number of locks waited for 0
Total ms spent acquiring locks 0
__ I/O Operations _____________________ Memory ________ Disk
Key cache
Key reads 0 0
Key writes 0 0
Temp tables 0 0
Temp files 0
InnoDB buffer pool
Reads 888017 9044
Random read-aheads 132
Sequential read-aheads 10
Write requests 3843 121
Reads/creates blocked by flushes 0
InnoDB log operations
Log writes 1756 72
Log writes blocked by flushes 0
__ InnoDB Data Operations ____ Pages _____ Ops _______ Bytes
Reads 12868 11082 210829312
Writes 121 153 4717568
Doublewrites 121 8
Creates 22
Fsyncs 96
OS fsyncs 80 748544
[kyanny@xxxx ~]$ mk-query-profiler -D xxxx -u xxxx -vv slow.sql
+----------------------------------------------------------+
| 1 (0.5920 sec) |
+----------------------------------------------------------+
__ Overall stats _______________________ Value _____________
Total elapsed time 0.592
Questions 23
COMMIT 0
DELETE 0
DELETE MULTI 0
INSERT 0
INSERT SELECT 0
REPLACE 0
REPLACE SELECT 0
SELECT 1
UPDATE 0
UPDATE MULTI 0
Data into server 208
Data out of server 39153
Optimizer cost 16890.209
__ Table and index accesses ____________ Value _____________
Table locks acquired 18
Table scans 0
Join 0
Index range scans 1
Join without check 0
Join with check 0
Rows sorted 0
Range sorts 0
Merge passes 0
Table scans 0
Potential filesorts 0
__ Row operations ____________________ Handler ______ InnoDB
Reads 87904 87922
Fixed pos (might be sort) 0
Next row (table scan) 0
Bookmark lookup 4
First in index (full scan?) 0
Next in index 0
Prev in index 87900
Writes
Delete 0 0
Update 0 2
Insert 0 1
Commit 0
InnoDB row locks
Number of locks waited for 0
Total ms spent acquiring locks 0
__ I/O Operations _____________________ Memory ________ Disk
Key cache
Key reads 0 0
Key writes 0 0
Temp tables 0 0
Temp files 0
InnoDB buffer pool
Reads 296072 0
Random read-aheads 0
Sequential read-aheads 0
Write requests 33 0
Reads/creates blocked by flushes 0
InnoDB log operations
Log writes 15 4294967294
Log writes blocked by flushes 0
__ InnoDB Data Operations ____ Pages _____ Ops _______ Bytes
Reads 0 0 0
Writes 0 ######### 4294957055
Doublewrites 0 0
Creates 0
Fsyncs 1
OS fsyncs ######### 4294957055いまいち読み方に自信がないけど、 I/O Operations -> InnoDB buffer pool -> Reads -> Disk の項が 0 じゃないのでディスクから読んでる -> 遅い、と言えそう (でも数字の単位がわからない) 二回目は Disk からの Reads は 0 なので全部メモリに載っててメモリから読んでるので速い。 InnoDB Data Operations -> Reads の Ops が何なのかもわからない。それ以外にも Overall stats -> Optimizer cost とかも見られる。
オプションもいろいろあって、まだほとんど試してない。 --external オプションがわからなくて、指定したファイルなり STDIN なりを一行ずつ読んでシェルのコマンドとして実行する、とか書いてあるんだけど、具体的にどういうコマンドをそのファイルに書いておいたらいいのかがわからない。誰か教えてください。
まだ mk-query-digest をはじめ他のツールはほとんど使ってないので、これからいろいろ試していきたい。また何か覚えたらブログにでも書きます。
