コンテンツへスキップ

pt-query-digestを見なおしてみる

  • by

ブログ更新をかなりさぼっていたのですが、ちょっとずつ更新を再開します。

久しぶりのポストですがPercona社のMySQL関連お役立ちツールPercona Toolkitの中でも一番、使えるのではないかと思ってるpt-query-digestについてです。

前から使ってはいるものの、バージョンが変わって知らない間にいろいろ機能が追加されたり逆に無くなってたり、今一度見なおしてみようというところです。

Percona Toolkit

そもそも、pt-query-digestとは一言でいろんなインプット情報からクエリを集計してくれて、悪い順に並べてくれるようなツールです。

# 6.2s user time, 130ms system time, 28.20M rss, 114.51M vsz
# Current date: Sun Jun 21 22:19:32 2015
# Hostname: XXXX
# Files: XXXX-slow.log
# Overall: 10.05k total, 38 unique, 0.00 QPS, 0.00x concurrency __________
# Time range: 2013-08-25 17:33:45 to 2015-06-21 03:02:33
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 40082s 2s 110s 4s 8s 5s 3s
# Lock time 267s 0 11s 27ms 2ms 264ms 138us
# Rows sent 909.20M 0 362.15k 92.59k 345.04k 145.13k 0
# Rows examine 909.21M 0 362.15k 92.59k 345.04k 145.13k 0.99
# Query size 47.96M 11 289.23k 4.88k 9.33k 15.01k 107.34# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ================ ===== ======= ===== ===========
# 1 0x94350EA2AB8AAC34 20519.9653 51.2% 6116 3.3551 1.31 UPDATE AAAA
# 2 0x67A347A2812914DF 14591.3722 36.4% 3037 4.8045 10.86 SELECT BBBB
# 3 0x30FE5C2032672827 2344.5861 5.8% 177 13.2462 15.07 SHOW TABLE STATUS
# 4 0xAA8DB00350539EB6 1035.0229 2.6% 281 3.6834 2.87 DELETE CCCC
# 5 0x8AE5000CAF43D53F 862.7898 2.2% 273 3.1604 0.86 INSERT UPDATE DDDD
# 6 0x132628303F99240D 368.0135 0.9% 85 4.3296 2.23 SHOW TABLES
# 7 0xF9A57DD5A41825CA 75.0345 0.2% 11 6.8213 2.37 SELECT
# 9 0x7AEDF19FDD3A33F1 35.2736 0.1% 13 2.7134 0.23 SELECT EEEE
# MISC 0xMISC 249.6660 0.6% 62 4.0269 0.0 <30 ITEMS>
このあとに個別のクエリレポートが続く

昔はmemcachedやpostgresqlにも対応していたようですが、最近のマニュアルにはそんなことは書いていないようです。

インプット情報別の使い方

まずはインプット情報の種類別にどういうシチュエーションで使うのかを考えてみました。

show processlistから読み込む場合の例

$ pt-query-digest –processlist h=localhost,u=root,p=password –run-time 60
Reading from STDIN …

上の例では、–run-timeの秒数の間でshow processlistで抽出されたクエリが集計されます。
指定した時間が経過するとレポートが出力されます。

ただし、show processlistを実行して抽出するようなので、タイミングが合って記録できたクエリしか取得できないようです。

tcpdumpを併用するのが最強なのですが、どうしてもtcpdumpが使えない状況などに簡易的にクエリを抽出したい場合に有効なのではないかと思います。

バイナリログから読み込む場合の例

# mysqlbinlog mysql-bin.000203 > /tmp/binlog.log
# pt-query-digest –type binlog /tmp/binlog.log

当たり前ですが、バイナリログは更新クエリしか残されていないので、SELECTは抽出できません。
また、バイナリログが行ベースの場合はクエリは残っていないので、結果何もわからないかもしれません・・・。

generalログも食べられます

# pt-query-digest –type genlog general.log

generalログを有効にすることで、すべてのクエリを解析することができます。
tcpdumpが使えない時に、mysqlの管理者権限があればgeneralログを有効にして、すべてのクエリを出力しておいて、後から解析できます。
ただし、もともとgeneralログにはクエリの実行時間が含まれていないので、どんなクエリが何回実行されているかなどの、大まかな結果しか出ません。

スロークエリログも食べられます

# pt-query-digest –type slowlog slow.log

スロークエリログなので、全てを網羅しているわけでなく、あくまでしきい値を超えた遅いクエリだけが対象です。
オンラインでスロークエリのしきい値を0にすれば網羅性は上がりますが、そもそもそんな設定自体が許されないかもしれません。

