日々の覚書: 複合プライマリーキー vs サロゲートキーでInnoDB読み取りページ数の比較 の続き。
毎回innodb_metricsを眺める方法だとサンプル数が余程限られている状態でもない限りスケールしないので、もうちょっと機械的にやる方法を考える。
思いついたのはPercona Serverのスローログでやる方法。
取り敢えずオリジナル側でサンプルにするためにスローログを取っておく。本番から期間を絞って取れれば取り敢えず良いだろうか。
mysql> SET GLOBAL slow_query_log = ON, long_query_time = 0;
/* サンプルクエリを取る */
mysql> SET GLOBAL long_query_time = ?; -- もとの値に戻す
データ元も取っておく。細かく気にするならxtrabackupでフルバックアップか、FLUSH TABLES FOR EXPORTでibdファイルをまるまる取ってきた方が断片化具合そのままで計測ができるけれど、気にしなければmysqldumpでも良いと思う。
$ bin/mysqldump d1 > /tmp/dump.sql
MySQL 8.0.23互換のPercona Server 8.0.23を手元にインストール。
$ wget https://downloads.percona.com/downloads/Percona-Server-8.0/Percona-Server-8.0.23-14/binary/tarball/Percona-Server-8.0.23-14-Linux.x86_64.glibc2.12.tar.gz
$ tar xf Percona-Server-8.0.23-14-Linux.x86_64.glibc2.12.tar.gz
$ cd Percona-Server-8.0.23-14-Linux.x86_64.glibc2.12/
$ bin/mysqld --no-defaults --initialize-insecure --datadir=/tmp/data_percona --lower_case_table_names=1 --log-error-verbosity=3
$ bin/mysqld --no-defaults --datadir=/tmp/data_percona --lower_case_table_names=1 --log-error-verbosity=3 --daemonize
mysqld will log errors to /tmp/data_percona/hostname.err
mysqld is running as pid 10782
$ bin/mysql -e "CREATE DATABASE d1"
$ bin/mysql d1 < /tmp/dump.sql
スローログの設定とlog_slow_verbosityの設定をしてから、サンプルのクエリを食わせる。余計なヘッダや実行されたくないクエリは抜いておく必要がありそう。
ヘッダの処理がめんどいのと期間指定もしたかったのでpt-query-digest —output=slowlog —no-reportを間に挟んで整形する
$ bin/mysql -e "SET GLOBAL slow_query_log = ON, long_query_time = 0, log_slow_verbosity= full"
$ pt-query-digest --since="2023-02-11 00:00:00" --output=slowlog --no-report /tmp/data/hostname-slow.log > /tmp/slow.log
$ bin/mysql < /tmp/slow.log > /dev/null
これで測定の諸元になるPercona版のスロークエリが手に入る。
$ less /tmp/data_percona/hostname-slow.log
..
# Time: 2023-02-11T06:49:28.072174Z
# User@Host: root[root] @ localhost [] Id: 12
# Schema: Last_errno: 0 Killed: 0
# Query_time: 0.068346 Lock_time: 0.000063 Rows_sent: 100000 Rows_examined: 100000 Rows_affected: 0 Bytes_sent: 3870459
# Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 0
# Full_scan: Yes Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 294
SET timestamp=1676098168;
SELECT * FROM d1.t5;
# Time: 2023-02-11T06:49:28.135320Z
# User@Host: root[root] @ localhost [] Id: 12
# Schema: Last_errno: 0 Killed: 0
# Query_time: 0.000275 Lock_time: 0.000088 Rows_sent: 100 Rows_examined: 100 Rows_affected: 0 Bytes_sent: 4145
# Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 0
# Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 2
SET timestamp=1676098168;
SELECT * FROM d1.t5 WHERE user_id = 0825;
# Time: 2023-02-11T06:49:28.137490Z
# User@Host: root[root] @ localhost [] Id: 12
# Schema: Last_errno: 0 Killed: 0
# Query_time: 0.001976 Lock_time: 0.000060 Rows_sent: 567 Rows_examined: 567 Rows_affected: 0 Bytes_sent: 22339
# Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 0
# Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 171
SET timestamp=1676098168;
SELECT * FROM d1.t5 WHERE updated = '2023-02-08 00:57:38';
..
うーんちょっと 前回 測ったのと結構結果が違ってどっから引いてるんだろうこれ。
Percona Serverのlog_slow_verbosityで追加した情報はpt-query-digestでそのまま食わせられるので（そりゃそうだ） ページ数に着目してプロファイルを見た後に、複合プライマリーキーに組み替えた後で同じスローログ (/tmp/slow.log) を流してページ数を比較するなんてことができるはず。
$ pt-query-digest /tmp/data_percona/hostname-slow.log --order-by="InnoDB_pages_distinct:sum"
# 250ms user time, 20ms system time, 27.57M rss, 120.81M vsz
# Current date: Sat Feb 11 15:55:43 2023
# Hostname: hostname
# Files: /tmp/data_percona/hostname-slow.log
# Overall: 60 total, 9 unique, 0.13 QPS, 24.78x concurrency ______________
# Time range: 2023-02-11T06:41:48 to 2023-02-11T06:49:28
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 1s 4us 76ms 19ms 65ms 23ms 7ms
# Lock time 15ms 0 6ms 215us 273us 708us 89us
# Rows sent 983.11k 0 97.66k 13.85k 97.04k 33.72k 0.99
# Rows examine 2.49M 0 97.66k 35.85k 97.04k 46.69k 97.36
# Rows affecte 0 0 0 0 0 0 0
# Bytes sent 37.17M 0 3.69M 536.05k 3.68M 1.28M 112.70
# Merge passes 0 0 0 0 0 0 0
# Tmp tables 0 0 0 0 0 0 0
# Tmp disk tbl 0 0 0 0 0 0 0
# Tmp tbl size 0 0 0 0 0 0 0
# Query size 2.79k 19 64 40.31 62.76 15.33 38.53
# InnoDB:
# IO r bytes 0 0 0 0 0 0 0
# IO r ops 0 0 0 0 0 0 0
# IO r wait 0 0 0 0 0 0 0
# pages distin 11.13k 2 297 189.98 284.79 128.16 284.79
# queue wait 0 0 0 0 0 0 0
# rec lock wai 0 0 0 0 0 0 0
# Boolean:
# Full scan 50% yes, 49% no
..
これならまあ、ひたすら手計測よりはいくらかマシであろう。。
0 件のコメント :
コメントを投稿