MySQL道普請便り

第9回pt-query-digestを使って遅いクエリーを発見する

遅いクエリーの調査をしてみようとして、実運用環境でスロークエリーログを出力してみたところ、思っていたよりもたくさん出力されていしまい、もはや何が起こっているのかわからなくなってしまうことはありませんか? スロークエリーログにいくら有益な情報が入っているとはいえ、数が多くなってしまうと一個一個確認していくのには気が遠くなるような時間と根気が必要となってしまいます。せっかくのIT技術を使っているのに人手による努力はなるべく避けたいものです。ということで大変なスロークエリーログの集計はPCやサーバにやってもらうことにしましょう。

そこで今回は、PERCONA社が公開しているPercona Toolkitのうちの、MySQLのクエリーから統計を取って教えてくれるpt-query-digestというコマンドツールについて説明をしていきます。

デモンストレーション環境

今回使用する環境は第7回 スロークエリーログを使って遅いクエリーを収集するで使用した環境を使用しております。

そのままだとスロークエリーログが1件しか無いため、前回出力したスロークエリーログを一旦削除して、以下のクエリーを実行して3件のスロークエリーログを追加してあります。

mysql> use zipcode
mysql> SELECT COUNT(*) FROM zipcode WHERE city='渋谷区' AND prefecture='東京都';
mysql> SELECT COUNT(*) FROM zipcode WHERE old_zipcode = '150';
mysql> SELECT COUNT(*) FROM zipcode WHERE old_zipcode = '150';

クエリーの実行後に、設定ファイルに記載した場所にあるスロークエリーログを確認して見ましょう。スロークエリーログを表示させた時に、以下のように3件のクエリーが表示されていれば問題ありません。

$ cat slow_query.log
/usr/local/Cellar/mysql/5.7.9/bin/mysqld, Version: 5.7.9-log (Homebrew). started with:
Tcp port: 0  Unix socket: (null)
Time                 Id Command    Argument
# Time: 2015-12-13T23:35:01.773062Z
# User@Host: root[root] @ localhost []  Id:     2
# Query_time: 0.060026  Lock_time: 0.000231 Rows_sent: 1  Rows_examined: 123864
use zipcode;
SET timestamp=1450049701;
SELECT COUNT(*) FROM zipcode WHERE city='渋谷区' AND prefecture='東京都';
# Time: 2015-12-13T23:35:07.206790Z
# User@Host: root[root] @ localhost []  Id:     2
# Query_time: 0.044150  Lock_time: 0.000093 Rows_sent: 1  Rows_examined: 123864
SET timestamp=1450049707;
SELECT COUNT(*) FROM zipcode WHERE old_zipcode = '150';
# Time: 2015-12-13T23:35:13.042779Z
# User@Host: root[root] @ localhost []  Id:     2
# Query_time: 0.051086  Lock_time: 0.000093 Rows_sent: 1  Rows_examined: 123864
SET timestamp=1450049713;
SELECT COUNT(*) FROM zipcode WHERE old_zipcode = '150';

このように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を使用している場合は以下のコマンドで簡単にインストールすることができます。

$ brew install percona-toolkit
==> Downloading https://homebrew.bintray.com/bottles/percona-toolkit-2.2.14.yosemite.bottle.2.tar.gz
######################################################################## 100.0%
==> Pouring percona-toolkit-2.2.14.yosemite.bottle.2.tar.gz
🍺  /usr/local/Cellar/percona-toolkit/2.2.14: 127 files, 7.0M

上記のように表示され、インストールが完了します。

Linux(CentOS)

公式に書かれている説明されているインストールガイドに従ってyumレポジトリを追加して、Percona Toolkitをインストールします。

$ yum install -y http://www.percona.com/downloads/percona-release/redhat/0.1-3/percona-release-0.1-3.noarch.rpm 
$ yum install -y percona-toolkit

Installed:
  percona-toolkit.noarch 0:2.2.16-1                                                                                                                          

Dependency Installed:
  perl-DBD-MySQL.x86_64 0:4.013-3.el6   perl-IO-Socket-SSL.noarch 0:1.31-2.el6      perl-Net-LibIDN.x86_64 0:0.12-3.el6 perl-Net-SSLeay.x86_64 0:1.35-9.el6
  perl-TermReadKey.x86_64 0:2.30-13.el6 perl-Time-HiRes.x86_64 4:1.9721-141.el6_7.1

Complete!

上記のように表示され、インストールは完了します。

スロークエリーログの統計情報を取得してみる

それではpt-query-digestを使用してスロークエリーログの統計情報を取得してみましょう。一番簡単な使い方は下のようになっていて、1番遅かったクエリーから順に表示されます。

$ pt-query-digest スロークエリーログを指定

実際にデモンストレーション環境で用意したスロークエリーログをpt-query-digestに入力して統計情報を出力してみましょう。出力は大きく2つの部分に分かれて出力されます。結果を一気に貼ってしまうと長すぎてよくわからなくなってしまうので、2つに分けて説明していきたいと思います。

1つ目のブロックですが、スロークエリーログ全体の統計情報が出力されます。2つ目のブロック以降に関しては、各クエリーの統計情報が出力されます。

スロークエリーログ全体の統計情報の出力結果から見ていきたいと思います。以下が実行結果です。