結果的に実行時間が短いが回数が多いクエリや、インデックスのレンジスキャンなどでCPUを多く使っているようなクエリが漏れるかもしれません。

最強のtcpdumpの併用

やはり一番効果的なのはtcpdumpを読み込ませての解析です。
すべてのクエリが対象になるので、漏れることもありません。
また、DBとは関係ない所で実行できるので、tcpdumpさえ取得して、別のサーバでレポーティングする等も簡単です。
OSのroot権限が必要になるので、運用上の問題で実行できないかもしれませんが、その場合は、OS管理者に実行してもらうか、だめな場合は上述の別の手段になるかと思います。

# tcpdump -s 65535 -x -nn -q -tttt -i any -c 1000 port 3306 mysql.tcpdump
# pt-query-digest –type tcpdump mysql.tcpdump

 

その他のお役立ち

他にも役に立ちそうな機能が目白押しです。

解析時のオプションでEXPLAINを実行することもできます

# pt-query-digest –type slowlog –explain h=localhost,u=root XXXX-slow.log

抜粋

# Query 9: 0.00 QPS, 0.00x concurrency, ID 0x7AEDF19FDD3A33F1 at byte 51668983
# Scores: V/M = 0.23
# Time range: 2013-09-22 09:11:06 to 2014-09-13 23:53:06
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 13
# Exec time 0 35s 2s 5s 3s 4s 794ms 2s
# Lock time 0 2ms 50us 285us 117us 167us 54us 105us
# Rows sent 0 10 0 1 0.77 0.99 0.42 0.99
# Rows examine 0 10 0 1 0.77 0.99 0.42 0.99
# Query size 0 1.14k 77 102 89.46 97.36 5.68 88.31
# String:
# Databases XXXX
# Hosts localhost
# Users XXXX
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################################################
# 10s+
# Tables
# SHOW TABLE STATUS FROM `XXXX` LIKE ‘opt’\G
# SHOW CREATE TABLE `XXXX`.`XXXX`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT opt_value FROM XXXX WHERE opt_name = ‘categories’ LIMIT 1\G
# *************************** 1. row ***************************
# id: 1
# select_type: SIMPLE
# table: XXXX
# partitions: NULL
# type: const
# possible_keys: opt_name
# key: opt_name
# key_len: 194
# ref: const
# rows: 1
# Extra:

集計する項目を自分で作ることもできます

# pt-query-digest –type slowlog XXXX-slow.log –filter ‘($event->{Row_ratio} = $event->{Query_time} / ($event->{Lock_time})) && 1’

無理やり作ってみましたが、Query_time（実行時間）とLock_time（ロック時間）の割合を出力するように。

# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 13
# Exec time 0 35s 2s 5s 3s 4s 794ms 2s
# Lock time 0 2ms 50us 285us 117us 167us 54us 105us
# Rows sent 0 10 0 1 0.77 0.99 0.42 0.99
# Rows examine 0 10 0 1 0.77 0.99 0.42 0.99
# Query size 0 1.14k 77 102 89.46 97.36 5.68 88.31
# Row ratio 0 351.71k 7.38k 53.19k 27.05k 44.45k 12.31k 24.16k　★追加分★

 

これはMySQLのスロークエリログですが、Percona Severのスロークエリログは更に多くの情報が残っているため、作りがいがあるかもしれません。

–reviewオプション

いつからかこんなオプションが追加されていました。

# pt-query-digest –review h=localhost,u=root –no-report slow.log

：

mysql> use percona_schema;

Database changed
mysql> show tables;
+————————–+
| Tables_in_percona_schema |
+————————–+
| query_review |
+————————–+
1 rows in set (0.01 sec)

–reviewオプション付きでクエリを解析にかけると、DSNで指定したMySQLにデータが保存されます。
テーブルにはこんなデータが入っています。

 

*************************** 8. row ***************************
checksum: 8858001711021306865
fingerprint: select option_value from XXXX where opt_name = ? limit ?
sample: SELECT option_value FROM XXXX WHERE opt_name = ‘categories’ LIMIT 1
first_seen: 2013-09-22 09:11:06
last_seen: 2014-09-13 23:53:06
reviewed_by: NULL
reviewed_on: NULL
comments: NULL
8 rows in set (0.00 sec)

ここでこのクエリは確認済みになったので、次からレポートには出力させたくないとします。

mysql> update query_review set reviewed_by=”yorozuyah”,reviewed_on = now() where checksum=8858001711021306865;

更新した旨UPDATEをして、から–reviewオプションを使ってレポーティングすると、次のレポートからは対象のクエリが挙がってこなくなりました。

# pt-query-digest –review h=localhost,u=root –type slowlog XXXX-slow.log

