pt-ioprofile

Posted 2020-09-25 M哥

pt-ioprofile 能够快速定位到IO问题的主要文件信息，下面就是一些简单的运用

我们先打开TPCC-mysql来进行压测：

[[email protected] tpcc-mysql]# ./tpcc_start -h127.0.0.1 -P3306 -d tpcc -u root -p123456 -w 10 -c 20 -r 5 -l 120

 

然后观察IO信息：

[[email protected] bin]# ./pt-ioprofile --profile-pid=3077
Fri Jun 23 15:17:02 CST 2017
Tracing process ID 3077
total pread read pwrite write fdatasync fsync open close lseek filename
28.935248 28.733903 0.000000 0.000000 0.000000 0.000000 0.201345 0.000000 0.000000 0.000000 /home/mysql/db3306/data/tpcc/stock.ibd
17.108773 16.846786 0.000000 0.000000 0.000000 0.000000 0.261987 0.000000 0.000000 0.000000 /home/mysql/db3306/data/tpcc/customer.ibd
10.872813 0.000000 0.000000 0.185898 0.000000 0.000000 10.686915 0.000000 0.000000 0.000000 /home/mysql/db3306/data/ib_logfile1
8.566047 0.000000 0.069094 0.000000 0.038271 8.456856 0.000000 0.000000 0.000000 0.001826 /home/mysql/db3306/log/mysql-bin.000016
8.267367 8.267367 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 /home/mysql/db3306/data/tpcc/item.ibd
6.220312 0.000000 0.000000 0.000000 6.220312 0.000000 0.000000 0.000000 0.000000 0.000000 /home/mysql/db3306/log/slowlog_343306.log
4.600437 0.000000 0.000000 0.000000 4.600437 0.000000 0.000000 0.000000 0.000000 0.000000 /home/mysql/db3306/data/mxqmongodb2.log
4.229331 2.917050 0.000000 0.072505 0.000000 0.000000 1.239776 0.000000 0.000000 0.000000 /home/mysql/db3306/data/ibdata1
2.892564 2.769299 0.000000 0.000000 0.000000 0.000000 0.123265 0.000000 0.000000 0.000000 /home/mysql/db3306/data/tpcc/orders.ibd
1.957788 1.836054 0.000000 0.000000 0.000000 0.000000 0.121734 0.000000 0.000000 0.000000 /home/mysql/db3306/data/tpcc/order_line.ibd
0.387830 0.387830 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 /home/mysql/db3306/data/tpcc/history.ibd
0.238722 0.238722 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 /home/mysql/db3306/data/tpcc/new_orders.ibd
0.053793 0.000000 0.000000 0.000000 0.000000 0.000000 0.053793 0.000000 0.000000 0.000000 /home/mysql/db3306/data/ib_logfile0
0.026171 0.026171 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 /home/mysql/db3306/data/tpcc/warehouse.ibd
0.016380 0.016380 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 /home/mysql/db3306/data/tpcc/district.ibd
0.010889 0.000000 0.000000 0.000000 0.000000 0.000000 0.010889 0.000000 0.000000 0.000000 /home/mysql/db3306/data/test/heartbeat.ibd
0.005180 0.000000 0.001707 0.000000 0.000000 0.000000 0.000000 0.001928 0.001545 0.000000 /dev/urandom
0.000276 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 0.000276 0.000000 /home/mysql/db3306/data/mysql/user.MYD
[[email protected] bin]# ./pt-ioprofile --profile-pid=3077 --cell=sizes
Fri Jun 23 15:18:12 CST 2017
Tracing process ID 3077
total pread read pwrite write fdatasync fsync lseek filename
9561761579 0 2051837 0 940278 0 0 9558769464 /home/mysql/db3306/log/mysql-bin.000016
44974080 44974080 0 0 0 0 0 0 /home/mysql/db3306/data/tpcc/customer.ibd
23789568 23789568 0 0 0 0 0 0 /home/mysql/db3306/data/tpcc/stock.ibd
16924672 278528 0 16646144 0 0 0 0 /home/mysql/db3306/data/ibdata1
3644470 0 0 0 3644470 0 0 0 /home/mysql/db3306/log/slowlog_343306.log
2260992 2260992 0 0 0 0 0 0 /home/mysql/db3306/data/tpcc/orders.ibd
2179072 2179072 0 0 0 0 0 0 /home/mysql/db3306/data/tpcc/item.ibd
1458176 1458176 0 0 0 0 0 0 /home/mysql/db3306/data/tpcc/order_line.ibd
1344333 0 0 0 1344333 0 0 0 /home/mysql/db3306/data/mxqmongodb2.log
797696 0 0 797696 0 0 0 0 /home/mysql/db3306/data/ib_logfile1
442368 442368 0 0 0 0 0 0 /home/mysql/db3306/data/tpcc/new_orders.ibd
0 0 0 0 0 0 0 0 /home/mysql/db3306/data/ib_logfile0
[[email protected] bin]# ./pt-ioprofile --profile-pid=3077 --cell=sizes --run-time=1
Fri Jun 23 15:19:55 CST 2017
Tracing process ID 3077
total pread read pwrite write fdatasync fsync close filename
3047424 3047424 0 0 0 0 0 0 /home/mysql/db3306/data/tpcc/customer.ibd
999424 999424 0 0 0 0 0 0 /home/mysql/db3306/data/tpcc/stock.ibd
966656 49152 0 917504 0 0 0 0 /home/mysql/db3306/data/ibdata1
208956 0 128392 0 80564 0 0 0 /home/mysql/db3306/log/mysql-bin.000016
137736 0 0 0 137736 0 0 0 /home/mysql/db3306/log/slowlog_343306.log
98304 98304 0 0 0 0 0 0 /home/mysql/db3306/data/tpcc/order_line.ibd
65536 65536 0 0 0 0 0 0 /home/mysql/db3306/data/tpcc/item.ibd
61067 0 0 0 61067 0 0 0 /home/mysql/db3306/data/mxqmongodb2.log
49152 49152 0 0 0 0 0 0 /home/mysql/db3306/data/tpcc/orders.ibd
46592 0 0 46592 0 0 0 0 /home/mysql/db3306/data/ib_logfile1
32768 32768 0 0 0 0 0 0 /home/mysql/db3306/data/tpcc/new_orders.ibd
0 0 0 0 0 0 0 0 /home/mysql/db3306/data/tpcc/history.ibd
0 0 0 0 0 0 0 0 /home/mysql/db3306/data/mysql/ndb_binlog_index.MYD

 

从反馈结果来看，/home/mysql/db3306/data/tpcc/customer.ibd这个表的访问量是较高的，slowlog也较高，按说不应该如此，但是我设置的慢查询时间为0，也就是记录全量的MySQL查询日志，所以说排到这个位置也是正常的。