SystemTapでMySQLのDisk I/Oを分析する
実験エントリです。
動機
OracleのStatspack/AWRで取れるファイル単位のDisk I/O情報を、MySQLでも採取したい。これは次に示すようなデータです。
File IO Stats DB/Inst: ORA112/ORA112 Snaps: 6-7
->Mx Rd Bkt: Max bucket time for single block read
->ordered by Tablespace, File
Tablespace Filename
------------------------ ----------------------------------------------------
Av Mx Av
Av Rd Rd Av Av Buffer BufWt
Reads Reads/s (ms) Bkt Blks/Rd Writes Writes/s Waits (ms)
-------------- ------- ----- --- ------- ------------ -------- ---------- ------
SYSAUX /opt/oracle/oradata/ORA112/sysaux01.dbf
48 1 8.5 ### 2.0 37 0 0
SYSTEM /opt/oracle/oradata/ORA112/system01.dbf
47 1 8.1 32 1.0 9 0 0
UNDOTBS1 /opt/oracle/oradata/ORA112/undotbs01.dbf
2 0 40.0 ### 1.0 13 0 0
USERS /opt/oracle/oradata/ORA112/users01.dbf
4,358 57 48.9 ### 1.9 5 0 8 15.0
-------------------------------------------------------------Oracleではこうした情報を表領域単位、ファイル単位、テーブル・インデックス単位で取得することができます。パフォーマンスチューニングのためにはぜひとも欲しい情報です。
方式案
いろいろ考えました。
SystemTapとは
SystemTapはLinuxカーネルの動作をモニタリングするツールです。概要については以下のIBM developerWorksの記事が参考になると思います。
あわせて、公式サイトのビギナーズガイドとリファレンスマニュアルもご参照ください。
CentOS 5の場合、SystemTapはディストリビューションに付属しています。ただし、追加でkernel-debuginfoとkernel-debuginfo-commonをインストールする必要があります。これらのパッケージは http://debuginfo.centos.org/ で配布されています。
SystemTapスクリプト
global PROCNAME = "mysqld" global fds probe begin { printf("start\n") } probe syscall.read, syscall.pread { if (execname() == PROCNAME) { fds[pid(), tid()] = fd } } probe syscall.read.return, syscall.pread.return { if (execname() == PROCNAME && $return != -1) { printf("read\t%d\t%d\t%d\n", pid(), fds[pid(), tid()], $return) } } probe syscall.write, syscall.pwrite { if (execname() == PROCNAME) { fds[pid(), tid()] = fd } } probe syscall.write.return, syscall.pwrite.return { if (execname() == PROCNAME && $return != -1) { printf("write\t%d\t%d\t%d\n", pid(), fds[pid(), tid()], $return) } } probe syscall.close { if (execname() == PROCNAME) { printf("close\t%d\t%d\n", pid(), fd) } } probe timer.s(5) { printf("print\n") }
これはread(2)、pread(2)、write(2)、pwrite(2)を監視してプロセスID、ファイルディスクリプタ、読み書きしたバイト数を標準出力にダンプするスクリプトです。その際ログが大量に出力されるのを防ぐため、監視対象をmysqldプロセスに限定しています。
Perlスクリプト
SystemTapだけではどうしても処理を完結できなかったので、補助的にPerlを使いました。次に示すスクリプトで出力結果の集計を行います。
#!/usr/bin/perl use strict; use warnings; my (%file, $flag, %entry, %reads, %writes, %rbytes, %wbytes, $interval); $flag = 0; $interval = 5; while (my $line = <>) { chomp($line); my ($call, $pid, $fd, $size) = split(/\t/, $line); if (($call eq 'read') or ($call eq 'write')) { if (!defined($file{"$pid,$fd"})) { $file{"$pid,$fd"} = readlink("/proc/$pid/fd/$fd") or next; } my $f = $file{"$pid,$fd"}; if (substr($f, 0, 1) eq '/') { $flag = 1; $entry{$f} = 1; if ($call eq 'read') { $reads{$f}++; $rbytes{$f} += $size; } elsif ($call eq 'write') { $writes{$f}++; $wbytes{$f} += $size; } } } elsif ($call eq 'close') { if (defined($file{"$pid,$fd"})) { delete($file{"$pid,$fd"}); } } elsif ($call eq 'print') { if ($flag == 1) { my ($sec, $min, $hour, $day, $mon, $year) = localtime(); printf "\n%04d-%02d-%02d %02d:%02d:%02d\n", $year + 1900, $mon + 1, $day, $hour, $min, $sec; print " r/s w/s rKB/s wKB/s file\n"; foreach my $f (sort keys %entry) { printf "%7.1f %7.1f %8.1f %8.1f %s\n", defined($reads{$f}) ? $reads{$f} / $interval : 0, defined($writes{$f}) ? $writes{$f} / $interval : 0, defined($rbytes{$f}) ? $rbytes{$f} / $interval / 1024 : 0, defined($wbytes{$f}) ? $wbytes{$f} / $interval / 1024 : 0, $f; } $flag = 0; %entry = %reads = %writes = %rbytes = %wbytes = (); } } else { print "$call\n"; } }
実行例
SystemTapはrootユーザで実行します。MySQLでInnoDBを利用している場合は、innodb_file_per_tableを有効にしてテーブルごとにファイルを分けておくことをおすすめします。試しにTPC-Bのトランザクションを実行してみたところ、以下の結果を得ることができました。
# stap mysql.stp | perl mysqltap.pl
start
2010-01-20 03:34:27
r/s w/s rKB/s wKB/s file
0.0 20.8 0.0 23.1 /var/lib/mysql/ib_logfile0
1.4 0.0 22.4 0.0 /var/lib/mysql/ibdata1
16.4 0.0 262.4 0.0 /var/lib/mysql/tpcb/accounts.ibd
0.6 0.0 9.6 0.0 /var/lib/mysql/tpcb/branches.ibd
0.0 0.6 0.0 22.4 /var/lib/mysql/tpcb/history.ibd
0.6 0.0 9.6 0.0 /var/lib/mysql/tpcb/tellers.ibd
2010-01-20 03:34:32
r/s w/s rKB/s wKB/s file
0.0 78.8 0.0 84.0 /var/lib/mysql/ib_logfile0
62.0 0.0 992.0 0.0 /var/lib/mysql/tpcb/accounts.ibd
0.0 0.2 0.0 6.4 /var/lib/mysql/tpcb/history.ibd
2010-01-20 03:34:37
r/s w/s rKB/s wKB/s file
0.0 80.0 0.0 84.1 /var/lib/mysql/ib_logfile0
0.2 1.0 3.2 176.0 /var/lib/mysql/ibdata1
59.6 0.0 953.6 0.0 /var/lib/mysql/tpcb/accounts.ibd
0.0 0.6 0.0 35.2 /var/lib/mysql/tpcb/history.ibd
2010-01-20 03:34:42
r/s w/s rKB/s wKB/s file
0.0 80.6 0.0 81.8 /var/lib/mysql/ib_logfile0
61.4 0.0 982.4 0.0 /var/lib/mysql/tpcb/accounts.ibd
0.0 0.4 0.0 6.4 /var/lib/mysql/tpcb/history.ibd
2010-01-20 03:34:47
r/s w/s rKB/s wKB/s file
0.0 52.6 0.0 56.3 /var/lib/mysql/ib_logfile0
0.0 1.8 0.0 1120.0 /var/lib/mysql/ibdata1
41.8 33.0 668.8 662.4 /var/lib/mysql/tpcb/accounts.ibd
0.0 0.2 0.0 3.2 /var/lib/mysql/tpcb/branches.ibd
0.0 0.2 0.0 3.2 /var/lib/mysql/tpcb/history.ibd
0.0 0.2 0.0 3.2 /var/lib/mysql/tpcb/tellers.ibd
2010-01-20 03:34:52
r/s w/s rKB/s wKB/s file
0.0 1.4 0.0 0.7 /var/lib/mysql/ib_logfile0
0.0 5.4 0.0 3769.6 /var/lib/mysql/ibdata1
0.0 204.8 0.0 4009.6 /var/lib/mysql/tpcb/accounts.ibd
0.0 0.6 0.0 25.6 /var/lib/mysql/tpcb/history.ibdいかがでしょう。MySQLが何をしていてどこに負荷がかかっているのか、一目瞭然ですね！
また、要するにこれはiostatをファイル単位で見られるようなものですから、MySQL以外にもいろいろ応用が利きそうです。
