Percona Toolkitをインストールし、pt-query-digestでスロークエリログを解析する手順

インフラ

こんにちは。仁科(@nishina555)です。

前回、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

なお、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
dpkgコマンドはdebファイルをインストールする際にパッケージの依存解決を自動で解決してくれません。

そのため、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

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
Query_time distributionにはクエリの実行時間の分布が表示され、Tablesには関連テーブルの情報が表示されています。
実際のSQLのサンプルも表示されているため、サンプルの情報をもとにExplainなどを実行し、より細かな調査を進めることができます。

以下の記事ではクエリ詳細の結果のどういった点に着目するかを実践的な視点で解説してくれています。

まとめ

今回はMySQLのスロークエリログをみやすくするpt-query-digestの導入方法について説明をしました。
スロークエリログは加工していない生データでも十分活用できますが、pt-query-digestを利用することでよりわかりやすくなります。

pt-query-digestのオプションや、より詳細な情報についてはPercona社のpt-query-digestのページをご確認ください。

この記事がいいなと思いましたらツイッター(@nishina555)のフォローもよろしくお願いします!