2009-04-14

MySQL 5.1のmysqldumpslowを使うとチューニングが楽になる！という話題です。
mysqldumpslowはもともとMySQLに付属しているツールで、スロークエリログを集計してくれるものです。これ自体はMySQL 5.1で特に変わったところはありませんが、スロークエリログ本体の方が機能強化されているため、組み合わせるとなかなか便利になっています。MySQL 5.1におけるスロークエリログの主な機能強化は以下の三点です。

long_query_timeに1秒未満の値を設定できるようになった。
出力先を設定できるようになった。
これらの設定をオンラインで変更できるようになった。

これでどうなるかというと、MySQLの性能分析をしたいと思ったときに、サーバを止めずにその場で

mysql> set global slow_query_log = 1;
mysql> set global slow_query_log_file = '/tmp/test.log';
mysql> set global long_query_time = 0;

と打てることになります。スロークエリログの出力先を変更するとともに、long_query_timeを0にすることですべてのクエリを出力対象にしてしまいます。
その後サーバが過負荷になったりログでディスクが溢れたりしないかを注意深く監視しつつ、数十秒〜数分待ってから設定を元に戻します。

mysql> set global slow_query_log = 1;
mysql> set global slow_query_log_file = '/var/lib/mysql/testsrv-slow.log';
mysql> set global long_query_time = 10;

書き出されたスロークエリログをmysqldumpslowにかけます。

$ mysqldumpslow -s t /tmp/test.log

すると以下のようなレポートが出力されます。負荷ツールにはDBT-1をカスタマイズしたものを用いています。

Count: 769  Time=0.02s (16s)  Lock=0.00s (0s)  Rows=5.0 (3827), dbt[dbt]@localhost
  SELECT STRAIGHT_JOIN i_id, i_title, a_fname, a_lname FROM item, author WHERE
  i_title LIKE 'S' AND i_a_id = a_id ORDER BY i_title ASC LIMIT N

Count: 1271  Time=0.01s (8s)  Lock=0.00s (0s)  Rows=50.0 (63550), dbt[dbt]@localhost
  SELECT i_id, i_title, a_fname, a_lname   FROM item, author   WHERE i_subject = 'S'
  AND i_a_id = a_id   ORDER BY i_pub_date DESC, i_title ASC LIMIT N

Count: 49040  Time=0.00s (5s)  Lock=0.00s (0s)  Rows=1.8 (86230), dbt[dbt]@localhost
  #

Count: 710  Time=0.01s (4s)  Lock=0.00s (0s)  Rows=44.4 (31500), dbt[dbt]@localhost
  SELECT i_id, i_title, a_fname, a_lname FROM item, author WHERE i_subject = 'S' AND
  i_a_id = a_id ORDER BY i_title ASC LIMIT N

Count: 6916  Time=0.00s (3s)  Lock=0.00s (0s)  Rows=5.0 (34520), dbt[dbt]@localhost
  SELECT i_id,i_thumbnail FROM item WHERE i_id = (SELECT i_related1 FROM item WHERE
  i_id = N) OR i_id = (SELECT i_related2 FROM item WHERE i_id = N) OR i_id = (SELECT
  i_related3 FROM item WHERE i_id = N) OR i_id = (SELECT i_related4 FROM item WHERE
  i_id = N) OR i_id = (SELECT i_related5 FROM item WHERE i_id = N)

いかがでしょうか。サーバで実行されたすべてのSQLが種類別に集計され、合計時間の悪いものから順番にレポートされています。あとはこれを上から順に直していけば良いというわけです。
特に、MySQL 5.1では1回の実行には0.01秒しかかからないが、毎分1万回実行されるので実は負荷の大半を占めている、といったSQLを簡単に特定できるようになったところがポイントです。MySQL 5.0まではこのようなSQLを調べる手段がありませんでした。
また、Oracle経験者の中には上のレポートを見てピンときた方もいらっしゃると思います。そうです、これはSTATSPACKレポートのSQL ordered by Elapsedセクションにそっくりなのです。

SQL ordered by Elapsed time for DB: ORA111  Instance: ORA111  Snaps: 46 -47
-> Total DB Time (s):              50
-> Captured SQL accounts for   66.4% of Total DB Time
-> SQL reported below exceeded  1.0% of Total DB Time

  Elapsed                Elap per            CPU                        Old
  Time (s)   Executions  Exec (s)  %Total   Time (s)  Physical Reads Hash Value
---------- ------------ ---------- ------ ---------- --------------- ----------
     17.47          352       0.05   35.1      17.49               0  797834135
Module: dbdriver_o@sandbox03 (TNS V1-V3)
SELECT i_id, i_title, a_fname, a_lname FROM ( SELECT i_id, i_tit
le, a_fname, a_lname FROM item, author WHERE i_title LIKE :"SYS_
B_0" AND i_a_id = a_id ORDER BY i_title ASC) WHERE ROWNUM <= :"S
YS_B_1"

      4.08          627       0.01    8.2       4.23               0 4063139509
Module: dbdriver_o@sandbox03 (TNS V1-V3)
SELECT i_id, i_title, a_fname, a_lname FROM ( SELECT i_id, i_tit
le, a_fname, a_lname FROM item, author WHERE i_subject = :"SYS_B
_0" AND i_a_id = a_id ORDER BY i_pub_date DESC, i_title ASC ) WH
ERE ROWNUM <= :"SYS_B_1"

      3.77          354       0.01    7.6       3.44               0 4242795701
Module: dbdriver_o@sandbox03 (TNS V1-V3)
SELECT i_id, i_title, a_fname, a_lname FROM ( SELECT i_id, i_tit
le, a_fname, a_lname FROM item, author WHERE i_a_id=a_id AND a_l
name LIKE :"SYS_B_0" ORDER BY i_title ASC ) WHERE ROWNUM <= :"SY
S_B_1"

これもSQLを種類別に集計して、合計時間の悪いものから順番にレポートしてくれるものです。STATSPACKはOracle 8iからの機能なのでかれこれ10年前からあるわけですが、このような仕事の生産性を上げるための機能について、MySQLもようやく商用のメジャーなRDBMS製品に追いついてきたのかもしれません。
と、ここまで持ち上げてきましたが、いくつか注意点があります。一つは全クエリをロギングするので当然サーバの負荷が上がってしまうということ。基本的には開発・試験環境で使うテクニックだと思います。もう一つはset global文の影響範囲です。set global文によって変更されたパラメータは、設定後に新規接続してきたセッションに対してのみ有効です。そのためTomcatなどコネクションプーリングを用いた構成では設定が即時反映されません。コネクションプーリングを用いている場合は、スロークエリログの設定後にアプリケーションサーバを再起動してください。
set global文の融通が利かない点はBug#38704でGoogleのMark Callaghan氏が報告しています。しかし「Not a Bug」ということで改善の予定はなさそうです。惜しいですね。

SH2の日記

MySQL 5.1のmysqldumpslowで快速チューニング