ablog

不器用で落着きのない技術者のメモ

MySQL の slow query log を Percona Toolkit の pt-query-digest で整形する

環境

インストール

% 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')\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や実際に実行する時にそのままコピー&ペーストできます。

スローログの集計に便利な「pt-query-digest」を使ってみよう | Think IT(シンクイット)