pt-ioprofile
pt-ioprofile 属于Percona Toolkit 下的一个工具
下载地址：https://www.percona.com/software/database-tools/percona-toolkit
简单看一下使用说明
pt-ioprofile --help
Usage: pt-ioprofile [OPTIONS] [FILE]
For more information, 'man pt-ioprofile' or 'perldoc /usr/local/bin/pt-ioprofile'.
Command line options:
--aggregate The aggregate function, either C<sum> or C<avg>.
--cell The cell contents.
--group-by The group-by item.
--help Print help and exit.
--profile-pid The PID to profile, overrides L<"--profile-process">.
--profile-process The process name to profile.
--run-time How long to profile.
--save-samples Filename to save samples in; these can be used for later
analysis.
--version Print the tool's version and exit.
Options and values after processing arguments:
--aggregate sum
--cell times
--group-by filename
--help TRUE
--profile-pid (No value)
--profile-process mysqld
--run-time 30
--save-samples (No value)
--version FALSE
其中
--cell 有三个参数
VALUE CELLS CONTAIN
===== =======================
count Count of I/O operations
sizes Sizes of I/O operations
times I/O operation timing
其他参数，可用 man 查看
可用于记录 MySQL 一段时间内IO调用次数
MySQL binlog 日志以及刷盘参数
mysql> show variables like 'log_bin';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_bin | ON |
+---------------+-------+
1 row in set (0.01 sec)
mysql> show variables like 'sync_binlog';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| sync_binlog | 1 |
+---------------+-------+
1 row in set (0.00 sec)
mysql> show variables like 'innodb_flush_log_at_trx_commit';
+--------------------------------+-------+
| Variable_name | Value |
+--------------------------------+-------+
| innodb_flush_log_at_trx_commit | 1 |
+--------------------------------+-------+
1 row in set (0.00 sec)
建库测试
一个session 先开启pt-ioprofile，然后另开一个窗口 对mysql 进行操作
mysql> create database test;
Query OK, 1 row affected (0.00 sec)
mysql> use test
Database changed
观察 pt-ioprofile 的结果
[mysql@dbrtmappredb37 ~]$ pt-ioprofile --profile-pid=$(pidof mysqld) --cell=count --run-time=20
Sun Jun 18 10:43:05 CST 2023
Tracing process ID 18866
total write open close getdents lseek filename
8 0 4 2 0 2 /mysql/binlog/mysql-bin.000278
5 1 1 3 0 0 /mysql/data/test/db.opt
5 0 1 2 2 0 /mysql/data/test/
4 0 1 1 2 0 /mysql/data/
建表测试
一个session 先开启pt-ioprofile，然后另开一个窗口 对mysql 进行操作
mysql> create table wnm (cj varchar(10));
Query OK, 0 rows affected (0.06 sec)
观察 pt-ioprofile 的结果
[mysql@dbrtmappredb37 ~]$ pt-ioprofile --profile-pid=$(pidof mysqld) --cell=count --run-time=20
Sun Jun 18 10:45:23 CST 2023
Tracing process ID 18866
total pread read pwrite write fsync fdatasync open close lseek fcntl filename
39 2 5 2 17 0 1 2 2 8 0 /mysql/data/test/wnm.frm
21 0 0 4 0 4 0 2 1 6 4 /mysql/data/test/wnm.ibd
9 0 0 0 0 0 0 4 3 2 0 /mysql/binlog/mysql-bin.000278
5 0 0 0 0 0 1 1 3 0 0 /mysql/data/test/
观察文件大小
[mysql@dbrtmappredb37 ~]$ ll /mysql/data/test/
total 116
-rw-r----- 1 mysql mysql 67 Jun 18 10:43 db.opt
-rw-r----- 1 mysql mysql 8556 Jun 18 10:45 wnm.frm
-rw-r----- 1 mysql mysql 98304 Jun 18 10:45 wnm.ibd
INSERT 测试
一个session 先开启pt-ioprofile，然后另开一个窗口 对mysql 进行操作
mysql> insert into wnm values ('233');
Query OK, 1 row affected (0.00 sec)
观察 pt-ioprofile 的结果
[mysql@dbrtmappredb37 ~]$ pt-ioprofile --profile-pid=$(pidof mysqld) --cell=count --run-time=20
Sun Jun 18 10:47:26 CST 2023
Tracing process ID 18866
total pread read open close lseek filename
16 2 5 1 4 4 /mysql/data/test/wnm.frm
4 0 0 4 0 0 /mysql/binlog/mysql-bin.000278
可见，此次insert 并未对redo log 进行刷盘操作，但是却操作了 表的 FRM 文件
观察文件大小,大小无变化
[mysql@dbrtmappredb37 ~]$ ll /mysql/data/test/
total 116
-rw-r----- 1 mysql mysql 67 Jun 18 10:43 db.opt
-rw-r----- 1 mysql mysql 8556 Jun 18 10:45 wnm.frm
-rw-r----- 1 mysql mysql 98304 Jun 18 10:47 wnm.ibd
INSERT 测试 2
一个session 先开启pt-ioprofile，然后另开一个窗口 对mysql 进行操作
mysql> insert into wnm values ('122');
Query OK, 1 row affected (0.00 sec)
观察 pt-ioprofile 的结果
[mysql@dbrtmappredb37 ~]$ pt-ioprofile --profile-pid=$(pidof mysqld) --cell=count --run-time=20
Sun Jun 18 10:50:48 CST 2023
Tracing process ID 18866
total open close lseek filename
11 4 4 3 /mysql/binlog/mysql-bin.000278
可见，此次insert 并未对redo log 进行刷盘操作，此次未对frm 文件进行操作，第一次读操作，怀疑为读取数据字典？
INSERT 测试 2
一个session 先开启pt-ioprofile，然后另开一个窗口 对mysql 进行操作
mysql> insert into wnm values ('2333');
Query OK, 1 row affected (0.00 sec)
观察 pt-ioprofile 的结果
[mysql@dbrtmappredb37 ~]$ pt-ioprofile --profile-pid=18866 --cell=count --run-time=20
Sun Jun 18 10:53:58 CST 2023
Tracing process ID 18866
total open filename
4 4 /mysql/binlog/mysql-bin.000278
可见，此次insert 还是没有对redo log 进行刷盘操作。。。。。哔了狗了。
不服。。。切到root 下面 接着测试，结果总算不一样了
INSERT 测试 3
一个session 先开启pt-ioprofile，然后另开一个窗口 对mysql 进行操作
mysql> insert into wnm values ('12');
Query OK, 1 row affected (0.01 sec)
mysql> insert into wnm values ('122');
Query OK, 1 row affected (0.01 sec)
mysql> insert into wnm values ('1222');
Query OK, 1 row affected (0.00 sec)
mysql> insert into wnm values ('12222');
Query OK, 1 row affected (0.00 sec)
mysql> insert into wnm values ('122222');
Query OK, 1 row affected (0.01 sec)
观察 pt-ioprofile 的结果
[root@dbrtmappredb37 ~]# pt-ioprofile --profile-pid=18866 --cell=count --run-time=20
Sun Jun 18 10:57:44 CST 2023
Tracing process ID 18866
total pwrite write fdatasync fsync open close lseek filename
36 18 0 0 18 0 0 0 /mysql/data/ib_logfile1
30 15 0 0 15 0 0 0 /mysql/data/xb_doublewrite
12 0 6 6 0 0 0 0 /binlog/mysql-bin.000279
10 0 0 0 0 4 3 3 /mysql/binlog/mysql-bin.000278
9 0 0 0 9 0 0 0 /mysql/data/ibdata1
5 0 0 0 5 0 0 0 /mysql/data/ib_logfile0
3 0 0 0 3 0 0 0 /mysql/data/test/wnm.ibd
1 0 0 0 1 0 0 0 /mysql/data/ora/t_mon_immediate.ibd
1 0 0 0 1 0 0 0 /mysql/data/mysql/innodb_table_stats.ibd
1 0 0 0 1 0 0 0 /mysql/data/mysql/innodb_index_stats.ibd
此次结果，看起来正常多了，与之前测试 唯一的不同点是，此次pt-ioprofile 的监控是由 root 发起
完整测试
建库
mysql> create database test;
Query OK, 1 row affected (0.00 sec)
mysql> use test
Database changed
[root@dbrtmappredb37 ~]# pt-ioprofile --profile-pid=18866 --cell=count --run-time=10
Sun Jun 18 11:01:27 CST 2023
Tracing process ID 18866
total write fdatasync open close getdents lseek filename
5 1 0 1 3 0 0 /mysql/data/test/db.opt
4 0 0 2 1 0 1 /mysql/binlog/mysql-bin.000278
4 0 0 1 1 2 0 /mysql/data/test/
4 0 0 1 1 2 0 /mysql/data/
2 1 1 0 0 0 0 /binlog/mysql-bin.000279
建表
mysql> create table wnm (cj varchar(10));
Query OK, 0 rows affected (0.06 sec)
[root@dbrtmappredb37 ~]# pt-ioprofile --profile-pid=18866 --cell=count --run-time=10
Sun Jun 18 11:01:52 CST 2023
Tracing process ID 18866
total pread read pwrite write fdatasync fsync open close lseek fcntl filename
39 2 5 2 17 1 0 2 2 8 0 /mysql/data/test/wnm.frm
21 0 0 4 0 0 4 2 1 6 4 /mysql/data/test/wnm.ibd
20 0 0 10 0 0 10 0 0 0 0 /mysql/data/ib_logfile1
18 0 0 9 0 0 9 0 0 0 0 /mysql/data/xb_doublewrite
7 0 0 0 0 0 7 0 0 0 0 /mysql/data/ibdata1
4 0 0 0 2 2 0 0 0 0 0 /binlog/mysql-bin.000279
4 0 0 0 0 1 0 1 2 0 0 /mysql/data/test/
4 0 0 0 0 0 4 0 0 0 0 /mysql/data/ib_logfile0
2 0 0 0 0 0 0 2 0 0 0 /mysql/binlog/mysql-bin.000278
1 0 0 0 0 0 1 0 0 0 0 /mysql/data/mysql/innodb_table_stats.ibd
1 0 0 0 0 0 1 0 0 0 0 /mysql/data/mysql/innodb_index_stats.ibd
insert测试
mysql> insert into wnm values ('12');
Query OK, 1 row affected (0.01 sec)
[root@dbrtmappredb37 ~]# pt-ioprofile --profile-pid=18866 --cell=count --run-time=10
Sun Jun 18 11:02:18 CST 2023
Tracing process ID 18866
total pread read pwrite write fdatasync fsync open close lseek filename
14 2 5 0 0 0 0 1 2 4 /mysql/data/test/wnm.frm
8 0 0 4 0 0 4 0 0 0 /mysql/data/ib_logfile1
6 0 0 0 0 0 0 2 2 2 /mysql/binlog/mysql-bin.000278
4 0 0 2 0 0 2 0 0 0 /mysql/data/xb_doublewrite
2 0 0 0 1 1 0 0 0 0 /binlog/mysql-bin.000279
2 0 0 0 0 0 2 0 0 0 /mysql/data/ib_logfile0
2 0 0 0 0 0 2 0 0 0 /mysql/data/ibdata1
1 0 0 0 0 0 1 0 0 0 /mysql/data/test/wnm.ibd
经过第二轮测试，采用root 用户启动pt-ioprofile 后的测试结果，明显更加接近我们理解的刷盘的现象，需要写redo log 2次，写binlog 1次，
同时，有写入数据文件 1次
注意
每次试验，结果不一定相同。。。上面的有次实验。。刚刚好赶上同时再测试其他表，同时 MySQL 其他刷盘逻辑也会引发刷盘操作。。