$ pt-query-digest slow_query.log

# 240ms user time, 110ms system time, 30.11M rss, 2.37G vsz
# Current date: Tue Dec 15 09:23:48 2015
# Hostname: kk2170.local
# Files: slow_query.log
# Overall: 3 total, 2 unique, 0 QPS, 0x concurrency ______________________
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time          155ms    44ms    60ms    52ms    59ms     6ms    51ms
# Lock time          417us    93us   231us   139us   224us    64us    89us
# Rows sent              3       1       1       1       1       0       1
# Rows examine     362.88k 120.96k 120.96k 120.96k 120.96k       0 120.96k
# Query size           187      54      78   62.33   76.28   11.06   54.21

# Profile
# Rank Query ID           Response time Calls R/Call V/M   Item
# ==== ================== ============= ===== ====== ===== ==============
#    1 0xEDFEDB113DDF641D  0.0952 61.3%     2 0.0476  0.00 SELECT zipcode
#    2 0xB3E8CD045E2D1B43  0.0600 38.7%     1 0.0600  0.00 SELECT zipcode

簡単に眺めてみると、以下の部分からOverallからスロークエリーログが全部で3件発生していて、そのうち2件がユニークであることがここからわかります。

# Overall: 3 total, 2 unique, 0 QPS, 0x concurrency

ここでいうユニークとは、SQLが完全一致した場合だけではなく、ノーマライズされた後の値も除外された値になるのでご注意ください。

mysql> SELECT COUNT(*) FROM zipcode WHERE old_zipcode = '150';
mysql> SELECT COUNT(*) FROM zipcode WHERE old_zipcode = '200';
# これらはノーマライズを行うと下記のように表現されるため、ユニークの時は1件として扱われます。
mysql> SELECT COUNT(*) FROM zipcode WHERE old_zipcode = N;

またその下のAttributeからはテーブルのように表示されていることがわかります。スロークエリーログの合計、一番遅いものや平均などで、実行時間やロックされている時間などが一目でわかるようになっています。

# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time          155ms    44ms    60ms    52ms    59ms     6ms    51ms
# Lock time          417us    93us   231us   139us   224us    64us    89us
# Rows sent              3       1       1       1       1       0       1
# Rows examine     362.88k 120.96k 120.96k 120.96k 120.96k       0 120.96k
# Query size           187      54      78   62.33   76.28   11.06   54.21

各列の要素が表しているものは以下の表の内容になります。

Attribute意味
totalスロークエリーログの合計
minスロークエリーログ内に記載されているもののうち最も時間がかからなかったクエリー
maxスロークエリーログ内に記載されているもののうち最も時間がかかったクエリー
avgスロークエリーログの平均値
95%スロークエリーログの速い順から95%にかかっている時間
stddev標準偏差
median中央値

各行の要素が表しているのは以下の表の内容になります。

Attribute意味
Exec timeクエリーの実行にかかった時間
Lock timeクエリーを実行した際のロック待ち時間
Row sent結果をクライアントに送信した回数
Rows examine実行されたクエリーがフェッチしたデータの行数
Query sizestrlen(sql)の値

次に、各クエリーに関する詳細部分に関して見ていきたいと思います。クエリーに関してもクエリ自体の統計情報と、詳細なクエリーの部分に別れるのですが、ここでは統計情報はほぼスロークエリーログ全体の統計情報と同じため割愛させていただきます。

詳細部分に関しては以下のように表示がされます。また最終行が実行されたクエリーとなっていて、その他の部分はコメントアウトされているのでそのままコピペして実際に実行してクエリーを実行してみることもできます。

# String:
# Databases    zipcode
# Hosts        localhost
# Time         2015-12-13... (1/50%), 2015-12-13... (1/50%)
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms  ################################################################
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `zipcode` LIKE 'zipcode'\G
#    SHOW CREATE TABLE `zipcode`.`zipcode`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT COUNT(*) FROM zipcode WHERE old_zipcode = '150'
\G

上の出力結果に関して簡単な説明を以下の表にまとめました。

それぞれの要素意味
Databasesクエリーが実行されたときのカレントデータベース
Hostsクエリーを実行したホスト
Time集計範囲の時刻
Usersクエリーを実行したユーザ
Query_time distributionクエリーの実行時間のグラフ化
Tables関連するテーブル情報の調査方法

これらの情報を使ってスロークエリーログの統計情報やスロークエリーログを発生させているクエリーを簡単に特定することができるようになりました。

まとめ

今回pt-query-digestを使ってスロークエリーログがたくさんある中で、最も遅かったクエリーを特定することができるようになりました。pt-query-digestを使ってみた時に、統計情報を1回だけ取っておしまいにしてしまうのは勿体無いです。運用として定期的に遅いクエリーが無いか、最近追加した機能によって遅いSQLが発生していないかなどのサービスに起こっている状態を監視する意味も含めて、定期的に動かして傾向を見ることをおすすめします。

ここでは詳細な説明はしませんが、出力された結果をメールやチャットツールなどに投稿しておくと、開発者や運用者がサービスのチューニングをしようと思った時やサービスの異常の検知が楽になります。

年末のスロークエリーログの大掃除にぜひご活用ください。それでは良いお年を。

おすすめ記事

記事・ニュース一覧