スロークエリの記録とpt-query-digestを用いた解析
技術本部 サービスリライアビリティグループ（SRG）の鬼海（@fat47）です。
#SRG（Service Reliability Group）は、主に弊社メディアサービスのインフラ周りを横断的にサポートしており、既存サービスの改善や新規立ち上げ、OSS貢献などを行っているグループです。
なにかの役に立てば幸いです。
スロークエリとはスロークエリログの推奨設定ログの出力有効化logrotateでローテート設定スロークエリログの解析方法スロークエリの統計をとろうpt-query-digestのオプションを活用して調査EXPLAINでクエリを解析する終わりに
スロークエリとは
MySQLの設定で指定されたlong_query_timeの値を超えたものがログに記録されます。
一般的に遅いクエリはインデックスが適切に設定されていなかったり、大量の行数を呼ぶような
高コストなクエリなことが多いため、データベースに負荷を与えるクエリとなっています。
スロークエリログの推奨設定
このドキュメントはオンプレやEC2などでMySQLをそのまま運用している場合の設定手順です。
ログの出力有効化
my.cnfに設定
またはMySQLにログインしてから下記を実行します
logrotateでローテート設定
このままの設定ではスロークエリは同一mysql-slow.logのファイルに書き続けられてしまいます。
解析しづらくなるので日付ごとでローテートするようにします。
テストの実行
設定が完了すると下記のようにログが蓄積されていきます
スロークエリログの解析方法
記録されたスロークエリログ中身を確認してみてるとこのような形で閾値を超えたクエリが記録されます。
実際のログではこれらが数百件も数千件も出ていたりするので、とてもすべてを確認していくことはできません。
スロークエリの統計をとろう
Percona Toolkitに含まれるpt-query-digestを使ってスローログの統計をとってみましょう。
CentOS7でのインストール例
オプションをつけずに実行してみます
出力を確認してみましょう
上の方ではログの統計情報としてExec TimeやLock Timeなどの結果がまとめられています。
次のセクションではレスポンスタイムの遅くてコール数が多いものをランキング形式にして出力しています。
- Response time はそのクエリ実行時間の合計とスローログ全体のうちそのクエリが占めるパーセンテージが表示されています
- Calls はクエリーの実行された回数
- R/Call はRespons Time / Callで実行ごとの平均応答時間
- V/M は応答時間の分散対平均比（？）
- Item はクエリのサマリが表示されています
次のセクションは各クエリー単位での集計情報が記録されています。
- Query_time distribution クエリ実行時間の平均のグラフが表示されています
- Tables このクエリで関係しているテーブル情報を確認できるクエリです
- EXPLAIN 実際にEXPLAINで確認できるクエリのサンプルを表示しています
このログの例ではQuery1は応答時間のほとんどは100ms～10秒以内で返している激遅クエリだということがわかります
pt-query-digestのオプションを活用して調査
先ほどのようにデフォルト設定でも解析ができますが、
下記の用なオプションを活用するとより便利に解析ができます。
一部を抜粋して紹介します。
日付や時間の範囲指定してログを検索したい
クエリの合計実行時間順にソートしたい
読み取り行数多い順にソートしたい
スロークエリが多いテーブル順に表示したい
EXPLAINでクエリを解析する
スロークエリログの解析をして改善できそうなクエリにあたりがついたら、
いよいよクエリー自体を解析していきます。
こちらについては別途記事を作成予定となるのでしばらくお待ち下さい。
終わりに
SRG では一緒に働く仲間を募集しています。
ご興味ありましたらぜひこちらからご連絡ください。
