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ではこうした情報を表領域単位、ファイル単位、テーブル・インデックス単位で取得することができます。パフォーマンスチューニングのためにはぜひとも欲しい情報です。

方式案

いろいろ考えました。

1. MySQLにパッチを当てるとともに、プラグインを書いてINFORMATION_SCHEMAで情報を見られるようにする
   ⇒ 理想的ですが、主に私の技術力が足りません。
2. ptrace(2)でDisk I/O関連のシステムコールをフックする
   ⇒ 途中まで作っていたのですが、3番目の案を思いついたのでやめました。
3. SystemTapでDisk I/O関連のシステムコールを監視する
   ⇒ これでできそうな気がします。

SystemTapとは

SystemTapはLinuxカーネルの動作をモニタリングするツールです。概要については以下のIBM developerWorksの記事が参考になると思います。

• Linux のイントロスペクションと SystemTap (日本語)

あわせて、公式サイトのビギナーズガイドとリファレンスマニュアルもご参照ください。

• SystemTap Beginners Guide (英語)
• SystemTap Language Reference (英語)

CentOS 5の場合、SystemTapはディストリビューションに付属しています。ただし、追加でkernel-debuginfoとkernel-debuginfo-commonをインストールする必要があります。これらのパッケージは http://debuginfo.centos.org/ で配布されています。

SystemTapスクリプト

今回作成した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以外にもいろいろ応用が利きそうです。

今後の課題

とりあえずMySQLのパフォーマンスチューニングには使えそうなのですが、完璧を期すにはいくつか足りないところがあります。

• 他にも監視しなければならないシステムコールがある(io_submit(2)など)
• 実際の物理I/Oを見るには、もっと低いレイヤの関数を監視する必要がある

正直私はこれでいっぱいいっぱいなので、詳しい方に改良していただけるととてもうれしいです。