Profiling Titanium

SilasTheMonk has asked for the wisdom of the Perl Monks concerning the following question:

Spotting the HTML::Template::Pro module yesterday prompted me to try profiling Titanium. 1.) My current script using Titanium

Total Elapsed Time = 0.492128 Seconds
  User+System Time = 0.472128 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 10.5   0.050  0.305     20   0.0025 0.0153  base::import
 8.47   0.040  0.069      7   0.0057 0.0099  CGI::Application::Plugin:
+:DebugScr
                                             een::BEGIN
 8.47   0.040  0.276     15   0.0026 0.0184  Titanium::BEGIN
 6.35   0.030  0.030      5   0.0060 0.0060  CGI::_compile
 4.24   0.020  0.060      1   0.0200 0.0596  CGI::Application::cgiapp_
+get_query
 4.24   0.020  0.020      7   0.0029 0.0028  CGI::Application::Plugin:
+:Session:
                                             :BEGIN
 4.24   0.020  0.020      6   0.0033 0.0033  Devel::StackTrace::BEGIN
 4.24   0.020  0.029      8   0.0025 0.0037  Data::FormValidator::Resu
+lts::BEGI
                                             N
 4.24   0.020  0.079      9   0.0022 0.0088  Data::FormValidator::BEGI
+N
 4.24   0.020  0.020     73   0.0003 0.0003  strict::import
 2.12   0.010  0.010      1   0.0100 0.0100  UNIVERSAL::require
 2.12   0.010  0.019      1   0.0100 0.0194  HTML::Template::_init
 2.12   0.010  0.000      3   0.0033 0.0000  Exporter::Heavy::heavy_ex
+port_to_l
                                             evel
 2.12   0.010  0.010      5   0.0020 0.0020  overload::OVERLOAD
 2.12   0.010  0.010      4   0.0025 0.0025  Devel::StackTraceFrame::B
+EGIN
[download]

2.) Removing Titanium and using CGI::Application

Total Elapsed Time = 0.267287 Seconds
  User+System Time = 0.247287 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 12.1   0.030  0.030      5   0.0060 0.0060  CGI::_compile
 12.1   0.030  0.070      1   0.0300 0.0697  CGI::Application::cgiapp_
+get_query
 12.1   0.030  0.059      1   0.0300 0.0594  CGI::Application::load_tm
+pl
 12.1   0.030  0.089      4   0.0075 0.0222  main::BEGIN
 8.09   0.020  0.020      6   0.0033 0.0033  Devel::StackTrace::BEGIN
 8.09   0.020  0.020      1   0.0199 0.0196  HTML::Template::_parse
 8.09   0.020  0.020      8   0.0025 0.0025  base::import
 4.04   0.010  0.010      2   0.0050 0.0049  Exception::Class::import
 4.04   0.010  0.010      7   0.0014 0.0014  CGI::Application::param
 4.04   0.010  0.010      2   0.0050 0.0050  Class::Data::Inheritable:
+:BEGIN
 4.04   0.010  0.010      3   0.0033 0.0033  CGI::BEGIN
 4.04   0.010  0.010     16   0.0006 0.0006  strict::bits
 4.04   0.010  0.030      6   0.0017 0.0049  GasthausMesner::MainApp::
+BEGIN
 4.04   0.010  0.049      8   0.0012 0.0062  Exception::Class::BEGIN
 4.04   0.010  0.010     11   0.0009 0.0009  HTML::Template::BEGIN
[download]

3.) Additionally using HTML::Template::Pro instead of HTML::Template.

Total Elapsed Time = 0.237335 Seconds
  User+System Time = 0.237335 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 12.6   0.030  0.030      5   0.0060 0.0060  CGI::_compile
 12.6   0.030  0.060      1   0.0300 0.0597  CGI::Application::cgiapp_
+get_query
 12.6   0.030  0.030      8   0.0037 0.0037  base::import
 8.43   0.020  0.030      1   0.0199 0.0298  CGI::Application::load_tm
+pl
 8.43   0.020  0.040     10   0.0020 0.0040  Exception::Class::Base::B
+EGIN
 4.21   0.010  0.010      4   0.0025 0.0025  Devel::StackTraceFrame::B
+EGIN
 4.21   0.010  0.010      1   0.0100 0.0099  GasthausMesner::MainApp::
+setup
 4.21   0.010  0.099      1   0.0100 0.0989  CGI::Application::run
 4.21   0.010  0.010      7   0.0014 0.0014  HTML::Template::Pro::BEGI
