dprofpp'ing a pesky file

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

Once again I return for help. the last two times, you guys have saved me after DAYS of hair-pulling, with simple answers that I've overlooked. Thanks in advance. :)

So, this is the 'perl -d:DProf testfile.cgi' then 'ddprofpp -r -I' of a small perl function that is updating a character's stats in a homebrew online game. It loads their info, outputs it to screen, updates their whatever, and closes.

My problem: Note the huge amount of time taken in 'Main:Begin'. What does that mean? Does that mean that the majority of this code is burning its time in the actual main function, and not in all of the calls - i.e. there is probably inefficient formatting / loops in there? Or should that be disregarded, and the other parts of the output looked at? (note, these were run during unusually high load times, excuse the length of execution.

%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 39.6   0.251  0.304     14   0.0179 0.0217  main::BEGIN
 5.35   0.000  0.041      1   0.0001 0.0413  main::SETUP_GAME
 4.05   0.000  0.031      1   0.0000 0.0307  DBI::connect
 3.92   0.000  0.030      4   0.0000 0.0076  DynaLoader::bootstrap
 2.74   0.010  0.021     12   0.0009 0.0017  DBI::BEGIN
 2.74   0.000  0.021      1   0.0001 0.0206  DBI::install_driver
 2.61   0.000  0.020      9   0.0000 0.0022  main::CHANGE_PLAYER_VALUE
 2.61   0.020  0.020     15   0.0013 0.0013  DBI::db::do
 2.61   0.020  0.020      1   0.0200 0.0200  Image::Magick::bootstrap
 1.70   0.002  0.013     83   0.0000 0.0002  DBI::st::fetchrow_hashref
 1.44   0.010  0.011      1   0.0102 0.0111  main::LOAD_PLAYER_STATS
 1.44   0.000  0.011      6   0.0001 0.0018  main::GET_FLAG
 1.44   0.011  0.011     83   0.0001 0.0001  DBI::st::FETCH
 1.31   0.010  0.010      6   0.0017 0.0017  File::Copy::BEGIN
 1.31   0.010  0.010     36   0.0003 0.0003  DBI::st::execute
[download]

Second 'bonus' question: This output is on the same file but while using SelfLoader. does it sa to you 'wow, selfloader is a bad idea for this guy, he should use autoLoader' or 'he should not be using either'?

%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 31.0   0.130  0.669      7   0.0185 0.0955  main::BEGIN
 30.5   0.059  0.658     36   0.0016 0.0183  SelfLoader::AUTOLOAD
 25.9       -  0.560      1        - 0.5598  DBI::connect
 25.5   0.550  0.550      1   0.5500 0.5500  DBD::mysql::db::_login
 25.5       -  0.550      1        - 0.5500  DBD::mysql::dr::connect
 25.5       -  0.550      1        - 0.5500  DBI::dr::connect
 25.5       -  0.550      1        - 0.5500  DBI::__ANON__
 22.7       -  0.490      4        - 0.1225  DynaLoader::bootstrap
 19.5   0.010  0.420     12   0.0008 0.0350  DBI::BEGIN
 18.5   0.400  0.400      1   0.4000 0.4000  DBI::bootstrap
 17.1   0.370  0.370     36   0.0103 0.0103  DBI::st::execute
 3.71   0.080  0.080      1   0.0800 0.0800  Image::Magick::bootstrap
 3.25   0.070  0.070     16   0.0044 0.0044  DBI::db::do
 1.39   0.030  0.030      9   0.0033 0.0033  SelfLoader::BEGIN
 0.93       -  0.020      1        - 0.0196  main::LOAD_MISSION
[download]

Triple bonus: What's with the Image Magick bootstrap? I don't call IM in any of these files in any way.

I hope this is understandable, I sometimes have a hard time getting things across concisely in English.

Comment on dprofpp'ing a pesky file - any input? Select or Download Code

Replies are listed 'Best First'.
Re: dprofpp'ing a pesky file - any input? by perrin (Chancellor) on Feb 07, 2009 at 20:58 UTC
Why are you using SelfLoader/Autloader? Are you worried about compile time? You'd get a much better performance boost by using mod_perl or FastCGI, skipping the compile time completely. Also, I recommend the more modern Devel::NYTProf at this point.	[reply]
Re: dprofpp'ing a pesky file - any input? by Anonymous Monk on Feb 07, 2009 at 18:52 UTC
Note the huge amount of time taken in 'Main:Begin'. What does that mean? Does that mean that the majority of this code is burning its time in the actual main function... Here's what it means D:\> D:\>more hi.pl BEGIN { use DBI; use CGI; } hi(); sub hi{ print "Hi there\n"; } D:\>perl -d:DProf hi.pl Hi there D:\>dprofpp tmon.out Total Elapsed Time = 0.108110 Seconds User+System Time = 0.108110 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 14.8 0.016 0.016 1 0.0160 0.0160 Fh::BEGIN 14.8 0.016 0.016 6 0.0027 0.0027 constant::BEGIN 14.8 0.016 0.047 13 0.0012 0.0036 DBI::BEGIN 14.8 0.016 0.093 5 0.0032 0.0186 main::BEGIN 13.8 0.015 0.031 1 0.0150 0.0308 ActivePerl::Config::overr +ide 13.8 0.015 0.015 3 0.0050 0.0050 CGI::BEGIN 0.00 0.000 0.000 1 0.0000 0.0000 Config::launcher 0.00 0.000 0.000 1 0.0000 0.0000 Config::fetch_string 0.00 0.000 0.000 1 0.0000 0.0000 Exporter::Heavy::heavy_ex +port_ok_t ags 0.00 - -0.000 1 - - warnings::import 0.00 - -0.000 1 - - File::Basename::fileparse +_set_fsty 0.0000 pe 0.00 - -0.000 1 - - Cwd::bootstrap 0.00 - -0.000 1 - - DBI::DBI_tie::TIEHASH 0.00 - -0.000 1 - - overload::OVERLOAD 0.00 - -0.000 1 - - CGI::initialize_globals D:\> [download] Notice how hi has very short runtime, while loading DBI/CGI takes more time.	[reply] [d/l]
Re: dprofpp'ing a pesky file - any input? by Anonymous Monk on Feb 07, 2009 at 18:44 UTC
What's with the Image Magick bootstrap? I don't call IM in any of these files in any way. But something you do call does `use Image::Magick;`	[reply] [d/l]