遅いクエリーの調査をしてみようとして、実運用環境でスロークエリーログを出力してみたところ、思っていたよりもたくさん出力されていしまい、もはや何が起こっているのかわからなくなってしまうことはありませんか? スロークエリーログにいくら有益な情報が入っているとはいえ、数が多くなってしまうと一個一個確認していくのには気が遠くなるような時間と根気が必要となってしまいます。せっかくのIT技術を使っているのに人手による努力はなるべく避けたいものです。ということで大変なスロークエリーログの集計はPCやサーバにやってもらうことにしましょう。
そこで今回は、PERCONA社が公開しているPercona Toolkitのうちの、MySQLのクエリーから統計を取って教えてくれるpt-query-digestというコマンドツールについて説明をしていきます。
デモンストレーション環境
今回使用する環境は第7回 スロークエリーログを使って遅いクエリーを収集するで使用した環境を使用しております。
そのままだとスロークエリーログが1件しか無いため、前回出力したスロークエリーログを一旦削除して、以下のクエリーを実行して3件のスロークエリーログを追加してあります。
クエリーの実行後に、設定ファイルに記載した場所にあるスロークエリーログを確認して見ましょう。スロークエリーログを表示させた時に、以下のように3件のクエリーが表示されていれば問題ありません。
このように3件のスロークエリーログではありますが、ログとしてかなりの量が出力さていることがわかると思います。特に実運用環境でスロークエリーログを出力した場合には、1時間に1000件以上表示されてしまうこともあります。そのためスロークエリーログを直接見て、どの遅いクエリーがたくさん呼ばれているかを判断することは難しくなります。
そこで次からは、このスロークエリーログやtcpdumpなどから統計情報が取得することができるpt-query-digestが含まれているPercona Toolkitをインストールして行きます。
Percona Toolkitをインストールする
Percona Toolkitとは
Percona ToolkitとはMySQL互換のデータベース、Percona Serverを開発しているPercona社が公開しているMySQLやその他の互換DBの運用管理を便利にしてくれるコマンドラインツール群です。
今回はそのうちの1つであるpt-query-digestについて取り上げますが、その他にもたくさんの便利なコマンドラインツールが用意されてます。他にどのようなツールがあるか気になる方は公式のPercona Toolkit Documentationを読んでみると良いと思います。
Percona Toolkitをインストール方法はOS毎にさまざまなものがあるのですが、ここでは代表的なものを上げておきます。現在Windows上でPercona Toolkitを動かす方法が無いため、Windowsをご利用の方は仮想環境やサーバを用意して、その上で試してみてください。
また、pt-query-digestを使う時の注意点としては統計を取る対象の件数が増えてくると、計算に時間がかかってしまったり、CPUを100%使いきってしまうことがあります。ぜひCPUを使いきっても問題にならないように、実運用環境以外のサーバやクライアントで実行するようにしましょう。
Mac OS X
Mac OS Xにインストールする場合は、Homebrewを使用している場合は以下のコマンドで簡単にインストールすることができます。
上記のように表示され、インストールが完了します。
Linux(CentOS)
公式に書かれている説明されているインストールガイドに従ってyumレポジトリを追加して、Percona Toolkitをインストールします。
上記のように表示され、インストールは完了します。
スロークエリーログの統計情報を取得してみる
それではpt-query-digestを使用してスロークエリーログの統計情報を取得してみましょう。一番簡単な使い方は下のようになっていて、1番遅かったクエリーから順に表示されます。
実際にデモンストレーション環境で用意したスロークエリーログをpt-query-digestに入力して統計情報を出力してみましょう。出力は大きく2つの部分に分かれて出力されます。結果を一気に貼ってしまうと長すぎてよくわからなくなってしまうので、2つに分けて説明していきたいと思います。
1つ目のブロックですが、スロークエリーログ全体の統計情報が出力されます。2つ目のブロック以降に関しては、各クエリーの統計情報が出力されます。
スロークエリーログ全体の統計情報の出力結果から見ていきたいと思います。以下が実行結果です。
簡単に眺めてみると、以下の部分からOverallからスロークエリーログが全部で3件発生していて、そのうち2件がユニークであることがここからわかります。
ここでいうユニークとは、SQLが完全一致した場合だけではなく、ノーマライズされた後の値も除外された値になるのでご注意ください。
またその下のAttributeからはテーブルのように表示されていることがわかります。スロークエリーログの合計、一番遅いものや平均などで、実行時間やロックされている時間などが一目でわかるようになっています。
各列の要素が表しているものは以下の表の内容になります。
Attribute | 意味 |
total | スロークエリーログの合計 |
min | スロークエリーログ内に記載されているもののうち最も時間がかからなかったクエリー |
max | スロークエリーログ内に記載されているもののうち最も時間がかかったクエリー |
avg | スロークエリーログの平均値 |
95% | スロークエリーログの速い順から95%にかかっている時間 |
stddev | 標準偏差 |
median | 中央値 |
各行の要素が表しているのは以下の表の内容になります。
Attribute | 意味 |
Exec time | クエリーの実行にかかった時間 |
Lock time | クエリーを実行した際のロック待ち時間 |
Row sent | 結果をクライアントに送信した回数 |
Rows examine | 実行されたクエリーがフェッチしたデータの行数 |
Query size | strlen(sql)の値 |
次に、各クエリーに関する詳細部分に関して見ていきたいと思います。クエリーに関してもクエリ自体の統計情報と、詳細なクエリーの部分に別れるのですが、ここでは統計情報はほぼスロークエリーログ全体の統計情報と同じため割愛させていただきます。
詳細部分に関しては以下のように表示がされます。また最終行が実行されたクエリーとなっていて、その他の部分はコメントアウトされているのでそのままコピペして実際に実行してクエリーを実行してみることもできます。
上の出力結果に関して簡単な説明を以下の表にまとめました。
それぞれの要素 | 意味 |
Databases | クエリーが実行されたときのカレントデータベース |
Hosts | クエリーを実行したホスト |
Time | 集計範囲の時刻 |
Users | クエリーを実行したユーザ |
Query_time distribution | クエリーの実行時間のグラフ化 |
Tables | 関連するテーブル情報の調査方法 |
これらの情報を使ってスロークエリーログの統計情報やスロークエリーログを発生させているクエリーを簡単に特定することができるようになりました。
まとめ
今回pt-query-digestを使ってスロークエリーログがたくさんある中で、最も遅かったクエリーを特定することができるようになりました。pt-query-digestを使ってみた時に、統計情報を1回だけ取っておしまいにしてしまうのは勿体無いです。運用として定期的に遅いクエリーが無いか、最近追加した機能によって遅いSQLが発生していないかなどのサービスに起こっている状態を監視する意味も含めて、定期的に動かして傾向を見ることをおすすめします。
ここでは詳細な説明はしませんが、出力された結果をメールやチャットツールなどに投稿しておくと、開発者や運用者がサービスのチューニングをしようと思った時やサービスの異常の検知が楽になります。
年末のスロークエリーログの大掃除にぜひご活用ください。それでは良いお年を。