YAPC::Tokyo 2019 トークと資料まとめ

はじめに

YAPC::Tokyo 2019 トークと資料まとめたものです。

yapcjapan.org

トーク一覧

11:20 ~ 12:00

12:10 ~ 12:50

13:05 ~ 13:45

14:00 ~ 14:40

14:50 ~ 15:30

15:40 ~ 16:20

16:30 ~ 17:10

17:20 ~ 17:50

  • Lightning Talks (30min)
    • Shuya Motouchi
    • OGATA Tetsuji
    • aereal
    • 八雲アナグラ
    • 門松宏明 / note103
    • moznion

18:00 ~ 18:40

YAPC::Tokyo 2019に参加してきた。

はじめに

YAPC::Tokyo 2019に行ってきました\(◎o◎)/

普段業務で毎日Perl書いてて、一日1000行以上書くこともよくあるのに、初参加です。

yapcjapan.org

見たトーク

感想

全体的に学びが多くてよかった。 「OSSは良いぞ!!」みたいな話が多く、聞いてるだけでエンジニアとしてのモチベーションが上がった。

すぐ取り入れることができそうだと思ったのは、「CPAN Module Hacks」や「Dive into MySQL Error」で、内容もわかりやすく、基礎的な話が多く、特に初心者におすすめできる内容だった。

あと個人的には、大仲 能史さんの「Perl on Rails」も面白かった。PerlのプロジェクトにRubyの良いところ取り入れて、共存している感じが良くて、業務で使えそうだった。

@songmu さんの、多くのCPAN Authorに育てられ、息をするようにCPANモジュールを書けるようになり、そして分かったこと は、直接は聞けなかったけど、資料をみていて、聞いておけばよかったと後悔してます。。。

そして、最後の @tokuhirom さんのKeynoteもすごく良く、Perlのコミュニティがどう歩んできたか、といったような歴史やこれからのPerlのコミュニティの話などを聞くことができて、Perl書いてる人にとって、すごく刺激になって良かったです。

私は、他の大きいカンファレンスにあまり行ったことがないので、気のせいかもしれませんが、YAPCはすごくアットホームで、オープンな感じがして、資料などたくさん上がっているので、ぜひ参加出来なかった方も調べてみてください。

@kondoyuko さんのまとめおすすめです。 note.mu

おまけ

YAPC::Tokyo 2019 の前夜祭でLTしました。

凄い先輩や、@dankogai さんにもいいねして頂いてすごく嬉しかった。

いつかYAPCトークしたいな〜と思いました( ˘ω˘)

次は、DeNA TechCon 2019に参加しようかなと思ってます。

techcon.dena.com

DBIx::QueryLogを用いてN+1クエリを検知する

こんにちは @return520 です。 これはPerl Advent Calendar 2018 14日目の記事です。

昨日は takihito さんで、「チームで中規模Perlアプリケーションを開発する工夫 」でした。

はじめに

この記事では、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の %paramssql文が入ってるので、これを正規表現を用いて、同じテーブルが連続で何度も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万点を突破する方法」です。

Perl 5.28.0でのforループと文字列の連結の速度検証

試しに、qittaの記事をそのまま移してみる。 qiita.com

概要

Perl 5.28.0がリリースされ、いくつか機能が追加されました。 参考: http://d.hatena.ne.jp/perlcodesample/20180626/1529966283

その中で、

  • forループの高速化

  • 文字列連結の高速化

がどのくらい高速化されたのか気になったので調べてみました。

実行環境

MacBook Pro OS: macOS High Sierra プロセッサ: 2.5 GHz Intel Core i7 メモリ: 16 GB 1600 MHz DDR3

plenvで v5.18.2v5.26.0v5.28.0を切り替えてプログラムを実行します。

forループの高速化

こちらの記事で、 https://qiita.com/narita_cpp/items/543d55016d48a3baa5d5

@kfly8 さんのコメントを参考に作成しました。

実行コード

use strict;
use warnings;

use Benchmark qw/timethis/;

my $max   = 100000;
my @array = 1 .. $max;

timethis(
    1000,
    sub {
        for (@array) {
            ;
        }
    }
);

結果

v5.18.2

% perl for_spead_test.pl
timethis 1000:  2 wallclock secs ( 2.28 usr +  0.01 sys =  2.29 CPU) @ 436.68/s (n=1000)

% perl for_spead_test.pl
timethis 1000:  2 wallclock secs ( 2.31 usr +  0.00 sys =  2.31 CPU) @ 432.90/s (n=1000)

% perl for_spead_test.pl
timethis 1000:  2 wallclock secs ( 2.27 usr +  0.01 sys =  2.28 CPU) @ 438.60/s (n=1000)

% perl for_spead_test.pl
timethis 1000:  2 wallclock secs ( 2.28 usr +  0.01 sys =  2.29 CPU) @ 436.68/s (n=1000)

毎秒430回ほど実行できてるらしい。

