Catalystのオーバーヘッド～Catalyst::Engine::FastCGI

投稿者：kounoike　日付：月, 2005-11-07 02:02 Catalyst | fastcgi | Perl

Catalyst::Engine::FastCGIでHelperが出力したものをそのまんま動かしたときのDProfを取ってみた。 lighttpdからFastCGIをcallし，ab2 -k -c 1 -n 10000した。まずはそのab2の結果。ちなみにlighttpd/1.4.7のCatalyst-5.33上での結果。


Server Software:        lighttpd/1.4.7
Server Hostname:        localhost
Server Port:            8080
Document Path:          /fcgi/ctest.fcgi
Document Length:        48 bytes
Concurrency Level:      1
Time taken for tests:   43.469302 seconds
Complete requests:      10000
Failed requests:        0
Write errors:           0
Keep-Alive requests:    9412
Total transferred:      1717060 bytes
HTML transferred:       480000 bytes
Requests per second:    230.05 [#/sec] (mean)
Time per request:       4.347 [ms] (mean)
Time per request:       4.347 [ms] (mean, across all concurrent requests)
Transfer rate:          38.56 [Kbytes/sec] received

230 #/secなら十分とは思うけど，


sub default : Private {
    my ( $self, $c ) = @_;
    $c->res->output('Congratulations, CatalystTestApp is on Catalyst!');
}

という処理しかしていないのに，と思う。っつーわけで犯人を捜せ。ちなみに最初に確認の１回wgetと終了をスクリプト内部でやっとけって思ってexitするハンドラを１回呼んでいる。なので，prepare/dispatchは10002回のコール，finalizeは10001回のコールとなっている。 dprofpp -I -O 30の結果。


%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 157.   0.110 24.348      1   0.1100 24.348  Catalyst::Engine::FastCGI::Base::run
 142.   0.380 22.018  10002   0.0000 0.0022  Catalyst::Engine::handler
 139.   0.390 21.578  10002   0.0000 0.0022  Catalyst::Engine::__ANON__
 86.2   0.950 13.359  10002   0.0001 0.0013  Catalyst::Engine::prepare
 27.5   0.350  4.270  10002   0.0000 0.0004  Catalyst::Dispatcher::dispatch
 25.3   0.450  3.930  10002   0.0000 0.0004  Catalyst::Engine::CGI::Base::prepare_path
 22.5   0.520  3.490  10001   0.0001 0.0003  Catalyst::Engine::finalize
 19.0   1.080  2.950  50011   0.0000 0.0001  Catalyst::Dispatcher::get_action
 18.9   0.290  2.930  10002   0.0000 0.0003  Catalyst::Engine::FastCGI::prepare_request
 17.9   2.780  2.780 940157   0.0000 0.0000  Class::Accessor::Fast::__ANON__
 14.8   0.040  2.300  10002   0.0000 0.0002  Catalyst::Engine::CGI::prepare_request
 14.5   0.950  2.250  10002   0.0001 0.0002  Catalyst::Engine::CGI::Base::prepare_headers
 14.3   2.220  2.220  10002   0.0002 0.0002  FCGI::Accept
 14.3   0.120  2.220  10002   0.0000 0.0002  CGI::new
 13.5   0.480  2.100  10002   0.0000 0.0002  CGI::init
 10.8   0.660  1.680  70013   0.0000 0.0000  HTTP::Headers::header
 9.30   0.220  1.440  10001   0.0000 0.0001  Catalyst::Engine::CGI::Base::finalize_headers
 9.30   0.540  1.440  50009   0.0000 0.0000  Tree::Simple::Visitor::FindByPath::new
 8.98   1.390  1.390  90015   0.0000 0.0000  HTTP::Headers::_header
 6.52   0.530  1.010  20004   0.0000 0.0001  CGI::delete
 5.81   0.540  0.900  50009   0.0000 0.0000  Tree::Simple::Visitor::FindByPath::_init
 5.55   0.420  0.860  10002   0.0000 0.0001  Catalyst::Engine::execute
 5.49   0.110  0.850  10002   0.0000 0.0001  URI::http::canonical
 5.23   0.300  0.810  20004   0.0000 0.0000  URI::_server::host
 5.17   0.620  0.800  70014   0.0000 0.0000  URI::_generic::authority
 4.59   0.280  0.710  10002   0.0000 0.0001  Catalyst::Engine::prepare_action
 4.33   0.280  0.670  10001   0.0000 0.0001  HTTP::Headers::as_string
 4.26   0.420  0.660  20004   0.0000 0.0000  URI::_scheme
 4.07   0.230  0.630  10002   0.0000 0.0001  URI::_server::canonical
 4.07   0.290  0.630  60012   0.0000 0.0000  CGI::param

リクエストはそれぞれがCatalyst::Engine::handlerが処理する。Catalyst::Engine::__ANON__はその内部の匿名ブロック。 ab2の43.469302秒に対して，クライアント側・通信・lighttpd内の処理などのもろもろのオーバーヘッドを除いて22.018秒がかかっている，と。


sub handler {
    my ( $class, @arguments ) = @_;
    # Always expect worst case!
    my $status = -1;
    eval {
        my @stats = ();
        my $handler = sub {
            my $c = $class->prepare(@arguments);
            $c->{stats} = \@stats;
            $c->dispatch;
            return $c->finalize;
        };
        if ( $class->debug ) {
            my $elapsed;
            ( $elapsed, $status ) = $class->benchmark($handler);
            $elapsed = sprintf '%f', $elapsed;
            my $av = sprintf '%.3f',
              ( $elapsed == 0 ? '??' : ( 1 / $elapsed ) );
            my $t = Text::ASCIITable->new;
            $t->setCols( 'Action', 'Time' );
            $t->setColWidth( 'Action', 64, 1 );
            $t->setColWidth( 'Time',   9,  1 );
            for my $stat (@stats) { $t->addRow( $stat->[0], $stat->[1] ) }
            $class->log->info(
                "Request took ${elapsed}s ($av/s)\n" . $t->draw );
        }
        else { $status = &$handler }
    };
    if ( my $error = $@ ) {
        chomp $error;
        $class->log->error(qq/Caught exception in engine "$error"/);
    }
    $COUNT++;
    return $status;
}

この$handlerの部分。debugのときにベンチマーク取るので$handlerに入れてるわけだ。この中ではprepare, dispatch, finalizeの３つの処理をしているだけだ。その３つの処理があわせて21.5秒(/10000 req，以下同様)かかっている。 prepareが13.3秒，dispatchが4.2秒，finalizeが3.5秒，とprepareがもっとも時間がかかっている。 dispatchも処理としてはoutputへの代入しかしてないのに，その準備にオーバーヘッドがありすぎな気もするが・・・まあ，柔軟なdispatchの代償だろう。finalizeも少し気になる。 Catalyst::Engine::prepareの処理は大きく２つ。contextオブジェクト（request/response/stashオブジェクトを含む）の生成と各種prepare_*メソッドの呼び出しだ。


sub prepare {
    my ( $class, @arguments ) = @_;
    my $c = bless {
        counter => {},
        depth   => 0,
        request => Catalyst::Request->new(
            {
                arguments  => [],
                cookies    => {},
                headers    => HTTP::Headers->new,
                parameters => {},
                secure     => 0,
                snippets   => [],
                uploads    => {}
            }
        ),
        response => Catalyst::Response->new(
            {
                body    => '',
                cookies => {},
                headers => HTTP::Headers->new( 'Content-Length' => 0 ),
                status  => 200
            }
        ),
        stash => {},
        state => 0
    }, $class;
    if ( $c->debug ) {
        my $secs = time - $START || 1;
        my $av = sprintf '%.3f', $COUNT / $secs;
        $c->log->debug('**********************************');
        $c->log->debug("* Request $COUNT ($av/s) [$$]");
        $c->log->debug('**********************************');
        $c->res->headers->header( 'X-Catalyst' => $Catalyst::VERSION );
    }
    $c->prepare_request(@arguments);
    $c->prepare_connection;
    $c->prepare_headers;
    $c->prepare_cookies;
    $c->prepare_path;
    $c->prepare_action;
    my $method  = $c->req->method  || '';
    my $path    = $c->req->path    || '';
    my $address = $c->req->address || '';
    $c->log->debug(qq/"$method" request for "$path" from $address/)
      if $c->debug;
    if ( $c->request->method eq 'POST' and $c->request->content_length ) {
        if ( $c->req->content_type eq 'application/x-www-form-urlencoded' ) {
            $c->prepare_parameters;
        }
        elsif ( $c->req->content_type eq 'multipart/form-data' ) {
            $c->prepare_parameters;
            $c->prepare_uploads;
        }
        else {
            $c->prepare_body;
        }
    }
    if ( $c->request->method eq 'GET' ) {
        $c->prepare_parameters;
    }
    if ( $c->debug && keys %{ $c->req->params } ) {
        my $t = Text::ASCIITable->new;
        $t->setCols( 'Key', 'Value' );
        $t->setColWidth( 'Key',   37, 1 );
        $t->setColWidth( 'Value', 36, 1 );
        for my $key ( sort keys %{ $c->req->params } ) {
            my $param = $c->req->params->{$key};
            my $value = defined($param) ? $param : '';
            $t->addRow( $key, $value );
        }
        $c->log->debug( "Parameters are:\n" . $t->draw );
    }
    return $c;
}

ExclSecで見ると0.950秒なので，12秒ちょいをprepare_*メソッドで消費している。逆に言うと，0.950秒はblessの処理であろう。これ，毎回blessするんでなく使い回しが出来ないのだろうか。 prepare_path, prepare_headers, prepare_requestあたりが重い。この３つで10秒近くかかっているわけだ。その関係だけを抜き出してみよう。


%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 86.2   0.950 13.359  10002   0.0001 0.0013  Catalyst::Engine::prepare
 25.3   0.450  3.930  10002   0.0000 0.0004  Catalyst::Engine::CGI::Base::prepare_path
 18.9   0.290  2.930  10002   0.0000 0.0003  Catalyst::Engine::FastCGI::prepare_request
 14.8   0.040  2.300  10002   0.0000 0.0002  Catalyst::Engine::CGI::prepare_request
 14.5   0.950  2.250  10002   0.0001 0.0002  Catalyst::Engine::CGI::Base::prepare_headers

ひとまずはこの辺で。後でprepareの詳細と，余力があったらdispatch, finalizeの詳細についても見てみよう。

Trackback URL for this post:

http://old.typemiss.net/trackback/2

Catalystのオーバーヘッド～Catalyst::Engine::FastCGIのprepare系

from Typemiss.net on 火, 2005-11-08 04:36

Catalystのオーバーヘッド～Catalyst::Engine::FastCGIの続き。 handlerの準備段階であるprepare_*の詳細を見てみよう。

» kounoike さんのブログ

Typemiss.net

Catalystのオーバーヘッド～Catalyst::Engine::FastCGI

Trackback URL for this post:

コンテンツ

ナビゲーション

最近のブログ投稿

Ads

シンジケート