はじめに

この記事では、DBIx::QueryLogを用いてN+1クエリを検知するプログラムを作ってみようと思います。

以下の順番で説明していきます。

DBIx::QueryLogとは
DBIx::QueryLogでログ任意のタイミングで出力する
DBIx::QueryLogでN+1クエリを検知する

DBIx::QueryLogとは

DBIx::QueryLogとは、発行されたクエリのログを出力することができる便利なモジュールです。

metacpan.org

例えば次のプログラムのようにuseするだけでログを出力することができます。

┣ main.pl
┗ DB
  ┗ DB::User.pm

# main.pl
use strict;
use warnings;
use utf8;

use DB::User;

use DBIx::QueryLog;

my $result = DB::User->select_user;

# DB::User.pm
package DB::User;

use utf8;
use warnings;
use strict;

use DBI;

sub dbh {
    my $dsn = "dbi:mysql:database=Test;host=Localhost;port=3306";
    my $user = "root";
    my $pass ="";

    my $dbh = DBI->connect( $dsn, $user, $pass, {}) || die $DBI::errstr;
    return $dbh;
}

sub select_user {
    my $class = shift;
    return $class->dbh->selectall_arrayref("select * from user where id = 1");
}

1;

実行すると以下のように、query logが出力されます。

$ perl main.pl
[2018-12-01T16:11:10] [DB::User] [0.000409] select * from user where id = 1 at DB/User.pm line 20

DBIx::QueryLogでログ任意のタイミングで出力する

DBIx::QueryLogはuseするだけでログを出力することができて便利なのですが、実際の本番環境で常にログを出力し続けるのは、処理コストが掛かってしまいます。

ですので、開発環境で任意のタイミングで使用できるようなLogeerモジュールを作成してみます。

DBIx::QueryLogは Log::Dispach で作成したclassをsetすることができますので、これを使用します。

logger Sets a logger class (e.g. Log::Dispach)

The logger class must have a log method, which should work like the one of Log::Dispatch (but see also OUTPUT section below).

DBIx::QueryLog->logger($logger);

┣ main.pl
┣ Logger.pm
┗ DB
  ┗ DB::User.pm

# Logger.pm
package Logger {
    use strict;
    use warnings;
    use utf8;

    use DBIx::QueryLog ();
    use Log::Dispatch;

    sub enable {
        my ($class) = @_;

        my $logger = Log::Dispatch->new(
            outputs => [
                ['+My::Logger', min_level => 'debug'],
            ],
        );

        DBIx::QueryLog->logger($logger);
        DBIx::QueryLog->enable();
    }

    1;
}

package My::Logger {
    use strict;
    use warnings;
    use utf8;
    use parent qw(Log::Dispatch::Output);

    {
        no warnings 'redefine';
        sub new {
            my ($class, %params) = @_;
            my $self = bless {} => $class;

            $self->_basic_init(%params);
            return $self;
        }
    }

    {
        no warnings 'redefine';
        sub log_message {
            my ($self, %params) = @_;
            warn $params{message};
        }
    }

    1;
}

# main.pl
use strict;
use warnings;
use utf8;

use DB::User;

use Logger;
Logger->enable;

my $result = DB::User->select_user;

これを実行すると以下のようになり、独自のloggerを作成することができたことを確認することができます。

$ perl main.pl
[2018-12-01T16:35:10] [DB::User] [0.000375] select * from user where id = 1 at DB/User.pm line 20

DBIx::QueryLogでN+1クエリを検知する

独自のloggerを作成することができましたので、次はN+1クエリを検知できるようにしてみようと思います。

Logger.pm内のMy::LoggerにN+1を検知するメソッドを作成します。

検知の方法は、log_messageの %params にsql文が入ってるので、これを正規表現を用いて、同じテーブルが連続で何度もselectされたときにwarningを出力させます。

# Logger.pm
package Logger {
    ...
}

package My::Logger {
    use parent qw(Log::Dispatch::Output);
    use strict;
    use warnings;
    use utf8;

    my $before_table = '';
    my $count = 0;

    {
        no warnings 'redefine';
        sub new {
            my ($class, %params) = @_;
            my $self = bless {} => $class;

            $self->_basic_init(%params);
            return $self;
        }
    }

    {
        no warnings 'redefine';
        sub log_message {
            my ($self, %params) = @_;

            _check_n1_query($params{params}->{sql});

            warn $params{message};
        }
    }

    sub _check_n1_query {
        my $sql = shift;

        # 正規表現でselectされたテーブルをチェックする
        if ($sql =~ /^(select).*(from)\s([a-z]+)\s(where)/) {
            my $table = $3;

            if ($table eq $before_table) {
                $count++;

                if ($count >= 10) {
                    warn '****************************';
                    warn '*** warnings N + 1 query ***';
                    warn '****************************';
                }
                return;
            }

            $before_table = $table;
        }
    }

    1;
}

# main.pl
use strict;
use warnings;
use utf8;

use DB::User;

use Logger;
Logger->enable;

for (1..11) {
    my $result = DB::User->select_user;
}

これを実行すると以下ようにN+1クエリを検知することができます。

$perl main.pl
[2018-12-01T17:11:05] [DB::User] [0.000321] select * from user where id = 1 at DB/User.pm line 20
[2018-12-01T17:11:05] [DB::User] [0.000266] select * from user where id = 1 at DB/User.pm line 20
[2018-12-01T17:11:05] [DB::User] [0.000254] select * from user where id = 1 at DB/User.pm line 20
[2018-12-01T17:11:05] [DB::User] [0.000248] select * from user where id = 1 at DB/User.pm line 20
[2018-12-01T17:11:05] [DB::User] [0.000225] select * from user where id = 1 at DB/User.pm line 20
[2018-12-01T17:11:05] [DB::User] [0.000216] select * from user where id = 1 at DB/User.pm line 20
[2018-12-01T17:11:05] [DB::User] [0.000207] select * from user where id = 1 at DB/User.pm line 20
[2018-12-01T17:11:05] [DB::User] [0.000210] select * from user where id = 1 at DB/User.pm line 20
[2018-12-01T17:11:05] [DB::User] [0.000209] select * from user where id = 1 at DB/User.pm line 20
[2018-12-01T17:11:05] [DB::User] [0.000206] select * from user where id = 1 at DB/User.pm line 20
**************************** at Logger.pm line 66.
*** warnings N + 1 query *** at Logger.pm line 67.
**************************** at Logger.pm line 68.

最後に

いかがでしたか。

今回はDBIx::QueryLogを使用しましたが、DBIx::Tracer などを用いるともっと簡単に実装できると思います。

明日は @karupanerura さんで「ISUCON8予選問題においてPerl実装で25万点を突破する方法」です。