v5.26.0

% perl for_spead_test.pl
timethis 1000:  2 wallclock secs ( 2.32 usr +  0.01 sys =  2.33 CPU) @ 429.18/s (n=1000)

% perl for_spead_test.pl
timethis 1000:  2 wallclock secs ( 2.30 usr +  0.00 sys =  2.30 CPU) @ 434.78/s (n=1000)

% perl for_spead_test.pl
timethis 1000:  2 wallclock secs ( 2.29 usr +  0.00 sys =  2.29 CPU) @ 436.68/s (n=1000)

% perl for_spead_test.pl
timethis 1000:  2 wallclock secs ( 2.28 usr +  0.00 sys =  2.28 CPU) @ 438.60/s (n=1000)

v5.18.2と変わらず430回ほど実行できてるらしい。

v5.28.0

% perl for_spead_test.pl
timethis 1000:  2 wallclock secs ( 1.81 usr +  0.00 sys =  1.81 CPU) @ 552.49/s (n=1000)

% perl for_spead_test.pl
timethis 1000:  2 wallclock secs ( 1.81 usr +  0.00 sys =  1.81 CPU) @ 552.49/s (n=1000)

% perl for_spead_test.pl
timethis 1000:  2 wallclock secs ( 1.78 usr +  0.00 sys =  1.78 CPU) @ 561.80/s (n=1000)

% perl for_spead_test.pl
timethis 1000:  2 wallclock secs ( 1.85 usr +  0.00 sys =  1.85 CPU) @ 540.54/s (n=1000)

今度は、毎秒550回ほど実行できてるらしい。

結果、 v5.18.2v5.26.0では速度は変わらず、 v5.28.0で1.2倍ほど速くなると言う結果になりました。

文字列の連結速度

こちらに書いてあるコードを参考にして、実行してみました。 http://d.hatena.ne.jp/perlcodesample/20180626/1529966283

実行コード

use strict;
use warnings;

use Benchmark qw/timethis/;

timethis(
    100,
    sub {
        my $s;
        my $a = "ab\x{100}cde";
        my $b = "fghij";
        my $c = "\x{101}klmn";

        for my $i (1..100_000) {
            $s = "\x{100}wxyz";
            $s .= "foo=$a bar=$b baz=$c";
        }
    },
);

結果

v5.18.2

% perl moji_spead_test.pl
timethis 100:  8 wallclock secs ( 7.29 usr +  0.00 sys =  7.29 CPU) @ 13.72/s (n=100)

% perl moji_spead_test.pl
timethis 100:  7 wallclock secs ( 7.23 usr +  0.00 sys =  7.23 CPU) @ 13.83/s (n=100)

% perl moji_spead_test.pl
timethis 100:  8 wallclock secs ( 7.38 usr +  0.01 sys =  7.39 CPU) @ 13.53/s (n=100)

% perl moji_spead_test.pl
timethis 100:  7 wallclock secs ( 7.26 usr +  0.00 sys =  7.26 CPU) @ 13.77/s (n=100)

毎秒13回ほど実行できてるらしい。

v5.26.0

% perl moji_spead_test.pl
timethis 100:  8 wallclock secs ( 7.13 usr +  0.01 sys =  7.14 CPU) @ 14.01/s (n=100)

% perl moji_spead_test.pl
timethis 100:  7 wallclock secs ( 7.33 usr +  0.02 sys =  7.35 CPU) @ 13.61/s (n=100)

% perl moji_spead_test.pl
timethis 100:  8 wallclock secs ( 7.35 usr +  0.01 sys =  7.36 CPU) @ 13.59/s (n=100)

% perl moji_spead_test.pl
timethis 100:  7 wallclock secs ( 7.23 usr +  0.01 sys =  7.24 CPU) @ 13.81/s (n=100)

v5.18.2と変わらず毎秒13回ほど実行できてるらしい。

v5.28.0

% perl moji_spead_test.pl
timethis 100:  1 wallclock secs ( 1.23 usr +  0.00 sys =  1.23 CPU) @ 81.30/s (n=100)

% perl moji_spead_test.pl
timethis 100:  1 wallclock secs ( 1.24 usr +  0.00 sys =  1.24 CPU) @ 80.65/s (n=100)

% perl moji_spead_test.pl
timethis 100:  1 wallclock secs ( 1.23 usr +  0.00 sys =  1.23 CPU) @ 81.30/s (n=100)

% perl moji_spead_test.pl
timethis 100:  1 wallclock secs ( 1.24 usr +  0.00 sys =  1.24 CPU) @ 80.65/s (n=100)

毎秒80回ほど実行できてるらしい。

結果、 v5.18.2v5.26.0では速度は変わらず、 v5.28.0で6倍ほど速くなると言う結果になりました。

検証結果

結果は以下の通りになりました。

  • forループは、約1.2倍高速化
  • 文字列連結は、約6倍高速化

ぜひともversion上げたいですね。