pt-query-digest
pt-query-digestはスローログを集計して分析するためのツール。
Percona Toolkit
に含まれている。
Percona Toolkitのインストール
Ubuntuの場合
$ sudo apt install percona-toolkit
CentOSの場合
$ sudo yum install -y https://repo.percona.com/yum/percona-release-latest.noarch.rpm
$ sudo yum install -y percona-toolkit
MySQLのスロークエリを出力する設定
MySQLのスロークエリを出力する設定は以下の通り。
[mysqld]
...
slow_query_log = 1
slow_query_log_file = /tmp/mysql-slow.log
long_query_time = 0
- slow_query_log: スロークエリを出力するか。1なら出力する。
- slow_query_log_file: スロークエリを出力するファイルパス。
- long_query_time: スロークエリとみなすクエリの実行時間。0ならすべてのクエリをスロークエリとみなす。
上記設定では/tmp/mysql-slow.logにすべてのクエリを出力する。
以下、スロークエリを出力したファイルを/tmp/mysql-slow.logとしてコマンドを実行する。
pt-query-digestでスロークエリの集計
pt-query-digestでスロークエリを集計するには以下のコマンドを実行する。
$ pt-query-digest /tmp/mysql-slow.log
上記コマンドを実行すると以下のような結果が出力される。
# 970ms user time, 110ms system time, 43.93M rss, 49.77M vsz
# Current date: Mon Oct 9 14:56:03 2023
# Hostname: ip-10-0-4-127
# Files: /tmp/mysql-slow.log
# Overall: 313 total, 142 unique, 11.59 QPS, 0.78x concurrency ___________
# Time range: 2023-10-09T14:36:49 to 2023-10-09T14:37:16
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 21s 2us 693ms 67ms 308ms 119ms 596us
# Lock time 1ms 0 53us 3us 17us 6us 0
# Rows sent 20.25k 0 19.89k 66.25 2.90 1.09k 0
# Rows examine 256.43k 0 235.99k 838.93 3.89 13.22k 0
# Query size 73.08M 5 1008.95k 239.10k 961.27k 405.04k 80.10
# Profile
# Rank Query ID Response time Calls R/Call V/M It
# ==== =============================== ============= ===== ====== ===== ==
# 1 0x2096778F723F6666B5D7DDC9D0... 12.8967 61.4% 46 0.2804 0.01 INSERT user_cards
# 2 0x13D274D305314539C3CEC5658C... 2.5867 12.3% 8 0.3233 0.06 INSERT user_items
# 3 0x4112BAFCAD857E650001A24863... 2.4403 11.6% 16 0.1525 0.02 INSERT user_present_all_received_history
# 4 0x4AC4DC057720031F4B675AC0EA... 0.7593 3.6% 2 0.3796 0.21 INSERT user_devices
# 5 0xB6B9ED728E1332C1DD99773350... 0.6404 3.0% 2 0.3202 0.12 INSERT user_login_bonuses
# 6 0x523C65E07ED70181A900DF232E... 0.3282 1.6% 2 0.1641 0.30 INSERT users
# 7 0xD17D759B5B5B37355F782062E6... 0.3064 1.5% 1 0.3064 0.00 INSERT user_decks
# 8 0x87474CC379307B167F62C1A23A... 0.1042 0.5% 1 0.1042 0.00 SELECT user_present_all_received_history
# MISC 0xMISC 0.9563 4.5% 235 0.0041 0.0 <134 ITEMS>
# Query 1: 3.54 QPS, 0.99x concurrency, ID 0x2096778F723F6666B5D7DDC9D01010C7 at byte 241501
# Scores: V/M = 0.01
# Time range: 2023-10-09T14:36:51 to 2023-10-09T14:37:04
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 14 46
# Exec time 61 13s 193ms 474ms 280ms 339ms 55ms 266ms
# Lock time 0 0 0 0 0 0 0 0
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 0 0 0 0 0 0 0 0
# Query size 61 45.18M 970.86k 1006.59k 1005.76k 961.27k 0 961.27k
# String:
# Databases isucon
# Hosts localhost
# Users isucon
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms ################################################################
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isucon` LIKE 'user_cards'\G
# SHOW CREATE TABLE `isucon`.`user_cards`\G
INSERT INTO `user_cards` VALUES (1042148,9904038980,6,720,36,5336,1639932222,1639932222,NULL) /*... omitted ...*/\G
.
.
.
pt-query-digestの集計結果のみかた
サマリー部
最初のサマリー部分は以下の通り。
サマリー部分のうちよく見るのは以下のとおり。
Query ID
Query IDはのちにそれぞれの詳細を確認する際に使用する。
Response time, Count, R/Call
Response timeはクエリの実行時間の合計。全体のうちの割合も表示されているので、どのクエリに時間がかかっているのかがわかる。
その際、そのクエリの改善戦略のためにCountも参考にする。
Response timeが長いクエリの場合、Countが多い場合はそのクエリの「実行回数」を減らすことでパフォーマンス改善が期待できる。
一方、Countが少ない場合はそのクエリの「実行時間」を短縮することでパフォーマンス改善が期待できる。
特にCountが想像よりも多い場合N+1問題が発生している可能性がある。
詳細部
サマリー部でみたいクエリのRankかQuery IDに相当する行を探すと、そのクエリの詳細が表示されている。
詳細部分は以下のとおり。
よく見る部分は以下のとおり。
Count, Exec time
サマリーでも確認したカウントと実行時間を確認できる。
1クエリの実行時間を短くすればいいのか、クエリの実行回数を減らせばいいのかを判断するための参考にする。
Example
最終行に具体的なSQLの例が表示されている。
このSQLの先頭にEXPLAINをつけて実行して実行計画を確認し、インデックスが効いているかどうかを確認する。
繰り返し集計する場合の注意
スロークエリは/tmp/mysql-slow.logに追記されていく。そのため実行し直して集計し直す場合は/tmp/mysql-slow.logを削除する必要がある。
削除しないと前回のスロークエリも含まれてしまうため、正しい集計結果が得られない。
