こんにちは。仁科(@nishina555)です。
前回、遅いクエリを突き止める!MySQLクエリ解析にスロークエリログを導入する手順でSQLのクエリ解析の手段としてスロークエリログをMySQLに導入する手順について説明をしました。スロークエリログを確認することで、ボトルネックとなっているクエリを確認することができます。
そんなスロークエリログですが、データをより分析しやすい形式で出力してくれるコマンドがあります。それが今回紹介するpt-query-digestと呼ばれるものです。
pt-query-digestはMySQLの利便性を高めるためのツールであるPercona Toolkit(ペルコナツールキット)に含まれる機能の1つです。
今回はpt-query-digestのインストール方法と、pt-query-digestを利用したスロークエリログの読み方について説明をします。
なお、今回は実行環境としてサーバーはConoHa、OSはUbuntu16.04.4、クエリのサンプルデータはISUCON7(予選)過去問環境をConoHaで構築する手順で構築したISUCON7の過去問を利用しております。
- Percona Toolkit(ペルコナツールキット)をインストールする
- pt-query-digestを利用できるようにする
- pt-query-digestを利用したスロークエリログの読み方を理解する
目次
結論: pt-query-digestを利用できるようにする手順
説明が少し長くなってしまうためインストールの方法だけ知りたいという方は以下を参考にしてください。
$ wget https://www.percona.com/downloads/percona-toolkit/3.0.10/binary/debian/xenial/x86_64/percona-toolkit_3.0.10-1.xenial_amd64.deb
$ sudo apt-get install libdbd-mysql-perl libdbi-perl libio-socket-ssl-perl libnet-ssleay-perl libterm-readkey-perl
$ sudo dpkg -i percona-toolkit_3.0.10-1.xenial_amd64.deb
もしくは
$ wget https://www.percona.com/downloads/percona-toolkit/3.0.10/binary/debian/xenial/x86_64/percona-toolkit_3.0.10-1.xenial_amd64.deb
$ sudo apt-get install gdebi
$ sudo gdebi percona-toolkit_3.0.10-1.xenial_amd64.deb
なお、wgetで利用するダウンロードリンクはこちらのページから取得します。インストール対象のサーバーのOS用のリンクを確認してください。
pt-query-digestを利用できるようにする
pt-query-digestはPercona(ペルコナ)社が開発しているPercona Toolkit(ペルコナツールキット)に含まれる機能の1つです。
そのため、pt-query-digestはPercona Toolkitをインストールすることで利用できるようになります。
Percona Toolkitのインストール方法は主にPerconaのapt-repo(CentOSはyum-repo)を利用してインストールする方法とダウンロードしたPercona Toolkitのdebファイルを利用してインストールする方法の2通りがあります。
今回は後者のPercona Toolkitのdebファイルを利用する方法でインストールを行います。
Percona Toolkitをダウンロードする
まずはダウンロードするファイルはOSとバージョンによって異なるため、バージョンの確認をします。
$ cat /etc/os-release
以下のような結果が出てきます。今回であれば16.04.4のバージョン用のファイルをダウンロードしてきます。
NAME="Ubuntu"
VERSION="16.04.4 LTS (Xenial Xerus)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 16.04.4 LTS"
VERSION_ID="16.04"
HOME_URL="http://www.ubuntu.com/"
SUPPORT_URL="http://help.ubuntu.com/"
BUG_REPORT_URL="http://bugs.launchpad.net/ubuntu/"
VERSION_CODENAME=xenial
UBUNTU_CODENAME=xenial
なお、CentOSの場合は以下のコマンドでOSのバージョンを確認することができます。
$ cat /etc/redhat-release
こちらのページからPercona Toolkitをダウンロードできるので、該当のOS用のダウンロードリンクを取得します。
次に先ほど取得したURLをもとにファイルをダウンロードします。
$ wget https://www.percona.com/downloads/percona-toolkit/3.0.10/binary/debian/xenial/x86_64/percona-toolkit_3.0.10-1.xenial_amd64.deb
deb形式のPercona Toolkitをインストールする
Percona Toolkitはdeb形式のファイルで配布されています。
debはDebian系のLinuxで利用されるパッケージのフォーマットで、dpkgコマンドでdebファイル形式のパッケージをインストールすることができます。
今回ですと以下のようにしてインストールを行います。
$ sudo dpkg -i percona-toolkit_3.0.10-1.xenial_amd64.deb
ただし、このままだと以下のようにエラーがでるはずです。
sudo dpkg -i percona-toolkit_3.0.10-1.xenial_amd64.deb
Selecting previously unselected package percona-toolkit.
(Reading database ... 168881 files and directories currently installed.)
Preparing to unpack percona-toolkit_3.0.10-1.xenial_amd64.deb ...
Unpacking percona-toolkit (3.0.10-1.xenial) ...
dpkg: dependency problems prevent configuration of percona-toolkit:
percona-toolkit depends on libdbi-perl (>= 1.13); however:
Package libdbi-perl is not installed.
percona-toolkit depends on libdbd-mysql-perl | libdbd-mysql-5.1-perl; however:
Package libdbd-mysql-perl is not installed.
Package libdbd-mysql-5.1-perl is not installed.
percona-toolkit depends on libterm-readkey-perl (>= 2.10); however:
Package libterm-readkey-perl is not installed.
percona-toolkit depends on libio-socket-ssl-perl; however:
Package libio-socket-ssl-perl is not installed.
dpkg: error processing package percona-toolkit (--install):
dependency problems - leaving unconfigured
Processing triggers for man-db (2.7.5-1) ...
Errors were encountered while processing:
percona-toolkit
そのため、percona-toolkitを利用するのに必要なパッケージが存在していないため、インストールエラーが発生してしまいました。
エラーを解決するためには以下のようにpercona-toolkitに必要なパッケージを先にインストールしてからpercona-toolkitをインストールします。
$ sudo apt-get install libdbd-mysql-perl libdbi-perl libio-socket-ssl-perl libnet-ssleay-perl libterm-readkey-perl
$ sudo dpkg -i percona-toolkit_3.0.10-1.xenial_amd64.deb
もしくは、debファイルをインストールする際にパッケージの依存関係を自動で解決してくれるgdebiという便利なコマンドがあるので、それを利用する方法もあります。
$ sudo apt install gdebi
$ sudo gdebi percona-toolkit_3.0.10-1.xenial_amd64.deb
pt-query-digestを利用してみる
では実際にpt-query-digestを利用してスロークエリログを確認していきます。
以下のコマンドでpt-query-digestを利用してスロークエリログを確認できます。
$ sudo pt-query-digest /var/log/mysql/slow.log
pt-query-digestの出力には主に3つのパートに分かれます。
- スロークエリログの全体像
- クエリのランキング
- クエリの詳細情報
それぞれのパートについてこれから説明をしていきます。
スロークエリログの全体像
まずはスロークエリログ全体の結果をまとめたものが表示されます。
今回の例では以下のような結果が得られます。
# 3.1s user time, 20ms system time, 38.36M rss, 101.36M vsz
# Current date: Sun Jul 15 15:37:37 2018
# Hostname: conoha
# Files: /var/log/mysql/slow.log
# Overall: 21.81k total, 31 unique, 0.12 QPS, 0.00x concurrency __________
# Time range: 2018-07-12T18:41:46 to 2018-07-14T21:25:01
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 86s 1us 6s 4ms 3ms 89ms 98us
# Lock time 504ms 0 128ms 23us 31us 1ms 0
# Rows sent 18.11k 0 100 0.85 0.99 7.23 0
# Rows examine 8.78M 0 9.77k 421.97 0.99 1.87k 0
# Query size 1.70M 10 387.41k 81.88 62.76 3.67k 31.70スロークエリのラベルの意味と、表示されている属性は以下のようになっています。
| ラベル | 意味 |
| total | 合計値 |
| min | 最小値 |
| max | 最大値 |
| avg | 平均値 |
| 95% | 上位95%の合計値 |
| stddev | 標準偏差 |
| median | 中央値 |
| 変数 | 意味 |
| Exec time | 実行時間 |
| Lock time | ロック待ち時間 |
| Row sent | 送信回数 |
| Rows exeamine | フェッチした行数 |
| Query size | SQLの値 |
これらのラベルの値を比較することでスロークエリログがどのように分布しているか理解することができます。
例えばExec timeに注目をすると、平均値が4msに対して中央値が98usと非常に小さい値となっています。またtotalが86sかかっているのに上位95%では3msしか占めておりません。
つまり、ある実行時間の非常に遅いクエリが存在しているということがわかります。
クエリのランキング
クエリをノーマライズ、集計した結果をランキング形式で表示している部分です。
クエリのノーマライズとは、例えば、column1 = 1とcolumn1 = 2といった数字(もしくは文字列)をcolumn1 = Nのように同一のクエリとして識別することをいいます。
今回の例では以下のような結果が得られます。
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ====== ===== ==============
# 1 0x16A13978F3B7FCFA 70.2195 81.6% 41 1.7127 0.79 SELECT image
# 2 0x4866C96BA295C56E 6.0071 7.0% 902 0.0067 0.01 SELECT message
# 3 0x691DE3FA84054868 3.9916 4.6% 4531 0.0009 0.00 SELECT user
# 4 0x99AA0165670CE848 3.3058 3.8% 6942 0.0005 0.00 ADMIN PREPARE
# MISC 0xMISC 2.5478 3.0% 9398 0.0003 0.0 <27 ITEMS>ラベルの意味は以下のようになっています。
| ラベル | 意味 |
| Response time | 実行時間の和とスロークエリログ全体に占める割合 |
| Calls | 実行回数 |
| R/Call | 平均値 |
| V/M | 標準偏差 |
| Item | クエリのサマリー |
デフォルトではRespose timeをもとにソートして表示されています。
この例ですと、0x16A13978F3B7FCFAというIDのクエリがボトルネックになっていることがわかります。
クエリの詳細情報
各クエリごとの詳細データを表示している部分です。こちらは先ほどボトルネックと判断された0x16A13978F3B7FCFAのクエリの情報です。
# Query 1: 0.67 QPS, 1.15x concurrency, ID 0x16A13978F3B7FCFA at byte 5720544
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.79
# Time range: 2018-07-12T18:43:04 to 2018-07-12T18:44:05
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 41
# Exec time 81 70s 1s 6s 2s 4s 1s 1s
# Lock time 0 4ms 26us 2ms 105us 84us 305us 36us
# Rows sent 3 611 1 25 14.90 22.53 5.77 14.52
# Rows examine 0 40.12k 1001 1004 1001.90 964.41 0 964.41
# Query size 0 3.10k 46 79 77.39 76.28 6.82 76.28
# String:
# Databases isubata
# Hosts localhost
# Users isucon
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################################################
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isubata` LIKE 'image'\G
# SHOW CREATE TABLE `isubata`.`image`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM image WHERE name = 'ae8893170459dc68063b942c49cc0b2be78f6b47.png'\G実際のSQLのサンプルも表示されているため、サンプルの情報をもとにExplainなどを実行し、より細かな調査を進めることができます。
以下の記事ではクエリ詳細の結果のどういった点に着目するかを実践的な視点で解説してくれています。
まとめ
今回はMySQLのスロークエリログをみやすくするpt-query-digestの導入方法について説明をしました。
スロークエリログは加工していない生データでも十分活用できますが、pt-query-digestを利用することでよりわかりやすくなります。
pt-query-digestのオプションや、より詳細な情報についてはPercona社のpt-query-digestのページをご確認ください。
この記事がいいなと思いましたらツイッター(@nishina555)のフォローもよろしくお願いします！
