スローログの集計に便利な「pt-query-digest」を使ってみよう

今回は「pt-query-digest」を使用して、チューニングしたいSQLがスローログに記録されている場合の調査方法について説明します。

pt-query-digestとは

pt-query-digestはPercona社が開発・配布するMySQL用のユーティリティーキットで、「Percona Toolkit」の1つです。最新ドキュメント（2016/3/22現在）はこちらにあります。pt-query-digestの基本的な使い方は「スローログをノーマライズ・集計し、人間が判断しやすい形式で出力させる」です。基本的にはスローログ用と考えますが、スローログ以外にもジェネラルログやバイナリーログ（mysqlbinlogコマンドの出力を入力する）、パケットキャプチャー（tcpdumpコマンドの出力を入力する）などが利用可能です。

Percona Toolkitのインストール

まずはPercona Toolkitをインストールします。インストール方法にはいくつかの選択肢があります。 yum/aptリポジトリーを利用する以外の方法でインストールする場合は、Percona ToolkitのダウンロードページでインストールファイルのURLを取得してください。筆者の業務環境はCentOSがメインのため、CentOSに比べてDebian系の記述があっさりしていますがご了承ください。

RHEL/CentOSでyumリポジトリーを利用する

Percona Toolkitのyumリポジトリーを登録し、そこからyumコマンドでインストールする方法です。シンプルでアップグレードに追従しやすいという利点がありますが、Perconaのリポジトリーは独自のMySQL（「Percona Server」というMySQLのフォークプロダクト）を含んでおり、MySQLサーバーをyumリポジトリーでインストールした場合には意図せずパッケージが入れ替えられてしまう可能性がありますので注意してください。

Perconaのyumリポジトリーの登録コマンドは「Installing Percona Server on Red Hat Enterprise Linux and CentOS」に記載されています。

$ sudo yum install http://www.percona.com/downloads/percona-release/redhat/0.1-3/percona-release-0.1-3.noarch.rpm
..
==============================================================================================================
 Package                        Arch                  Version              Repository                                    Size
==============================================================================================================
Installing:
 percona-release                noarch                0.1-3                /percona-release-0.1-3.noarch                5.8 k

Transaction Summary
==============================================================================================================
Install       1 Package(s)

Total size: 5.8 k
Installed size: 5.8 k
Is this ok [y/N]: y
..

$ sudo yum install percona-toolkit
..
Dependencies Resolved

==============================================================================================================
 Package                           Arch            Version                              Repository                       Size
==============================================================================================================
Installing:
 percona-toolkit                   noarch          2.2.17-1                             percona-release-noarch          1.6 M
Installing for dependencies:
 Percona-Server-shared-51          x86_64          5.1.73-rel14.12.625.rhel6            percona-release-x86_64          2.1 M
 perl-DBD-MySQL                    x86_64          4.013-3.el6                          base                            134 k
 perl-DBI                          x86_64          1.609-4.el6                          base                            705 k
 perl-IO-Socket-SSL                noarch          1.31-2.el6                           base                             69 k
 perl-Net-LibIDN                   x86_64          0.12-3.el6                           base                             35 k
 perl-Net-SSLeay                   x86_64          1.35-9.el6                           base                            173 k
 perl-TermReadKey                  x86_64          2.30-13.el6                          base                             31 k
 perl-Time-HiRes                   x86_64          4:1.9721-141.el6_7.1                 updates                          49 k

Transaction Summary
==============================================================================================================
Install       9 Package(s)

Total download size: 5.0 M
Installed size: 11 M

Percona ToolkitのrpmパッケージはMySQLのクライアントライブラリー（「mysql-libs」という名前で配布されていることが多い）に依存しますが、Perconaのリポジトリーを有効にしているため、mysql-libsの代わりに「Percona-Server-shared-51」というパッケージが依存関係でインストールされています。あらかじめmysql-libsをインストールしておくことで回避できますが、mysql-libsがバージョンアップした際に置き換わりが発生するかも知れませんので、これを嫌うのであればyumリポジトリーを利用せず直接rpmファイルをインストールする方法が良いでしょう。

