DBIx::ProfileManager で SQL Profiling

風邪を引きっぱなしで全然治らない山口です。恐らくネット上では zigorou と言うハンドルでご存知の方もいらっしゃるかもしれません。
まずは技術系のネタの第1弾です。

今回は実際にモバゲーオープンプラットフォームで用いている SQL Profiling の方法をご紹介致します。

DBI::Profile について

モバゲータウンではデータベースは MySQL を用いており、サーバーサイドプログラムから管理ツールまでのほとんどが Perl で書かれており、当然ながら DBI モジュールまたはそれを利用したモジュールを使って DB アクセスをしています。
今回、オープンプラットフォームチームで作った OpenSocial RESTful API ですが、モバゲータウン内のデータベースに大量にアクセスする為に日々どのようなクエリが実行され、どれくらいの実行時間が掛かっているかは常に気になる所です。

色んなやり方が考えられるのですが、DBI::Profile と言う DBI 付属のモジュールがあり、これは DBI の内部で Profile を取ってくれるので、後付け的に Profile を明示的に取るよりもこの枠組みを使った方が簡単かなと思い利用する事にしてみました。

DBI::Profile モジュールは pod を見てみると分かりますが、大体次のように使います。


#!/usr/bin/perl
use strict;
use warnings;
use DBI;
use DBI::Profile;
$DBI::Profile::ON_DESTROY_DUMP = undef;
my $dbh = DBI->connect(“dbi:mysql:db=platform;”, “root”, “”, +{ RaiseError => 1, AutoCommit => 0, ShowErrorStatement => 1, PrintError => 1, PrintWarn => 0, });
$dbh->{Profile} = q|!Statement|;
$dbh->selectall_arrayref(“SELECT * FROM app_owner WHERE owner_id = ?”, undef, $_) for ( qw/10045 10046 10047/ );
print $dbh->{Profile}->format;

DBI::Profile の利用例

これを実行すると例えば、

DBI::Profile: 0.011575s 98.48% (6 calls) dbi_profile.pl @ 2010-03-11 19:25:23
'SELECT * FROM app_owner WHERE owner_id = ?' =>
    0.011575s / 6 = 0.001929s avg (first 0.004611s, min 0.000003s, max 0.004611s)

DBI::Profile の実行結果サンプル

のような出力になります。

0.011575s / 6 にある 6 ですがこれは実行回数です。ソース上では3回しか実行していないように見えるのですが何故 6 になるかと言うと $dbh->{Profile} = '!Statement:!MethodClass' とすると分かります。

DBI::Profile: 0.012108s 98.03% (6 calls) dbi_profile.pl @ 2010-03-11 19:30:45
'SELECT * FROM app_owner WHERE owner_id = ?' =>
    'DBD::mysql::db::selectall_arrayref' =>
        0.012070s / 3 = 0.004023s avg (first 0.004822s, min 0.003588s, max 0.004822s)
    'DBD::mysql::st::DESTROY' =>
        0.000038s / 3 = 0.000013s avg (first 0.000020s, min 0.000008s, max 0.000020s)

!Statement:!MethodClass と設定した場合の実行結果

内部的には DBI::db, DBI::st などのメソッド単位でプロファイルを取っている事が分かります。DESTROY のようなメソッドで掛かった時間は余り興味が無いのと、モバゲータウンでは用途ごとにデータベースを分割しており複数の接続先を持つ事から

複数のデータベースハンドルにいちいち Profile の設定をするのではなくて、ここからここまでと言った具合でプロファイル対象としたい
プロファイルデータをハンドルごとに分けて、尚かつ再利用可能なように構造化されたデータとしたい
必要なプロファイルデータのみを抽出しやすいデータ形式としたい
プロファイルデータを好きなフォーマットで出力したい

といった事柄を満たす物があると良いなと思い早速 DBIx::ProfileManager と言うモジュールを作ってみました。現在のバージョンは 0.03 です。先ほど CPAN に upload したばかりなのでまだ 0.03 は反映されていないかもしれません。開発自体は github でやっています。

DBIx::ProfileManager の使い方

やはりエンジニアならばソースコードから見た方が話が早いと思うので先に利用例を書いてしまいます。まず下記のようなテーブルがある前提とします。


