GA

2023/02/11

複合プライマリーキー vs サロゲートキーでInnoDB読み取りページ数の比較をもうちょっと機械的にやりたい

日々の覚書: 複合プライマリーキー 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 件のコメント :

コメントを投稿