[cgiapp] Debugging Performance with CGI::Application Using Firebug and Time::HiRes
Andy Daykin
daykinandy at gmail.com
Sun Jan 2 22:00:45 EST 2011
The performance bottleneck is certainly not the LDAP server. I only hit the
LDAP server when I am attempting to login, which was not the case during the
test results that I ran. I will run the tests again for the NYT Prof, but
the last time I ran them I didn't get very conclusive results. The database
hardly gets hit either, it only makes a few queries to tables that all have
less than 10 records in them.
There is definitely something else going on and I can't figure out what it
is, but hopefully the NYT Prof will give me a better idea.
-Andy
-----Original Message-----
From: Rhesa Rozendaal
Sent: Saturday, January 01, 2011 5:11 AM
To: CGI Application
Subject: Re: [cgiapp] Debugging Performance with CGI::Application Using
Firebug and Time::HiRes
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.
##### CGI::Application community mailing list ################
## ##
## To unsubscribe, or change your message delivery options, ##
## visit: http://lists.openlib.org/mailman/listinfo/cgiapp ##
## ##
## Web archive: http://lists.openlib.org/pipermail/cgiapp/ ##
## Wiki: http://cgiapp.erlbaum.net/ ##
## ##
################################################################
More information about the cgiapp
mailing list