RHEL/CentOS系でrpmファイルを利用する

Perconaのリポジトリーを登録せず、直接rpmファイルをインストールする方法です。依存関係の制御は相変わらずyumコマンドに任せられますし、MySQLのライブラリーをPercona Serverのもので置き換えられるリスクもありません。yumリポジトリー利用時はyum upgrade percona-toolkitで可能だったアップグレードのみ、毎回URLを入力する形式に変わります。

$ sudo yum install https://www.percona.com/downloads/percona-toolkit/2.2.17/RPM/percona-toolkit-2.2.17-1.noarch.rpm
..
==============================================================================================================
 Package                     Arch            Version                          Repository                                 Size
==============================================================================================================
Installing:
 percona-toolkit             noarch          2.2.17-1                         /percona-toolkit-2.2.17-1.noarch          5.6 M
Installing for dependencies:
 mysql-libs                  x86_64          5.1.73-5.el6_6                   base                                      1.2 M
 perl-DBD-MySQL              x86_64          4.013-3.el6                      base                                      134 k
 perl-DBI                    x86_64          1.609-4.el6                      base                                      705 k
 perl-IO-Socket-SSL          noarch          1.31-2.el6                       base                                       69 k
 perl-Net-LibIDN             x86_64          0.12-3.el6                       base                                       35 k
 perl-Net-SSLeay             x86_64          1.35-9.el6                       base                                      173 k
 perl-TermReadKey            x86_64          2.30-13.el6                      base                                       31 k
 perl-Time-HiRes             x86_64          4:1.9721-141.el6_7.1             updates                                    49 k

Transaction Summary
==============================================================================================================
Install       9 Package(s)

Total size: 8.0 M
Total download size: 2.4 M
Installed size: 13 M

Debian/Ubuntuでaptリポジトリーを利用する

Perconaのaptリポジトリーを登録し、そこからapt-getコマンドでインストールする方法です。シンプルでアップグレードに追従しやすいという利点がありますが、Perconaのリポジトリーは独自のMySQL（「Percona Server」というMySQLのフォークプロダクト）を含んでおり、MySQLサーバーをaptリポジトリーでインストールした場合には意図せずパッケージが入れ替えられてしまう可能性がありますので注意してください。

Perconaのaptリポジトリーの登録コマンドは「Installing Percona Server on Debian and Ubuntu」に記載されています。

$ wget https://repo.percona.com/apt/percona-release_0.1-3.$(lsb_release -sc)_all.deb
$ sudo dpkg -i percona-release_0.1-3.$(lsb_release -sc)_all.deb
$ sudo apt-get install percona-toolkit
..
The following extra packages will be installed:
  libalgorithm-c3-perl libarchive-extract-perl libcgi-fast-perl libcgi-pm-perl libclass-c3-perl libclass-c3-xs-perl
  libcpan-meta-perl libdata-optlist-perl libdata-section-perl libdbd-mysql-perl libdbi-perl libfcgi-perl libgdbm3
  libio-socket-ssl-perl liblog-message-perl liblog-message-simple-perl libmodule-build-perl libmodule-pluggable-perl
  libmodule-signature-perl libmro-compat-perl libmysqlclient18 libnet-libidn-perl libnet-ssleay-perl
  libpackage-constants-perl libparams-util-perl libpod-latex-perl libpod-readme-perl libregexp-common-perl
  libsoftware-license-perl libsub-exporter-perl libsub-install-perl libterm-readkey-perl libterm-ui-perl
  libtext-soundex-perl libtext-template-perl mysql-common perl perl-modules rename
Suggested packages:
  libclone-perl libmldbm-perl libnet-daemon-perl libsql-statement-perl libmime-base64-perl perl-doc
  libterm-readline-gnu-perl libterm-readline-perl-perl make libb-lint-perl libcpanplus-dist-build-perl libcpanplus-perl
  libfile-checktree-perl libobject-accessor-perl
Recommended packages:
  libarchive-tar-perl
