2013年4月アーカイブ

dannさんが以前Catalystでやってたのを参考に、Plack/PSGIアプリケーションのメモリリークを Devel::Leak::Object で調べる方法

plackup を -MDevel::Leak::Object 付けて起動

$ plackup -MDevel::Leak::Object=GLOBAL_bless -e '$Devel::Leak::Object::TRACKSOURCELINES = 1' -s Starlet --max-workers=1 app.psgi

-e ‘$Devel::Leak::Object::TRACKSOURCELINES = 1’ を付けると行数まで出力してくれる

app.psgiはこんなの

sub {
   my $env = shift;
   my $ref;$ref = bless \$ref, 'XXX';
   [200,['Content-Type'=>'text/html'],["OK"]];
};

Starletの —max-reqs-per-child のデフォルトは 100 なので、ab使って100回アクセス。

$ ab -n 100 http://localhost:5000/

すると、plackupを起動したコンソールの最後に、

...
127.0.0.1 - - [18/Apr/2013:17:21:17 +0900] "GET / HTTP/1.0" 200 2 "-" "ApacheBench/2.3"
127.0.0.1 - - [18/Apr/2013:17:21:17 +0900] "GET / HTTP/1.0" 200 2 "-" "ApacheBench/2.3"
127.0.0.1 - - [18/Apr/2013:17:21:17 +0900] "GET / HTTP/1.0" 200 2 "-" "ApacheBench/2.3"
Tracked objects by class:
    Config                                   1
    Errno                                    1
    POSIX::SigRt                             1
    XXX                                      100

Sources of leaks:
Config
     1 from /path/to/perl5/perlbrew/perls/perl-5.16/lib/5.16.3/darwin-2level/Config.pm line: 73
Errno
     1 from /path/to/perl5/perlbrew/perls/perl-5.16/lib/5.16.3/darwin-2level/Errno.pm line: 167
POSIX::SigRt
     1 from /path/to/perl5/perlbrew/perls/perl-5.16/lib/5.16.3/Tie/Hash.pm line: 246
XXX
   100 from /path/to/Desktop/app.psgi line: 3

とでます。これで XXX があやちいことがわかりましたね

Plack-1.0023 から Plack::Middleware::AccessLog が Apache::LogFormat::Compiler を使うようになって、アクセスログの出力が速くなりました。

これまでの PM::AccessLog はリクエストの度に ログフォーマットの文字列を正規表現でパース、必要なメソッドを呼び出してアクセスログを生成していましたが、ALFCは初期化フェーズで ログフォーマットの文字列を1つのperlのコードに変換してしまうので、低コストでログを生成することができます。

以下ベンチマーク結果。アクセスログを有効にしただけのHello Worldだと、1.5倍くらい早くなる模様。memcachedに数回リクエストを送るだけのアプリケーションならプロダクション環境でも効果があるんじゃないでしょうか。ちなみにサーバを介さないベンチマークだと6倍ぐらい高速になってました

Benchmarks

HelloWorld.psgi

use Plack::Builder;
builder {
    enable 'AccessLog', logger => sub { };
    sub { [200, ['Content-Type'=>'text/plain','Content-Length'=>11],['Hello World']] }
};

Setup

Plack-1.0022

$ cat cpanfile
requires 'Plack', '== 1.0022';
requires 'Starlet';
requires 'HTTP::Parser::XS';
$ carton install
$ carton exec -- -- plackup -s Starlet -E production --max-workers=10 --max-reqs-per-child=10000 -a HelloWorld.psgi

Plack-1.0023

$ cat cpanfile
requires 'Plack', '== 1.0023';
requires 'Starlet';
requires 'HTTP::Parser::XS';
$ carton install
$ carton exec -- -- plackup -s Starlet -E production --max-workers=10 --max-reqs-per-child=10000 -a HelloWorld.psgi

ApacheBench Options

$ ab -c 8 -n 50000 http://localhost:5000/

Result

Plack-1.0022

Concurrency Level:      8
Time taken for tests:   4.201 seconds
Complete requests:      50000
Failed requests:        0
Write errors:           0
Total transferred:      7300146 bytes
HTML transferred:       550011 bytes
Requests per second:    11900.85 [#/sec] (mean)
Time per request:       0.672 [ms] (mean)
Time per request:       0.084 [ms] (mean, across all concurrent requests)
Transfer rate:          1696.84 [Kbytes/sec] received

Plack-1.0023

Concurrency Level:      8
Time taken for tests:   2.864 seconds
Complete requests:      50000
Failed requests:        0
Write errors:           0
Total transferred:      7300146 bytes
HTML transferred:       550011 bytes
Requests per second:    17460.12 [#/sec] (mean)
Time per request:       0.458 [ms] (mean)
Time per request:       0.057 [ms] (mean, across all concurrent requests)
Transfer rate:          2489.48 [Kbytes/sec] received

これが出た事でAxsLogに「高速」というアドバンテージがなくなった。PODを書き直さないと！