So I was really sure the main speed problem is related to my - not so correct - use of Class::DBI
Then I wrote a small script to be able to profile a call to the application and this is what I got from Devel::DProf:
Total Elapsed Time = 7.562621 Seconds
User+System Time = 7.582621 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
48.7 3.694 5.761 18 0.2052 0.3201 Parse::RecDescent::_generate
5.51 0.418 0.754 3672 0.0001 0.0002 Text::Balanced::_match_codeblock
2.36 0.179 0.187 324 0.0006 0.0006 Parse::RecDescent::Token::new
2.22 0.168 0.168 6030 0.0000 0.0000 Text::Balanced::_failmsg
1.85 0.140 0.553 2538 0.0001 0.0002 Text::Balanced::_match_variable
1.45 0.110 0.110 54 0.0020 0.0020 DBI::st::fetchrow_arrayref
1.40 0.106 0.379 504 0.0002 0.0008 Parse::RecDescent::Rule::code
1.37 0.104 0.210 1854 0.0001 0.0001 Parse::RecDescent::Rule::expected
1.32 0.100 0.100 30 0.0033 0.0033 DBI::st::execute
1.04 0.079 0.079 603 0.0001 0.0001 vars::import
0.96 0.073 0.895 1152 0.0001 0.0008 Text::Balanced::extract_codeblock
0.92 0.070 0.099 9 0.0078 0.0110 WWW::Mechanize::BEGIN
0.92 0.070 0.304 22 0.0032 0.0138 CPAN::Forum::BEGIN
0.91 0.069 0.069 414 0.0002 0.0002 Text::Balanced::_match_bracketed
0.88 0.067 0.067 1692 0.0000 0.0000 Parse::RecDescent::Production::has
leftmost
That's very nice and a clean pointer at the problem.
I added caching to the grammar generation of Parse::RecDescent - that is, I stopped creating new
Parse::RecDescent objects. Improved speed very considerably.
I still have requests that take 2-3 seconds but it seems the 8-15 seconds are gone now.
So while there is still more work to do to improve speed this was a nice step.
Here are the results of the new profile run
Total Elapsed Time = 2.209616 Seconds
User+System Time = 2.219616 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
8.97 0.199 0.306 1 0.1985 0.3056 Parse::RecDescent::_generate
8.56 0.190 0.190 30 0.0063 0.0063 DBI::st::execute
5.14 0.114 0.210 1854 0.0001 0.0001 Parse::RecDescent::Rule::expected
4.19 0.093 0.274 165 0.0006 0.0017 Parse::RecDescent::namespace000001
::inline
4.05 0.090 0.090 54 0.0017 0.0017 DBI::st::fetchrow_arrayref
3.56 0.079 0.325 52 0.0015 0.0063 base::import
3.06 0.068 0.102 2993 0.0000 0.0000 Parse::RecDescent::Production::exp
ected
2.70 0.060 0.109 9 0.0067 0.0121 WWW::Mechanize::BEGIN
2.70 0.060 0.304 22 0.0027 0.0138 CPAN::Forum::BEGIN
2.48 0.055 0.494 208 0.0003 0.0024 Parse::RecDescent::namespace000001
::html
2.25 0.050 0.070 6 0.0083 0.0116 CPAN::Forum::Markup::BEGIN
1.80 0.040 0.040 1 0.0400 0.0400 File::Copy::copy
1.35 0.030 0.026 2381 0.0000 0.0000 Class::DBI::Column::name_lc
1.35 0.030 0.030 4889 0.0000 0.0000 Parse::RecDescent::Expectation::at
1.35 0.030 0.039 1 0.0300 0.0392 CGI::Application::load_tmpl
