MySQL · 2016-10-23 0

Percona-Toolkit系列之pt-ioprofile数据文件IO监控利器

1.pt-ioprofile

做数据库运维的兄弟们常常遇到这样的问题,iostat -x 1看到某块盘的%util为100%,老大下命令了,立刻给我降下来。其实这个时候我们是很蒙逼的,虽然知道是IO子系统不行,但是不知道从何下手,到底是数据库的那部分操作使IO这么忙,或者说到底是哪个表,哪个数据文件的IO动作最频繁,以及他到底是什么样的系统调用。

pt-ioprofile就是解救大家的神器,pt-ioprofile主要做了两件事情,1. lsof+strace每秒2.对输出结果做聚合计算。输出的内容正是我们想要的,可以帮我们清晰的定位出数据库IO问题所在。输出内容如下:

[mysql@hpc02 mysqldata1]$ pt-ioprofile 
Sun Oct 23 12:03:06 CST 2016
Tracing process ID 3156
     total      pread       read     pwrite      write  fdatasync      fsync       open      close      lseek      fcntl filename
  0.859126   0.000000   0.000000   0.000000   0.000000   0.000000   0.859126   0.000000   0.000000   0.000000   0.000000 /data/mysqldata1/ib_logfile0
  0.702415   0.000000   0.000000   0.062207   0.000000   0.000000   0.640208   0.000000   0.000000   0.000000   0.000000 /data/mysqldata1/ib_logfile1
  0.046738   0.000000   0.000000   0.000111   0.000000   0.000000   0.046433   0.000074   0.000049   0.000000   0.000071 /data/mysqldata1/ib_814_837_trunc.log
  0.045482   0.000000   0.000000   0.000000   0.000000   0.000000   0.045482   0.000000   0.000000   0.000000   0.000000 /data/mysqldata1/mysql/innodb_index_stats.ibd
  0.044966   0.042028   0.000000   0.000000   0.000000   0.000000   0.002706   0.000041   0.000054   0.000108   0.000029 /data/mysqldata1/test/example3.ibd
  0.021146   0.000000   0.000000   0.000000   0.000124   0.021022   0.000000   0.000000   0.000000   0.000000   0.000000 /data/mysqldata1/mysql-bin.000053
  0.016022   0.015486   0.000000   0.000000   0.000000   0.000000   0.000536   0.000000   0.000000   0.000000   0.000000 /data/mysqldata1/undo001
  0.005385   0.000000   0.000000   0.001927   0.000000   0.000000   0.003458   0.000000   0.000000   0.000000   0.000000 /data/mysqldata1/xb_doublewrite
  0.002102   0.000000   0.000000   0.000000   0.000000   0.000000   0.002102   0.000000   0.000000   0.000000   0.000000 /data/mysqldata1/ibdata1
  0.000714   0.000000   0.000000   0.000000   0.000000   0.000000   0.000714   0.000000   0.000000   0.000000   0.000000 /data/mysqldata1/mysql/innodb_table_stats.ibd
  0.000612   0.000000   0.000000   0.000000   0.000000   0.000000   0.000612   0.000000   0.000000   0.000000   0.000000 /data/mysqldata1/undo002
  0.000500   0.000050   0.000184   0.000000   0.000000   0.000000   0.000000   0.000076   0.000064   0.000126   0.000000 /data/mysqldata1/test/example3.frm
  0.000096   0.000000   0.000052   0.000000   0.000000   0.000000   0.000000   0.000028   0.000016   0.000000   0.000000 /dev/urandom
  0.000092   0.000000   0.000000   0.000000   0.000092   0.000000   0.000000   0.000000   0.000000   0.000000   0.000000 /data/mysqldata1/mysql_general.log

是不是很棒,列表中的数字的单位都是时间s(后面给大家介绍其他输出单位)。这些输出都是底层系统调用,我们一列一列的来看。

total:该列是对后面所有列相加得到的和。

read/write:read系统调用从文件描述符fd所代指的打开文件中读取/写入数据,通常会配合lseek系统调用来使用,首先使用lseek来定位偏移量,然后进行read/write操作。

ssize_t read(int fd, void *buf, size_t count);
ssize_t write(int fd, void *buf, size_t count);

pread/pwrite:

ssize_t pread(int fd, void *buf, size_t count, off_t offset);
ssize_t pwrite(int fd, const void *buf, size_t count, off_t offset);

该系统调用让我们在fd文件的offset处开始读取/写入,读取count个字节,并将这些数据放入*buf中,但是不改变文件文件的当前偏移量。  那么pread和read,pwrite和write有何区别呢?

xtra (1)

上图中我们假设文件偏移量刚开始敲好就在offset处,也就是说pread不改变文件原由的偏移量。那么write和pwrite的区别也是类似的,pwrite主要使用在多线程并发读写文件的场景,多个线程同时读写文件彼此不受影响。

fdatasync /fsync:

1.fsync=数据+元数据(属主,属组,文件权限文件大小,文件链接)
#include
int fsync(int fd);
fsync的功能是确保文件fd所有已修改的内容已经正确同步到硬盘上,该调用会阻塞等待直到设备报告IO完成。
除了同步文件的修改内容(脏页),fsync还会同步文件的描述信息(metadata,包括size、访问时间st_atime & st_mtime等等),因为文件的数据和metadata通常存在硬盘的不同地方,因此fsync至少需要两次IO写操作,变向随机IO.