The following NEW packages will be installed:
  libalgorithm-c3-perl libarchive-extract-perl libcgi-fast-perl libcgi-pm-perl libclass-c3-perl libclass-c3-xs-perl
  libcpan-meta-perl libdata-optlist-perl libdata-section-perl libdbd-mysql-perl libdbi-perl libfcgi-perl libgdbm3
  libio-socket-ssl-perl liblog-message-perl liblog-message-simple-perl libmodule-build-perl libmodule-pluggable-perl
  libmodule-signature-perl libmro-compat-perl libmysqlclient18 libnet-libidn-perl libnet-ssleay-perl
  libpackage-constants-perl libparams-util-perl libpod-latex-perl libpod-readme-perl libregexp-common-perl
  libsoftware-license-perl libsub-exporter-perl libsub-install-perl libterm-readkey-perl libterm-ui-perl
  libtext-soundex-perl libtext-template-perl mysql-common percona-toolkit perl perl-modules rename
0 upgraded, 40 newly installed, 0 to remove and 0 not upgraded.
Need to get 10.5 MB of archives.
After this operation, 51.5 MB of additional disk space will be used.
Do you want to continue? [Y/n]

Debian/Ubuntuでdebファイルを利用する

Perconaのリポジトリーを登録せず、取得したdebファイルをインストールする方法です。RHEL/CentOS系におけるyumリポジトリー vs rpmパッケージのように、Perconaのリポジトリー由来のファイルで本来のMySQLライブラリーなどが上書きされる心配はなくなりますが、依存関係のあるパッケージは自身であらかじめインストールしておく必要があります。

$ wget https://www.percona.com/downloads/percona-toolkit/2.2.17/deb/percona-toolkit_2.2.17-1_all.deb
$ sudo apt-get install perl libdbi-perl libdbd-mysql-perl libterm-readkey-perl libio-socket-ssl-perl libmysqlclient18 mysql-common libgdbm3 libnet-ssleay-perl perl-modules
$ sudo dpkg -i percona-toolkit_2.2.17-1_all.deb

ソースコードからインストールする

Percona Toolkitの中身はPerlスクリプトおよびシェルスクリプトの詰め合わせです。そのため、敢えてパッケージを利用しなくても簡単にインストールできます。

$ wget https://www.percona.com/downloads/percona-toolkit/2.2.17/deb/percona-toolkit_2.2.17-1.tar.gz
$ tar xf percona-toolkit_2.2.17-1.tar.gz
$ cd percona-toolkit-2.2.17

必要なPerlモジュールがインストールされていれば、このままbinディレクトリーにあるスクリプトを実行できますので、スーパーユーザー権限なしに利用することも可能です。perl Makefile.PL && make && make installで/usr/localにインストールされますが、manページが不要で単発で利用したいだけの場合はこのまま直接ファイルを実行しても良いと思います。

pt-query-digestの使い方

基本的な使い方

それではpt-query-digestの使い方を見ていきましょう。一番単純な使い方は以下の通り、オプションを指定せずに引数としてスローログのパスを指定することです。

$ pt-query-digest /path/to/slow.log

スローログをパースして集計した結果が標準出力に書き出されます。出力内容は入力のスローログに応じて増えますので、リダイレクトでファイルに落としておくのも良いでしょう。セクションごとに内容を見ていきます。

# 210ms user time, 40ms system time, 26.75M rss, 202.94M vsz
# Current date: Thu Mar 24 18:41:21 2016
# Hostname: xxxx
# Files: /usr/mysql/5.7.11/data/slow.log
# Overall: 119 total, 8 unique, 0 QPS, 0x concurrency ____________________
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time          272ms     9us    32ms     2ms     2ms     3ms     2ms
# Lock time           21ms       0     8ms   177us    89us   865us    54us
# Rows sent            510       0     104    4.29       0   19.93       0
# Rows examine         510       0     104    4.29       0   19.93       0
# Query size        17.17k      10     164  147.74  158.58   41.54  158.58

