スロークエリの記録とpt-query-digestを用いた解析

技術本部 サービスリライアビリティグループ(SRG)の鬼海(@fat47)です。
#SRG(Service Reliability Group)は、主に弊社メディアサービスのインフラ周りを横断的にサポートしており、既存サービスの改善や新規立ち上げ、OSS貢献などを行っているグループです。
本記事は、SRG 内にある DBWG(DBワーキンググループ)が全社内向けに提供しているデータベースに関する資料を公開します。
なにかの役に立てば幸いです。
 

スロークエリとは


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 では一緒に働く仲間を募集しています。 ご興味ありましたらぜひこちらからご連絡ください。
 
このエントリーをはてなブックマークに追加