インストール
% brew install percona-toolkit
使ってみる
- pt-query-digest で slow query log を集計する。
% pt-query-digest mysql-slowquery.log.2018-04-27.09 > mysql-slowquery.log.2018-04-27.09-pt.txt mysql-slowquery.log.2018-04-27.09: 9% 04:39 remain mysql-slowquery.log.2018-04-27.09: 23% 03:16 remain mysql-slowquery.log.2018-04-27.09: 45% 01:48 remain mysql-slowquery.log.2018-04-27.09: 72% 00:44 remain mysql-slowquery.log.2018-04-27.09: 93% 00:10 remain
- 集計結果を確認する
% less mysql-slowquery.log.2018-04-27.09-pt.txt # 150.8s user time, 1.8s system time, 59.41M rss, 2.38G vsz # Current date: Fri Apr 27 23:28:57 2018 # Hostname: ****** # Files: mysql-slowquery.log.2018-04-27.09 # Overall: 413.58k total, 977 unique, 114.91 QPS, 30.16x concurrency _____ # Time range: 2018-04-27 08:00:02 to 09:00:01 # Attribute total min max avg 95% stddev median # ============ ======= ======= ======= ======= ======= ======= ======= # Exec time 108556s 38us 56s 262ms 640ms 814ms 51ms # Lock time 129127208518408s 0 18446744073710s 312221233s 30ms 75048244001s 89us # Rows sent 35.25M 0 169.78k 89.37 28.75 1.61k 0.99 # Rows examine 19.10G 0 9.28M 48.42k 97.04k 279.61k 19.46 # Query size 509.74M 24 742.43k 1.26k 2.38k 21.67k 381.65 # Profile # Rank Query ID Response time Calls R/Call V/M Item # ==== ================== ================ ====== ======= ===== ========== # 1 0x959A21D964B0B02E 10676.2713 9.8% 1538 6.9417 1.62 SELECT ... # 2 0x7D68C5021733113C 10338.2087 9.5% 1537 6.7262 1.57 SELECT ... # 3 0xF22F26C61E850C7F 9187.9306 8.5% 22197 0.4139 0.03 SELECT ... # 4 0x864A6BD8BB56F3FC 7608.9758 7.0% 18397 0.4136 0.03 SELECT ....
見方
# 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')\G3つ目のセクションからは、クエリー単位の個別の集計結果が表示されます。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や実際に実行する時にそのままコピー＆ペーストできます。
スローログの集計に便利な「pt-query-digest」を使ってみよう | Think IT（シンクイット）