最初のセクションはスローログ全体を俯瞰した様子です。Exec time（スローログ上ではQuery_time）, Lock time, Rows sent, Rows examineなど、スローログに書き込まれている情報を集計した情報が書き出されています。

# Profile
# Rank Query ID           Response time Calls R/Call V/M   Item
# ==== ================== ============= ===== ====== ===== ===============
#    1 0xCAEC22E79B0EFD3B  0.2041 75.2%   105 0.0019  0.00 INSERT t?
#    2 0x35AAC71503957920  0.0322 11.9%     1 0.0322  0.00 FLUSH
#    3 0x0C922D63DA1D917B  0.0216  8.0%     1 0.0216  0.00 CREATE TABLE t? `t1`
#    4 0x5722277F9D796D79  0.0107  3.9%     2 0.0053  0.01 DROP
# MISC 0xMISC              0.0029  1.1%    10 0.0003   0.0 <4 ITEMS>

次のセクションには、クエリー単位でノーマライズ・集計された結果が並びます。pt-query-digestはスローログを処理する際にリテラルをノーマライズします。column1 = 1やcolumn1 = 2といった数値リテラルはcolumn1 = Nという形に丸められ、同じクエリーとして扱われます（カラム名の数字は丸められないため、数字が入っているカラム名を利用していてもカラムが違えば識別される）。

また、文字列リテラルや行リテラルもノーマライズされますので、個々のクエリーのパラメーターの差異によらずに全体としての傾向を掴めます。このセクションでのクエリーはデフォルトでは「各ノーマライズされたクエリーごとのQuery_timeの和」の降順で並べられています。これは --order-by オプションで変更できます。

Response timeはQuery_timeの和とスローログ全体におけるそのクエリーの占めるパーセンテージが出力されます。Callsはクエリーが実行された回数、R/Callは Response time / Call （平均値）、V/Mは標準偏差です。Itemにはクエリーのサマリーが表示されます。時間がかかっている（R/Callが大きい）クエリーでも稀にしか実行されないものである場合、チューニング対象としてはちょっと不足気味です（たとえば、年に1回しか実行されないクエリーを10秒速くすることにあまり意味はない）。また、時間の累計（Response time）が大きいクエリーである場合でもR/Callが十分小さい場合はスピードアップは困難かも知れません（10秒のクエリーを10％速くすることと、10msのクエリーを10％速くすることでは後者の方が難易度が高い）。

実際のスローログを pt-query-digest に集計させた場合、結果サイズはそれなりに大きくなります。全てを見ていくにも時間がかかりますので、このセクションで目ぼしいクエリーにあたりをつけ、Query ID（ノーマライズされたステートメントから計算されるハッシュ値）を検索する方法がお勧めです。

# Query 1: 0 QPS, 0x concurrency, ID 0xCAEC22E79B0EFD3B at byte 2247 _____
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         88     105
# Exec time     75   204ms     1ms     3ms     2ms     2ms   319us     2ms
# Lock time     32     7ms    37us   589us    64us    76us    57us    54us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Query size    97  16.75k     160     164  163.33  158.58    0.00  158.58
# String:
# Databases    mysqlslap
# Hosts        localhost
# Time         2016-03-24... (1/0%), 2016-03-24... (1/0%)... 103 more
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `mysqlslap` LIKE 't1'\G
#    SHOW CREATE TABLE `mysqlslap`.`t1`\G
INSERT INTO t1 VALUES (1308044878,'50w46i58Giekxik0cYzfA8BZBLADEg3JhzGfZDoqvQQk0Akcic7lcJInYSsf9wqin6LDC1vzJLkJXKn5onqOy04MTw1WksCYqPl2Jg2eteqOqTLfGCvE4zTZwWvgMz')\G

3つ目のセクションからは、クエリー単位の個別の集計結果が表示されます。1行目にQuery IDが含まれているため、2つ目のセクションで表示されていたQuery IDを検索すると個別クエリーのセクションの先頭行に行けるようになっています。

