> > However, I've noticed that scripts that generate lot of output take
> > substantially longer to run than their CGI counterparts.
> >
> > The CGI script took 1.59 seconds to run, whereas the mod_perl version
> > took 3.38 seconds. It generates about 321K of output.
>
> Are you positive that they generated identical output?
The output isn't quite identical -- there are some differences because
of differing script names and whitespace. But they're within a few
hundred bytes of each other.
> How were you doing this filtering in your CGI script?
I had a written an SSI parser in Perl. It's not exactly optimized and
is about six years old, but it basically recursed through INCLUDE
directives until it found a script or other SSI directive to execute.
Script output was captured by doing print `script`;
> > I'm guessing that it's because Apache::Filter loads the output of
> > each filter into memory before passing it on.
>
> That's a good guess. Why don't you profile it and find out where the
> problem is? Try Apache::DProf.
Hey, neat. :) I didn't know about that.
Here's the output after a few loads:
# dprofpp -F 24939/tmon.out
Faking 2 exit timestamp(s).
Total Elapsed Time = -0.05622 Seconds
User+System Time = 0 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
0.00 6.359 6.347 8921 0.0007 0.0007 Apache::Filter::PRINTF
0.00 1.163 8.016 3 0.3877 2.6719 Apache::RegistryFilter::handler
0.00 0.410 0.397 8996 0.0000 0.0000 DBI::st::fetchrow_arrayref
0.00 0.050 0.050 16 0.0031 0.0031 DBI::st::execute
0.00 0.050 0.099 2 0.0250 0.0494 Apache::SSI::handler
0.00 0.030 0.030 6 0.0050 0.0050 CGI::new
0.00 0.030 0.030 8 0.0037 0.0037 CGI::AUTOLOAD
0.00 0.020 0.030 65 0.0003 0.0005 Apache::PRINT
0.00 0.020 0.030 1 0.0200 0.0298 Apache::DBI::childinit
0.00 0.010 0.010 15 0.0007 0.0007 Apache::send_cgi_header
0.00 0.010 0.010 6 0.0017 0.0017 CGI::Util::expires
0.00 0.010 0.010 4 0.0025 0.0025 vars::import
0.00 0.010 0.010 11 0.0009 0.0009 DBI::_new_dbh
0.00 0.010 0.010 24 0.0004 0.0004 DBI::db::prepare
0.00 0.010 0.048 12 0.0008 0.0040 Apache::Registry::handler
It looks like the problem is repeated print statements. I basically
had a loop that did
while ($ref = $sth->fetchrow_arrayref()) {
print $$ref[0], $$ref[2], etc.
}
Changing it to
my $output;
while ($ref = $sth->fetchrow_arrayref()) {
$output .= $$ref[0] . $$ref[2], etc.
}
print $output;
cut the load time to 1.03 seconds -- that's 1/3 of the timing with multiple
print statements and 2/3 of the timing for the CGI script.
So the lesson I learned is to store all of your output when using
Apache::Filter, then print it all out at once.
Thanks for the pointer, Perrin!
Chris
--
Reporting bugs: http://perl.apache.org/bugs/
Mail list info: http://perl.apache.org/maillist/modperl.html