USE platform_users;
CREATE TABLE people (
id bigint(20) NOT NULL AUTO_INCREMENT,
nickname varchar(32) NOT NULL DEFAULT ‘’,
created_on datetime NOT NULL,
updated_on datetime NOT NULL,
PRIMARY KEY (id)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;
USE platform_friends;
CREATE TABLE friends (
id bigint(20) NOT NULL AUTO_INCREMENT,
friend_id bigint(20) NOT NULL,
created_on datetime NOT NULL,
updated_on datetime NOT NULL,
PRIMARY KEY (id,friend_id)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

データベース定義

次に上記のテーブルにアクセスするコードとそれに Profile を適用するサンプルが下記になります。ちょっと長いです＾＾；


#!/usr/bin/perl
use strict;
use warnings;
use Carp;
use Data::Dump qw(dump);
use DBI;
use DBI::Profile;
use DBIx::ProfileManager;
use SQL::Abstract;
use SQL::Abstract::Plugin::InsertMulti;
use String::Random qw(random_regex);
$\                             = “\n”;
$,                             = “\n”;
$DBI::Profile::ON_DESTROY_DUMP = undef;
my $pm = DBIx::ProfileManager->new( config => ‘!Statement:!MethodClass’ );
$pm->profile_start;
my $dbh_users = DBI->connect(
‘dbi:mysql:db=platform_users’,
‘root’, ‘’,
+{
AutoCommit         => 0,
RaiseError         => 1,
ShowErrorStatement => 1,
PrintWarn          => 0,
PrintError         => 0,
}
);
my $dbh_friends = DBI->connect(
‘dbi:mysql:db=platform_friends’,
‘root’, ‘’,
+{
AutoCommit         => 0,
RaiseError         => 1,
ShowErrorStatement => 1,
PrintWarn          => 0,
PrintError         => 0,
}
);
my @users;
for ( 1 .. 3000 ) {
push(
@users,
+{
nickname   => random_regex('[A-Za-z0-9]{8,12}'),
created_on => 'NOW()',
updated_on => 'NOW()',
}
);
}
print “insert users”;
insert_users( $dbh_users, @users, +{ offset => 0, limit => 1000 } );
print “bulk insert users (10)";
bulk_insert_users( $dbh_users, @users,
+{ offset => 1000, limit => 1000, bulk_insert => 10 } );
print “bulk insert users (100)";
bulk_insert_users( $dbh_users, @users,
+{ offset => 2000, limit => 1000, bulk_insert => 100 } );
print “bulk insert friends”;
bulk_insert_friends( $dbh_friends, 3000 );
print “select friends”;
select_friends( $dbh_users, $dbh_friends, 3000 );
$pm->profile_stop;
print $pm->data_formatted(
‘%{statement} (%{method_class}, %{dsn}) %{total}s / %{count} = %{avg}s avg (first %{first}s, min %{min}s, max %{max}s)’,
(
grep {
$->{statement}
&& $->{method_class} =~ m/(?:select|fetch|do|execute)/
} $pm->data_structured
),
);
sub insert_users {
my ( $dbh, $users, $opts ) = @_;
my $sql = SQL::Abstract->new;
my ( $stmt, @bind );

my @users_copy = @$users;
@users_copy = splice( @users_copy, $opts->{offset}, $opts->{limit} );

eval {
    for my $user (@users_copy)
    {
        ( $stmt, @bind ) = $sql->insert( 'people', $user );
        $dbh->do( $stmt, undef, @bind ) or croak( $dbh->errstr );
    }
    $dbh->commit or croak( $dbh->errstr );
};
if ($@) {
    my $e = $@;
    eval { $dbh->rollback; };
    carp $e;
}

}
sub bulk_insert_users {
my ( $dbh, $users, $opts ) = @_;
my $sql = SQL::Abstract->new;
my ( $stmt, @bind );

my @users_copy = @$users;
my @users_tmp;

@users_copy = splice( @users_copy, $opts->{offset}, $opts->{limit} );
eval {
    while (
        ( @users_tmp = splice( @users_copy, 0, $opts->{bulk_insert} ) ) >
        0 )
    {
        ( $stmt, @bind ) = $sql->insert_multi( 'people', \@users_tmp );
        $dbh->do( $stmt, undef, @bind ) or croak( $dbh->errstr );
    }
    $dbh->commit or croak( $dbh->errstr );
};
if ($@) {
    my $e = $@;
    eval { $dbh->rollback; };
    carp $e;
}

}
sub bulk_insert_friends {
my ( $dbh, $max_id ) = @_;
my @friends;
my $sql = SQL::Abstract->new;
my ( $stmt, @bind );

for my $id ( 1 .. $max_id - 1 ) {
    my $ratio = ( $id % 3 + 1 ) * 0.002;
    my @target = grep { rand 1 > 1 - $ratio } ( $id + 1 .. $max_id );

    push(
        @friends,
        map {
            (
                +{
                    id         => $id,
                    friend_id  => $_,
                    created_on => \'NOW()',
                    updated_on => \'NOW()'
                },
                +{
                    id         => $_,
                    friend_id  => $id,
                    created_on => \'NOW()',
                    updated_on => \'NOW()'
                }
              )
          } @target
    );

    my @friends_tmp;

    eval {
        while ( ( @friends_tmp = splice( @friends, 0, 100 ) ) > 0 )
        {
            ( $stmt, @bind ) =
              $sql->insert_multi( 'friends', \@friends_tmp );
            $dbh->do( $stmt, undef, @bind ) or croak( $dbh->errstr );
        }

        $dbh->commit or croak( $dbh->errstr );
    };
    if ($@) {
        my $e = $@;
        eval { $dbh->rollback; };
        carp $e;
    }
}

}
sub select_friends {
my ( $dbh_users, $dbh_friends, $max_id ) = @_;
my $sql = SQL::Abstract->new;
my ($stmt, @bind);

for ( 1 .. $max_id ) {
    ($stmt, @bind) = $sql->select( 'friends', [ qw/friend_id/ ], +{ id => $_ } );
    my @friend_ids = map { $_->[0] } @{$dbh_friends->selectall_arrayref( $stmt, undef, @bind )};

    next if (@friend_ids == 0);

    ($stmt, @bind) = $sql->select(
        'people',
        [qw/id nickname/],
        +{
            id => +{ IN => \@friend_ids }
        }
    );

    my @users = $dbh_users->selectall_arrayref( $stmt, undef, @bind );
}

}

DBIx::ProfileManager の利用例

中身はともかくして、$pm->profile_start や $pm->profile_stop とやっている部分の内側がプロファイルの対象となります。実際にこのプログラムの実行結果は次のようになります。(一部省略)

...
INSERT INTO friends ( created_on, friend_id, id, updated_on ) VALUES ( NOW(), ?, ?, NOW() ), ( NOW(), ?, ?, NOW() ), ( NOW(), ?, ?, NOW() ), ( NOW(), ?, ?, NOW() ), ( NOW(), ?, ?, NOW() ), ( NOW(), ?, ?, NOW() ), ( NOW(), ?, ?, NOW() ), ( NOW(), ?, ?, NOW() ), ( NOW(), ?, ?, NOW() ), ( NOW(), ?, ?, NOW() ), ( NOW(), ?, ?, NOW() ), ( NOW(), ?, ?, NOW() ), ( NOW(), ?, ?, NOW() ), ( NOW(), ?, ?, NOW() ), ( NOW(), ?, ?, NOW() ), ( NOW(), ?, ?, NOW() ), ( NOW(), ?, ?, NOW() ), ( NOW(), ?, ?, NOW() ), ( NOW(), ?, ?, NOW() ), ( NOW(), ?, ?, NOW() ) (DBD::mysql::db::do, dbi:mysql:db=platform_users) 0.0831961631774902s / 110 = 0.000756328756159002s avg (first 0.000993967056274414s, min 0.000515937805175781s, max 0.00301384925842285s)
...
SELECT id, nickname FROM people WHERE ( id IN ( ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ? ) ) (DBD::mysql::db::selectall_arrayref, dbi:mysql:db=platform_users) 0.0953891277313232s / 260 = 0.000366881260505089s avg (first 0.00031590461730957s, min 0.000281810760498047s, max 0.00636410713195801s)
SELECT id, nickname FROM people WHERE ( id IN ( ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ? ) ) (DBD::mysql::db::selectall_arrayref, dbi:mysql:db=platform_users) 0.000848054885864258s / 2 = 0.000424027442932129s avg (first 0.000418901443481445s, min 0.000418901443481445s, max 0.000429153442382812s)
...
INSERT INTO people ( created_on, nickname, updated_on ) VALUES ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ) (DBD::mysql::db::do, dbi:mysql:db=platform_users) 0.0476808547973633s / 100 = 0.000476808547973633s avg (first 0.000421047210693359s, min 0.000266790390014648s, max 0.0036921501159668s)
INSERT INTO people ( created_on, nickname, updated_on) VALUES ( NOW(), ?, NOW() ) (DBD::mysql::db::do, dbi:mysql:db=platform_users) 0.176061868667603s / 1000 = 0.000176061868667603s avg (first 0.000382900238037109s, min 0.000118017196655273s, max 0.00446701049804688s)
INSERT INTO people ( created_on, nickname, updated_on ) VALUES ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ), ( NOW(), ?, NOW() ) (DBD::mysql::db::do, dbi:mysql:db=platform_users) 0.0217092037200928s / 10 = 0.00217092037200928s avg (first 0.00223302841186523s, min 0.00193119049072266s, max 0.00232481956481934s)

