Appended to this message are are some basic profiles of the script when
run with TT 2.06/a-d. I installed each release, deleted the compiled
templates, requested the script twice with the -d:DProf option enabled
(once to compile the templates and once to get profiling data), and ran
"dprofpp" without any options to get a list of the 15 most expensive
functions.
The reason for the slowdown in 2.06d is pretty clear: the
Template::Filters::html_filter_factory function became many times slower
in that release. That function doesn't make an appearance on the 2.06
list but does appear on the lists for the other developer releases, so
it may also be part of the general slowdown seen in the developer releases.
-myk
2.06:
Total Elapsed Time = 1.958218 Seconds
User+System Time = 1.472858 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
27.0 0.398 2.843 542 0.0007 0.0052 Template::Provider::__ANON__
19.6 0.290 0.222 32231 0.0000 0.0000 Template::Stash::XS::get
16.0 0.237 0.393 26 0.0091 0.0151 main::BEGIN
9.51 0.140 3.020 540 0.0003 0.0056 Template::Context::process
8.83 0.130 0.120 4950 0.0000 0.0000 Template::Iterator::get_next
8.15 0.120 0.111 4375 0.0000 0.0000 Template::Filters::__ANON__
3.39 0.050 0.049 502 0.0001 0.0001 Template::Config::load
2.72 0.040 0.039 486 0.0001 0.0001 main::DiffDate
2.72 0.040 0.031 4465 0.0000 0.0000 Template::Context::filter
2.04 0.030 0.029 497 0.0001 0.0001 Template::Iterator::get_first
2.04 0.030 0.043 497 0.0001 0.0001 Template::Config::iterator
2.04 0.030 1.145 11 0.0027 0.1041 Template::BEGIN
1.36 0.020 0.017 1547 0.0000 0.0000 Template::Stash::XS::set
1.36 0.020 0.016 1954 0.0000 0.0000 Template::Iterator::AUTOLOAD
1.36 0.020 0.020 3 0.0067 0.0066 Template::Stash::XS::BEGIN
2.06a:
Total Elapsed Time = 2.766433 Seconds
User+System Time = 2.026433 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
18.9 0.384 4.184 542 0.0007 0.0077 Template::Provider::__ANON__
14.3 0.290 0.336 32231 0.0000 0.0000 Template::Stash::XS::get
10.8 0.219 0.386 26 0.0084 0.0149 main::BEGIN
7.90 0.160 0.237 4465 0.0000 0.0001 Template::Filters::fetch
7.40 0.150 0.145 4950 0.0000 0.0000 Template::Iterator::get_next
5.92 0.120 4.358 540 0.0002 0.0081 Template::Context::process
4.44 0.090 0.086 4375 0.0000 0.0000
Template::Filters::html_filter_fac
tory
4.44 0.090 0.086 4375 0.0000 0.0000 Template::Filters::__ANON__
4.44 0.090 0.318 4465 0.0000 0.0001 Template::Context::filter
3.45 0.070 0.066 4374 0.0000 0.0000 main::__ANON__
2.96 0.060 0.059 502 0.0001 0.0001 Template::Config::load
1.48 0.030 0.030 497 0.0001 0.0001 Template::Iterator::get_first
1.48 0.030 0.068 551 0.0001 0.0001 Template::Context::BEGIN
1.48 0.030 0.056 497 0.0001 0.0001 Template::Config::iterator
0.99 0.020 0.018 1602 0.0000 0.0000 UNIVERSAL::isa
2.06b:
-rw-r--r-- 1 apache apache 880853 Feb 8 14:38 tmon.out
Total Elapsed Time = 2.793048 Seconds
User+System Time = 2.076436 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
22.3 0.463 4.264 542 0.0009 0.0079 Template::Provider::__ANON__
17.8 0.370 0.466 32231 0.0000 0.0000 Template::Stash::XS::get
10.5 0.219 0.406 26 0.0084 0.0156 main::BEGIN
8.19 0.170 4.468 540 0.0003 0.0083 Template::Context::process
7.71 0.160 0.155 4950 0.0000 0.0000 Template::Iterator::get_next
6.74 0.140 0.187 4465 0.0000 0.0000 Template::Filters::fetch
3.85 0.080 0.076 4374 0.0000 0.0000 main::__ANON__
2.89 0.060 0.056 4375 0.0000 0.0000
Template::Filters::html_filter_fac
tory
2.89 0.060 0.058 1954 0.0000 0.0000 Template::Iterator::AUTOLOAD
2.41 0.050 0.228 4465 0.0000 0.0001 Template::Context::filter
1.44 0.030 0.026 4375 0.0000 0.0000 Template::Filters::__ANON__
1.44 0.030 0.029 502 0.0001 0.0001 Template::Config::load
1.44 0.030 1.630 11 0.0027 0.1482 Template::BEGIN
0.96 0.020 0.020 486 0.0000 0.0000 main::DiffDate
0.96 0.020 0.019 540 0.0000 0.0000 Template::Stash::update
2.06c:
-rw-r--r-- 1 apache apache 880973 Feb 8 14:39 tmon.out
Total Elapsed Time = 2.506261 Seconds
User+System Time = 1.889649 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
19.6 0.372 3.941 542 0.0007 0.0073 Template::Provider::__ANON__
18.5 0.350 0.394 32231 0.0000 0.0000 Template::Stash::XS::get
11.5 0.218 0.405 26 0.0084 0.0156 main::BEGIN
7.41 0.140 0.133 4950 0.0000 0.0000 Template::Iterator::get_next
6.88 0.130 0.123 4375 0.0000 0.0000
Template::Filters::html_filter_fac
tory
6.35 0.120 4.092 540 0.0002 0.0076 Template::Context::process
5.82 0.110 0.220 4465 0.0000 0.0000 Template::Filters::fetch
5.29 0.100 0.307 4465 0.0000 0.0001 Template::Context::filter
4.23 0.080 0.073 4375 0.0000 0.0000 Template::Filters::__ANON__
3.70 0.070 0.063 4374 0.0000 0.0000 main::__ANON__
2.12 0.040 0.038 502 0.0001 0.0001 Template::Iterator::BEGIN
2.12 0.040 0.039 502 0.0001 0.0001 Template::Config::load
2.12 0.040 1.520 11 0.0036 0.1382 Template::BEGIN
1.59 0.030 0.027 1954 0.0000 0.0000 Template::Iterator::AUTOLOAD
1.59 0.030 0.029 486 0.0001 0.0001 main::DiffDate
2.06d:
-rw-r--r-- 1 apache apache 1092237 Feb 8 14:40 tmon.out
Total Elapsed Time = 3.724526 Seconds
User+System Time = 3.234526 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
34.9 1.130 1.461 4375 0.0003 0.0003
Template::Filters::html_filter_fac
tory
12.7 0.411 8.204 542 0.0008 0.0151 Template::Provider::__ANON__
6.80 0.220 0.344 4375 0.0001 0.0001 diagnostics::death_trap
6.49 0.210 0.244 32231 0.0000 0.0000 Template::Stash::XS::get
6.43 0.208 0.385 26 0.0080 0.0148 main::BEGIN
4.95 0.160 0.153 4950 0.0000 0.0000 Template::Iterator::get_next
4.95 0.160 1.608 4465 0.0000 0.0004 Template::Filters::fetch
4.02 0.130 0.123 4375 0.0000 0.0000 HTML::Entities::encode_entities
4.02 0.130 1.724 4465 0.0000 0.0004 Template::Context::filter
3.40 0.110 0.103 4375 0.0000 0.0000 CGI::Carp::realdie
3.09 0.100 8.354 540 0.0002 0.0155 Template::Context::process
1.85 0.060 0.053 4374 0.0000 0.0000 main::__ANON__
1.55 0.050 0.047 1954 0.0000 0.0000 Template::Iterator::AUTOLOAD
1.24 0.040 0.039 502 0.0001 0.0001 Template::Config::load
0.93 0.030 0.030 6 0.0050 0.0050
Template::Provider::_load_compiled