+N
 4.21   0.010  0.010     13   0.0008 0.0008  vars::import
 4.21   0.010  0.079      4   0.0025 0.0197  main::BEGIN
 4.21   0.010  0.049      8   0.0012 0.0062  Exception::Class::BEGIN
 4.21   0.010  0.069      8   0.0012 0.0086  CGI::Application::Dispatc
+h::BEGIN
 4.21   0.010  0.010     16   0.0006 0.0006  strict::unimport
 0.00   0.000  0.000      1   0.0000 0.0000  CGI::read_from_cmdline
[download]

4.) Additionally using CGI::Simple instead of CGI.

Total Elapsed Time = 0.196889 Seconds
  User+System Time = 0.186889 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 21.4   0.040  0.050      5   0.0080 0.0100  CGI::Application::Plugin:
+:AnyCGI::
                                             BEGIN
 16.0   0.030  0.040      8   0.0037 0.0049  base::import
 10.7   0.020  0.020      6   0.0033 0.0033  Devel::StackTrace::BEGIN
 10.7   0.020  0.020      1   0.0199 0.0197  CGI::Application::load_tm
+pl
 10.7   0.020  0.039     10   0.0020 0.0039  Exception::Class::Base::B
+EGIN
 5.35   0.010  0.010      1   0.0100 0.0099  CGI::Simple::header
 5.35   0.010  0.010      2   0.0050 0.0050  lib::BEGIN
 5.35   0.010  0.020      4   0.0025 0.0049  Periapt::BaseApp::BEGIN
 5.35   0.010  0.010     15   0.0007 0.0007  Exporter::import
 5.35   0.010  0.010      9   0.0011 0.0011  CGI::Simple::BEGIN
 5.35   0.010  0.079      4   0.0025 0.0197  main::BEGIN
 0.00   0.000  0.000      1   0.0000 0.0000  AutoLoader::__ANON__
 0.00       - -0.000      1        -      -  UNIVERSAL::VERSION
 0.00       - -0.000      1        -      -  version::(bool
 0.00       - -0.000      1        -      -  Config::TIEHASH
[download]

So I conclude that I should test a bit more with a view to making these module substitutions. Any thoughts?

Comment on Profiling Titanium Select or Download Code

Replies are listed 'Best First'.
Re: Profiling Titanium by perrin (Chancellor) on Aug 25, 2009 at 16:06 UTC
Here are my thoughts: Stop using Devel::DProf. It has been replaced by Devel::NYTProf. You'll get much better information. Run your page requests 10-100 times in one profiling session, or wait to enable the profiler until after the first request. If you don't, the setup time will swallow everything else. Profile a real application, or at least something with a database request in it. If you profile a "hello world" app you'll wind up spending hours working on things that increase performance by 0.1%. I think it would be a mistake to use HTML::Template::Pro. Its only real speed advantage is when running as CGI, and if you care about performance, you should be using mod_perl or FastCGI. There are faster templating tools than HTML::Template, but I've never seen it be the bottleneck in any real application.	[reply]
Re^2: Profiling Titanium by SilasTheMonk (Chaplain) on Aug 25, 2009 at 16:29 UTC
* Stop using Devel::DProf. It has been replaced by Devel::NYTProf. You'll get much better information. * Run your page requests 10-100 times in one profiling session, or wait to enable the profiler until after the first request. If you don't, the setup time will swallow everything else. * Profile a real application, or at least something with a database request in it. If you profile a "hello world" app you'll wind up spending hours working on things that increase performance by 0.1%. * I think it would be a mistake to use HTML::Template::Pro. Its only real speed advantage is when running as CGI, and if you care about performance, you should be using mod_perl or FastCGI. There are faster templating tools than HTML::Template, but I've never seen it be the bottleneck in any real application. Actually I would say security is a slightly higher concern than performance. For the forseeable fortune this is likely to be a VPS running a lot of sadly obscure websites. As such I am not using fastcgi or mod_perl but rather suExec. As such the module load startup is significant. I think that also shows why I stop using Titanium until I am using all the modules it loads. Still there is no reason to completely ignore performance or deny speed ups where available. Also the script does have a database backend though I will keeping rerunning the profile as it gets bigger. I am not laying to much by this experiment but it seems I have to agree about HTML::Template::Pro its contribution to the speed up was quite small.	[reply]