僕の愛用している、MySQLのslow query対策のために非常に便利なpt-query-digestの紹介をします。
pt-query-digestとは
pt-query-digestとはPercona Toolkitの一つで、MySQLのクエリログの分析ができるツールです。
クエリログ（slow, general, binlog）やtcpdumpからのクエリを元に、SQLを分類してそれぞれの統計情報を出力できます。パフォーマンスが悪いSQLを見つけ、それらの優先順位づけと原因の予測に利用できて非常に便利です。
How it works
MySQLのslowqueryのログは以下のようなフォーマットになっています:
$ cat slowquery.log
# Time: 2024-07-04T00:00:32.533834Z
# User@Host: user[user] @ [192.168.1.33] Id: 29049220
# Query_time: 9.589728 Lock_time: 0.000211 Rows_sent: 30 Rows_examined: 34049
use testdb;
SET timestamp=1720051232;
SELECT [略]
...
このように大量にクエリログが含まれたファイルをそのままpt-query-digestに読ませてみると、以下のように集計した結果が出力されます:
$ pt-query-digest slowquery.txt
# 29.4s user time, 140ms system time, 51.00M rss, 57.00M vsz
# Current date: Mon Sep 23 01:15:59 2024
# Hostname: fv-az1372-226
# Files: slowquery.log
# Overall: 190.60k total, 47 unique, 0.32 QPS, 4.00x concurrency _________
# Time range: 2024-09-15T15:00:11 to 2024-09-22T14:59:55
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 2419726s 1s 1082s 13s 27s 50s 3s
# Lock time 28s 22us 23ms 145us 273us 117us 144us
# Rows sent 155.17M 0 426.84k 853.67 80.10 5.66k 24.84
# Rows examine 14.91G 923 2.60M 82.02k 380.41k 221.31k 13.13k
# Query size 306.45M 177 14.69k 1.65k 3.52k 1.35k 1.39k
# Profile
# Rank Query ID Response time Calls R/Call V/M
# ==== =========================== ================= ===== ======== =====
# 1 0x494A28B206A7F62A3489B9... 617228.7506 25.5% 66019 9.3493 16.48 SELECT table1 table2 table3 table4
# 2 0xA9B5D006C41B8EB6CCA1A2... 580741.4678 24.0% 57090 10.1724 18.35 SELECT table1 table2 table3 table4
# 3 0x9C695527419174E15657F3... 541443.6390 22.4% 1991 271.9456 22... SELECT table1
# 4 0xCB5F11BDC42A866BD930AC... 167842.3309 6.9% 1341 125.1621 22... SELECT table1 table2 table3 table4
# 5 0x0A1C885653521028D7167A... 151556.9931 6.3% 10219 14.8309 21... SELECT table1 table2 table3
[...省略...]
# MISC 0xMISC 514.3940 0.0% 83 6.1975 0.0 <18 ITEMS>
# Query 1: 0.11 QPS, 1.02x concurrency, ID 0x494A28B206A7F62A3489B902E44772D7 at byte 238198532
# This item is included in the report because it matches --limit.
# Scores: V/M = 16.48
# Time range: 2024-09-15T15:00:23 to 2024-09-22T14:59:55
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 34 66019
# Exec time 25 617229s 1s 174s 9s 27s 12s 5s
# Lock time 43 12s 96us 23ms 181us 273us 125us 167us
# Rows sent 1 1.89M 30 30 30 30 0 30
# Rows examine 16 2.45G 1.40k 425.52k 38.87k 112.33k 47.82k 22.45k
# Query size 45 138.98M 1.21k 14.62k 2.16k 4.07k 1.16k 1.78k
# String:
# Databases testdb
# Hosts 192.168.7.214 (4268/6%)... 42 more
# Users dbuser
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################################################
# 10s+ ###########################
# EXPLAIN /*!50100 PARTITIONS*/
SELECT [略]
# Query 2: 0.09 QPS, 0.96x concurrency, ID 0xA9B5D006C41B8EB6CCA1A27C7DC07B88 at byte 238119452
[以下略]
SQLのパラメータの違いを吸収した上でそれぞれにID（上の例では 0x494A28B206A7F62A3489B902E44772D7など）をつけ、実行時間、ロック時間、走査された行数、送信された行数等の統計が出力されます。デフォルトではクエリのレスポンスタイム（合計）の大きい順に並んでいます。
上記の例のRank1のクエリ 0x494A28B206A7F62A3489B902E44772D7 を抜粋して見てみると:
# Query 1: 0.11 QPS, 1.02x concurrency, ID 0x494A28B206A7F62A3489B902E44772D7 at byte 238198532
# This item is included in the report because it matches --limit.
# Scores: V/M = 16.48
# Time range: 2024-09-15T15:00:23 to 2024-09-22T14:59:55
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 34 66019
# Exec time 25 617229s 1s 174s 9s 27s 12s 5s
# Lock time 43 12s 96us 23ms 181us 273us 125us 167us
# Rows sent 1 1.89M 30 30 30 30 0 30
# Rows examine 16 2.45G 1.40k 425.52k 38.87k 112.33k 47.82k 22.45k
# Query size 45 138.98M 1.21k 14.62k 2.16k 4.07k 1.16k 1.78k
# String:
# Databases testdb
# Hosts 192.168.7.111 (4268/6%)... 42 more
# Users dbuser
例えば以下のように改善の当たりをつけることができます:
- Exec timeが1sから174sまでばらつきが大きい。パラメータによって実行時間が大きく変わるクエリなのだろう。medianが5sなので、遅くなる条件がありそうだ。
- Rows sentのavgをみると、30に対してRows examineが38.87kと非常に大きい。おそらくどこかでフルスキャンが走っており、インデックスを活用して行の絞り込み効率をあげることで改善できるかもしれない。
- Databases, Hosts, Usersより、あのアプリケーションからのクエリだ
インストール方法
Percona Toolkitのインストールは以下にまとまっています。
プレーンにインストールした場合はPerlのモジュールが必要になることも多いのでこちらも参照。
Macの場合はbrewでインストールできます。
brew install percona-toolkit
tacomsでの利用
tacomsではAWSにて複数のAurora MySQLクラスタが稼働しています。Performance InsightsのTop SQLタブから実行時間の長いSQLを確認することはできますが、具体的な実行時間の分布や走査された/送られた行数等の情報は得ることはできませんでした。
pt-query-digestを導入することで、slowlogを使って今まで見られなかった情報も含めて分析ができるようになりました。遅いクエリが多々あることは今までも認識されていたのですが、pt-query-digestはその優先順位の可視化を非常に簡単に行えるという点が価値が高いと感じています。
現在はpt-query-digestによるslow queryの分析結果を定期的にslackに流すことで、誰でもその状況が見られるようにしています。
まとめ
pt-query-digestはslow logをそのまま読ませるだけで簡単にパフォーマンス改善に有用な情報をみることができるので、MySQLのパフォーマンス改善の第一歩として非常に便利です。
また、Percona Toolkitにはpt-query-digest以外にもさまざまなツールがあります。pt-online-schema-changeあたりはかなり有名かと思います。MySQLを使う人はどんなツールがあるか一度見ておくと使えそうなものが見つかるかもしれません。
Discussion