出力結果

この出力形式は formatter を提供しているので好きに設定出来ます。詳しくは pod をご覧下さい。

ちなみに最後の3行は people テーブルに 1000 件のレコードを1, 10, 100件ずつ insert した際のプロファイルデータになります。

1件ずつ: 0.176061868667603s / 1000 (トータル実行時間/実行回数)
10件ずつ: 0.0476808547973633s / 100
100件ずつ: 0.0217092037200928s / 10

当然ながら100件ずつ bulk insert した方が圧倒的に速いと言う事が読み取れます。

このように既存のプログラムにちょっと手を加えるだけで SQL Profiling が出来ます。Catalyst みたいな WAF であれば MyApp->prepare_request, MyApp->finalize 辺りに引っ掛けて実行しても良いでしょう。是非試してみて下さい。

ちなみにモバゲーオープンプラットフォームの API では 0.1 % の確率でプロファイルを取る事にしています。来週3/16のDeNA Technology Seminar #1 ではこのような話も含めてプラットフォーム開発の内側についてお話する予定です。ご参加予定の方は忘れずにお越し下さい。
また都合で来られなくなってしまった方がいらっしゃいましたら atnd で参加をキャンセルして頂きますようお願い致します。キャンセル待ちの方は今一度 atnd のページをチェックしてみて下さい。
また参加出来なかった方の為に ust で配信予定です。こちらもお楽しみに。

DBI::Profile について

DBIx::ProfileManager の使い方

related articles