[cgiapp] Debugging Performance with CGI::Application Using Firebug and Time::HiRes

[Rhesa Rozendaal]

On 12/31/2010 07:32 PM, Jerry Kaidor wrote:
> I have also noticed that CGI::Application is slow.  When I recoded my
> business software ( which was originally a set of Perl/CGI/mysql scripts,
> each one with a big messy dispatch table ) my page load times went up from
> under a second to about 2 seconds.
>
>   It's still tolerable, and I figured it was just the price of civilized
> programming.

No, CGI::Application is not slow at all. Here's a minimal cgiapp:

#!/usr/bin/perl

My::App->new->run;

package My::App;
use base 'CGI::Application';

sub setup {
     my $self = shift;
     $self->run_modes([ 'static' ]);
     $self->start_mode('static');
}

sub static {
     return "Hello, World!\n";
}


When I run this through Devel::NYTProf with `perl -d:NYTProf basic.pl` I 
get a
total run time of 111ms(*):

Profile of basic.pl for 111ms, executing 1290 statements and 250 subroutine
calls in 14 source files and 7 string evals.


Top 15 Subroutines — ordered by exclusive time
=====================================================================
Calls P   F   Exclusive   Inclusive           Subroutine
               Time        Time
---------------------------------------------------------------------
4     1   1   26.7ms      26.8ms               CGI::_compile
1     1   1   13.8ms      64.8ms  CGI::Application::cgiapp_get_query
1     1   1   13.6ms      13.9ms              vars::BEGIN at 7
1     1   1   8.14ms      15.1ms              base::import
1     1   1   6.26ms      6.82ms               CGI::BEGIN at 27
3     3   2   4.03ms      4.12ms          Exporter::import
1     1   1   4.03ms      4.43ms                Fh::BEGIN at 3715
1     1   1   4.03ms      4.06ms               CGI::read_from_cmdline
1     1   1   3.66ms      3.78ms   MultipartBuffer::BEGIN at 3788
2     2   1   3.42ms      3.52ms          constant::import
1     1   1   1.72ms      2.00ms  CGI::Application::BEGIN at 4
1     1   1   1.34ms      32.4ms           My::App::BEGIN at 7
1     1   1   1.16ms      4.85ms  CGI::Application::BEGIN at 2
1     1   1   957µs       1.16ms              base::BEGIN at 3
1     1   1   915µs       4.89ms               CGI::BEGIN at 32
=====================================================================

As you can see, this is mostly compilation. A persistent environment 
will pretty much remove this completely.

A slight variation on basic.pl runs the app 10,000 times, to make the
compile time less of a factor:


#!/usr/bin/perl

My::App->new->run for 1 .. 10_000;

package My::App;
use base 'CGI::Application';

sub setup {
     my $self = shift;
     $self->run_modes([ 'static' ]);
     $self->start_mode('static');
}

sub static {
     return "Hello, World!\n";
}


This time, NYTProf gives me a total run time of 34.5s, or 3.45ms per
iteration.

Here's the profile output:

Profile of loop.pl for 34.5s, executing 4690822 statements and 800170
subroutine calls in 14 source files and 7 string evals.


Top 15 Subroutines — ordered by exclusive time
=====================================================================
Calls   P   F   Exclusive   Inclusive           Subroutine
                 Time        Time
---------------------------------------------------------------------
40000   4   1   2.55s       3.36s   CGI::Application::call_hook
60000   5   3   1.34s       2.12s                CGI::param
10000   1   1   1.24s       6.17s                CGI::init
130000  5   4   1.13s       1.13s                CGI::self_or_default
10000   1   1   1.04s       15.2s   CGI::Application::run
10000   2   2   1.04s       1.99s                CGI::header
20000   3   1   1.01s       2.56s                CGI::delete
10000   1   1   840ms       3.51s   CGI::Application::new
30000   2   2   599ms       908ms          CGI::Util::rearrange
10000   1   1   549ms       549ms         Class::ISA::self_and_super_path
30000   3   1   515ms       7.17s   CGI::Application::query
30000   3   2   465ms       742ms                CGI::charset
20000   2   2   444ms       444ms   CGI::Application::run_modes
20000   2   1   440ms       440ms   CGI::Application::mode_param
20000   2   1   437ms       437ms   CGI::Application::header_type
=====================================================================

Here's a quick sanity check:

rhesa at schutz:~/devel/test/cgiapp-profile$ time perl basic.pl > /dev/null

real    0m0.097s
user    0m0.056s
sys 0m0.004s
rhesa at schutz:~/devel/test/cgiapp-profile$ time perl loop.pl > /dev/null

real    0m2.731s
user    0m2.408s
sys 0m0.008s

Clearly, Devel::NYTProf introduces a substantial overhead. Running 
loop.pl without the profiler boils down to 0.27ms per iteration!

Bottom line: CGI::Application itself has virtually no overhead.

Rhesa

(*) Profiles and times produced on my oldish ThinkPad z60m.