MySQLでのSlowLogの分析方法

概要

サービス開発/運用中に性能問題が発生した際に、DBのSlowLogを見るのは非常に有効なアプローチです。

SlowLogの出し方はRDBMS毎にやり方がありますが、特にMySQLでは単純に遅いQueryを出力するだけでなく、データが取得しやすいようにSlowLogをサマるためのツールが付属しています。

今回はそのツールmysqldumpslowの使い方を紹介します。

SlowLogから分かること

• SlowLogが出ていない場合、性能問題の原因がDBではない事。
• SlowLogが出ている場合、どのQueryが性能問題を引き起こしているのか。
• 出力されるQueryの閾値をゼロとして全Queryを出力させると、Query毎の登場頻度も確認可能。

mysqldumpslowの使い方

準備

この手順では以下の物が必要となります。

1. 分析対象のSlowLog

   • リードレプリカを作ってる場合、複数のDBサーバのSlowLogを以下のように結合して、1つのファイルにまとめてもOK。
     • cat file1.log >> file2.log
   • 同じログを何回も分析してもしょうがないので、事前に以下のようにして切り回しておくのがオススメです。
     • cat ${TARGET_FILE} > ${TARGET_FILE}.${DATE}; echo "" > ${TARGET_FILE}
     • 分析用には${TARGET_FILE}.${DATE}を利用します。

2. mysqldumpslowがインストールされている環境

   • Linux系でmysqlクライアントがインストールされていればだいたい入ってます。
     • mysqlサーバがインストールされてなくても大丈夫。

手順

以下のコマンドを実行するだけです！

$ mysqldumpslow -s t ${SlowLogファイル} > ${出力先ファイル}

結果は標準出力に出てしまうので、上記のようにファイルにリダイレクトしてください。

-sの部分は結果の表示順を制御しています。設定できる主な値は以下の通りです。

• at Queryの平均実行時間
• c Queryの出現回数
• ar Query内で取得/更新した合計レコード行数
• t Queryの合計実行時間

他にもgrepやhost名の指定など便利なオプションがあるので、使いたい人は--helpしてみてください。

出力の見方

mysqldumpslowの出力は以下のような形になります。
ここに記載しているのは1Query分なので、この出力がQueryの種類の数だけ表示されることになります。
(表示順は、前述のパラメータで指定します。)

mysqldumpslowの実行結果(Query1種類分)

Count: 100  Time=0.50s (48s)  Lock=0.00s (0s)  Rows=1.0 (100), user[user]@[192.168.1.2]
  SELECT
  *  
  FROM
  student
  WHERE
  name = 'S'
  AND
  weight > N

1行目がサマリ情報です。出力の意味は以下の通りです。

• Count: 出現回数。
• Time: 平均実行時間。カッコの中は、合計実行時間。
• Lock: がテーブルをロックした平均時間。カッコの中は合計ロック時間。
• Rows: 読取り/更新したレコード数の平均。カッコの中は合計。
• user[user]@[192.168.1.2] アクセス元。

2行目以降は、実際のQueryです。
文字列や数値のパラメータはすべて、NとSで抽象化されて合算されているのがポイントです。

使い方については以上です。

おまけ

SlowLogはサービスインした後は監視の対象とするなど、出ない事が前提となる事が多いと思います。

しかし、開発中は、あえてlong_query_time = 0として全QueryをSlowLogに出力させるようにしておくと、mysqldumpslowを使ってDBのボトルネックが明らかに出来るのでお勧めです(古いのはどんどん捨てないとディスクを圧迫するので、ご注意を…)。
後は、その結果を日次でメールかチケットで送るようにしておくと便利ですね。