筆者はここで Rows examine / Rows sent の値をよく計算します。GROUP BYを使っている場合を除けばRows examine / Rows sentの値が1に近い（小さい）ほど効率良くインデックスで WHERE 句を処理できているからです。1に近いほどインデックス以外の箇所でSQLをチューニングしなければならないため時間がかかり、1から遠いほどインデックスの追加で劇的に速くなる可能性があるため、効率良くチューニングできる可能性が高まります。

またRows sentやRows examine、Exec timeに大きなバラつきがあり相関しているように見える場合、WHERE句の条件によって結果セットの大きさが大幅に変化していることが考えられます。転送された結果セットが本当に全てアプリケーション側で利用されているかを確認すると良いでしょう（本当に使われていた場合はどうしようもないが）。

Rows sent、Rows examine、Lock timeにバラつきが少ないにも関わらずExec timeにバラつきがある場合は、バッファプールのヒット率が悪いことなどが考えられます（MyISAMストレージエンジンのテーブルであればこの限りではない）。InnoDBバッファプールはSELECTのみでなくINSERTやDELETEの際にも利用されます。またInnoDBのテーブル圧縮を使用している場合、バッファプールミスヒットのコストは無圧縮状態に比べて非常に高くなるため注意が必要です。バッファプールの他にもテーブルキャッシュが足りなくなっていないかなども考慮する必要があります。

Timeの行は本来であれば「そのクエリーが最初に現れた時間」と「そのクエリーが最後に現れた時間」を表示しますが、残念ながらMySQL 5.7系列のスローログには対応していません。バッチなどによる一過性のスローログなのか、継続的なものか、あるいはもう既に修正されたもの（最後に現れた時間が十分過去）なのかをチェックしておきましょう。

最後の行は、このチェックサムのクエリーのうちサンプルとして1件、ノーマライズしていないクエリーを表示します。EXPLAINや実際に実行する時にそのままコピー＆ペーストできます。

これ以降、各クエリー単位でこのセクションが並びます。2セクション目のクエリー単位で集計された内容と、この詳細な内容を行ったり来たりしながらSQLチューニングを行なっていきます。

業務上での利用例

pt-query-digestを業務で使う場合、小さな単位で反復的に結果を受け取ると便利です。筆者の勤務先では1日1回スローログを集計して件数のみ通知しています（集計とは別にスローログが一定数出るとリアルタイムに通知される仕組みもある）。

件数のみを通知している理由は「前回の集計から今回の集計の間にスローログがこれだけ増えた」という増分に注目するためです（繰り返しになるが、集計とは別に一定数スローログが出力されるとリアルタイムに出力される。サービスに影響が出るようなスローログはそちらで検知する）。また、小さな単位で集計することで「最近問題になっているスロークエリー」をピックアップしやすくなります。

pt-query-digestでは--sinceオプションと--untilオプションを利用することでスローログの「いつからいつまでを集計範囲にするか」を指定できます。たとえば、2016/3/22のまる1日分のみを集計するためには以下のように指定します。

$ pt-query-digest --since="2016-03-22" --until="2016-03-23" /path/to/slow.log

この出力結果の通知の他に、pt-query-digestの出力の最初のセクションに含まれていた"Overall: xxx total, x unique"の行をパースして保存しています。これにより日々のスロークエリーの数は後から追いやすくなっています。

また、見やすく集計してくれるとはいえpt-query-digestの結果はテキストファイルのため視認性はよくありません。比較的長い範囲を集計したい場合は「Anemometer」という`pt-query-digest`専用のグラフ化ツールを利用して傾向を確認するようにしています（ただしそのままでは利用しづらいため「anemoeater」というラッパースクリプトを作成してAnemometerにデータをインポートしている。良ければ利用してみてほしい）。

まとめ

pt-query-digestはスローログを集計し「チューニングしやすいクエリー」を発見するのに役立ちます。集計単位を小さくすることやグラフ化ツールを併用することで効率を上げましょう。バイナリーログやtcpdumpの結果をスローログのように見立てて集計することも可能ですので、更新クエリーの集中状況やlong_query_timeの値を変更できない場合（あるいは、特定のアプリケーションサーバーのみでのtcpdump結果からの集計）も利用できます。