刺身☆ブーメランのはてなダイアリー

Maatkit の mk-query-profiler を少し使ってみた

MySQL

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 をはじめ他のツールはほとんど使ってないので、これからいろいろ試していきたい。また何か覚えたらブログにでも書きます。

Permalink | コメント(0) | トラックバック(0) | 02:32