2.fdatasync=数据
fdatasync,放宽了同步的语义以提高性能:
#include
int fdatasync(int fd);

fdatasync的功能与fsync类似,但是仅仅在必要的情况下才会同步metadata,因此可以减少一次IO写操作。举例来说,文件的尺寸 (st_size)如果变化,是需要立即同步的,否则OS一旦崩溃,即使文件的数据部分已同步,由于metadata没有同步,依然读不到修改的内容。而最后访问时间(atime)/修改时间(mtime)是不需要每次都同步的,只要应用程序对这两个时间戳没有苛刻的要求,基本无伤大雅。

open/lose/seek:这是最基本的三种文件系统调用,分别是openda打开文件描述符,close是关闭文件描述符,lseek是改变文件偏移量。这里不再赘述,毕竟不是讲系统编程.

fcntl:函数可以改变已打开的文件性质,较复杂,有兴趣可自行研究。

filename:对应的数据文件。

根据以上采集的信息,我们可以很快分析出数据库到底在哪部分造成了IO子系统瓶颈

2.常用配置

1.60s内数据库有IO活动的文件产生的各种系统调用次数
[ampmon@vq23ucmd02 ~]$ pt-ioprofile --profile-process=mysqld --run-time=60 --save-samples=/app/ampmon/mysql_ioprofile.txt --group-by=filename --cell=count --aggregate=sum
Sun Oct 23 14:14:33 CST 2016
Tracing process ID 16676
     total      pread       read     pwrite      write      fsync      lseek  ftruncate filename
     23164          0          0          0      11581          2      11581          0 /data/smp/mysql/data/master.info
     19917          0       3949          0      12018          1       3949          0 /data/smp/mysql/data/vq23ucmd02-relay-bin.000063
      3755          0        230          0        267          0       3173         85 /tmp/ML23MkEh
      2459          0          0          0       2459          0          0          0 /data/smp/mysql/data/mysql-bin.000021
      1667          0          0       1605          0         62          0          0 /data/smp/mysql/data/ib_logfile2
       659          0          0        327          0        332          0          0 /data/smp/mysql/data/ibdata1
       183          2          0          0          0        181          0          0 /data/smp/mysql/data/snc_amp/trends_uint.ibd
       171          3          0          0          0        168          0          0 /data/smp/mysql/data/snc_amp/history_uint.ibd
       121          0          0          0          0        121          0          0 /data/smp/mysql/data/snc_amp/history_str.ibd
        17          1          0          0          0         16          0          0 /data/smp/mysql/data/snc_amp/history.ibd
        15          0          0          0          0         15          0          0 /data/smp/mysql/data/snc_amp/events.ibd
        14          0          0          0          0         14          0          0 /data/smp/mysql/data/snc_amp/trends.ibd
         8          0          0          0          0          8          0          0 /data/smp/mysql/data/ib_logfile0
         7          0          0          0          0          7          0          0 /data/smp/mysql/data/snc_amp/item_discovery.ibd
         5          0          0          0          0          5          0          0 /data/smp/mysql/data/snc_amp/last_uint.ibd
         2          0          0          0          0          2          0          0 /data/smp/mysql/data/snc_amp/last.ibd
         2          0          0          0          0          2          0          0 /data/smp/mysql/data/snc_amp/items.ibd
         1          0          0          0          0          1          0          0 /data/smp/mysql/data/snc_amp/last_str.ibd
         1          0          0          0          0          1          0          0 /data/smp/mysql/data/snc_amp/hosts.ibd

2.60s内数据库中有IO活动的文件,各种系统调用平均每秒产生的数据量
[ampmon@vq23ucmd02 ~]$ pt-ioprofile --profile-process=mysqld --run-time=60 --save-samples=/app/ampmon/mysql_ioprofile.txt --group-by=filename --cell=sizes --aggregate=avg
Sun Oct 23 14:11:15 CST 2016
Tracing process ID 16676
     total      pread       read     pwrite      write      fsync      lseek  ftruncate filename
 115511329          0       3711          0        771          0  786756564          0 /data/smp/mysql/data/vq23ucmd02-relay-bin.000063
     16384      16384          0          0          0          0          0          0 /data/smp/mysql/data/snc_amp/history_uint.ibd
     16384      16384          0          0          0          0          0          0 /data/smp/mysql/data/snc_amp/history.ibd
     16384      16384          0          0          0          0          0          0 /data/smp/mysql/data/snc_amp/events.ibd
     13803          0          0      14444          0          0          0          0 /data/smp/mysql/data/ib_logfile2
      6501          0      26136          0      23221          0       3201          0 /tmp/ML23MkEh
      3816          0          0          0       3816          0          0          0 /data/smp/mysql/data/mysql-bin.000021
        64          0          0          0        130          0          0          0 /data/smp/mysql/data/master.info

以上两份信息我是从一个生产库的备库上采集的, 很显然,现在relay-log是系统中IO消耗最大部分。

更多组合请自行研究,解释下参数:

–aggregate:sum|avg。可以算平均值和总和

–cell:count|sizes:times。可以算系统调用次数,系统调用传输数据量,系统调用耗费的时间

–group-by:all|filename|pid。聚合方式,所有聚合在一起还是按照文件聚合

–profile-process:mysqld进程名

–run-time:采集时间

–save-samples:将输出保存到文件,供后续分析。