運用上定期的に、解析結果を出して確認していたり、開発中にクエリを1つずつ潰しているような時に使えそうです。

–historyオプション

reviewと似たような機能として、historyという機能が増えてます。
後から振り返って状況を確認するなど、使い道はいろいろありそうです。

# pt-query-digest –history h=localhost,u=root –no-report XXXX-slow.log
：
：
mysql> show tables;
+————————–+
| Tables_in_percona_schema |
+————————–+
| query_history |
| query_review |
+————————–+
2 rows in set (0.01 sec)
*************************** 8. row ***************************
checksum: 8858001711021306865
sample: SELECT option_value FROM XXXX WHERE opt_name = ‘categories’ LIMIT 1
ts_min: 2013-09-22 09:11:06
ts_max: 2014-09-13 23:53:06
ts_cnt: 13
Query_time_sum: 35.2736
Query_time_min: 2.05142
Query_time_max: 4.97518
Query_time_pct_95: 3.52771
Query_time_stddev: 0.794433
Query_time_median: 2.45322
Lock_time_sum: 0.00153
Lock_time_min: 0.00005
Lock_time_max: 0.000285
Lock_time_pct_95: 0.000167833
Lock_time_stddev: 0.0000546159
Lock_time_median: 0.000105611
Rows_sent_sum: 10
Rows_sent_min: 0
Rows_sent_max: 1
Rows_sent_pct_95: 0.992137
Rows_sent_stddev: 0.418012
Rows_sent_median: 0.992137
Rows_examined_sum: 10
Rows_examined_min: 0
Rows_examined_max: 1
Rows_examined_pct_95: 0.992137
Rows_examined_stddev: 0.418012
Rows_examined_median: 0.992137
Rows_affected_sum: NULL
Rows_affected_min: NULL
Rows_affected_max: NULL
Rows_affected_pct_95: NULL
Rows_affected_stddev: NULL
Rows_affected_median: NULL
Rows_read_sum: NULL
Rows_read_min: NULL
Rows_read_max: NULL
Rows_read_pct_95: NULL
Rows_read_stddev: NULL
Rows_read_median: NULL
Merge_passes_sum: NULL
Merge_passes_min: NULL
Merge_passes_max: NULL
Merge_passes_pct_95: NULL
Merge_passes_stddev: NULL
Merge_passes_median: NULL
InnoDB_IO_r_ops_min: NULL
InnoDB_IO_r_ops_max: NULL
InnoDB_IO_r_ops_pct_95: NULL
InnoDB_IO_r_ops_stddev: NULL
InnoDB_IO_r_ops_median: NULL
InnoDB_IO_r_bytes_min: NULL
InnoDB_IO_r_bytes_max: NULL
InnoDB_IO_r_bytes_pct_95: NULL
InnoDB_IO_r_bytes_stddev: NULL
InnoDB_IO_r_bytes_median: NULL
InnoDB_IO_r_wait_min: NULL
InnoDB_IO_r_wait_max: NULL
InnoDB_IO_r_wait_pct_95: NULL
InnoDB_IO_r_wait_stddev: NULL
InnoDB_IO_r_wait_median: NULL
InnoDB_rec_lock_wait_min: NULL
InnoDB_rec_lock_wait_max: NULL
InnoDB_rec_lock_wait_pct_95: NULL
InnoDB_rec_lock_wait_stddev: NULL
InnoDB_rec_lock_wait_median: NULL
InnoDB_queue_wait_min: NULL
InnoDB_queue_wait_max: NULL
InnoDB_queue_wait_pct_95: NULL
InnoDB_queue_wait_stddev: NULL
InnoDB_queue_wait_median: NULL
InnoDB_pages_distinct_min: NULL
InnoDB_pages_distinct_max: NULL
InnoDB_pages_distinct_pct_95: NULL
InnoDB_pages_distinct_stddev: NULL
InnoDB_pages_distinct_median: NULL
QC_Hit_cnt: NULL
QC_Hit_sum: NULL
Full_scan_cnt: NULL
Full_scan_sum: NULL
Full_join_cnt: NULL
Full_join_sum: NULL
Tmp_table_cnt: NULL
Tmp_table_sum: NULL
Tmp_table_on_disk_cnt: NULL
Tmp_table_on_disk_sum: NULL
Filesort_cnt: NULL
Filesort_sum: NULL
Filesort_on_disk_cnt: NULL
Filesort_on_disk_sum: NULL
8 rows in set (0.00 sec)

まだまだ尽きませんが主要な部分はこんなところでしょうか・・・
また随時アップデートしていきます。

タグ:

コメントを残す

メールアドレスが公開されることはありません。 ※ が付いている欄は必須項目です

CAPTCHA