遅いクエリーの調査をしてみようとして、
そこで今回は、
デモンストレーション環境
今回使用する環境は第7回 スロークエリーログを使って遅いクエリーを収集するで使用した環境を使用しております。
そのままだとスロークエリーログが1件しか無いため、
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';
クエリーの実行後に、
$ 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件のスロークエリーログではありますが、
そこで次からは、
Percona Toolkitをインストールする
Percona Toolkitとは
Percona ToolkitとはMySQL互換のデータベース、
今回はそのうちの1つであるpt-query-digestについて取り上げますが、
Percona Toolkitをインストール方法はOS毎にさまざまなものがあるのですが、
また、
Mac OS X
Mac OS Xにインストールする場合は、
$ 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レポジトリを追加して、
$ 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を使用してスロークエリーログの統計情報を取得してみましょう。一番簡単な使い方は下のようになっていて、
$ pt-query-digest スロークエリーログを指定
実際にデモンストレーション環境で用意したスロークエリーログをpt-query-digestに入力して統計情報を出力してみましょう。出力は大きく2つの部分に分かれて出力されます。結果を一気に貼ってしまうと長すぎてよくわからなくなってしまうので、
1つ目のブロックですが、
スロークエリーログ全体の統計情報の出力結果から見ていきたいと思います。以下が実行結果です。
$ 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 total, 2 unique, 0 QPS, 0x concurrency
ここでいうユニークとは、
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 size | strlen(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_ | クエリーの実行時間のグラフ化 |
| Tables | 関連するテーブル情報の調査方法 |
これらの情報を使ってスロークエリーログの統計情報やスロークエリーログを発生させているクエリーを簡単に特定することができるようになりました。
まとめ
今回pt-query-digestを使ってスロークエリーログがたくさんある中で、
ここでは詳細な説明はしませんが、
年末のスロークエリーログの大掃除にぜひご活用ください。それでは良いお年を。