I've been profiling my MySQL driven Mod_Perl website by adding debug
messages throughout the code which relays what time has elapsed since the
script was invoked (using Time::HiRes)
Now the script is pretty whizzy, serving up complete pages in circa 0.010
seconds.
I got to wondering how those 0.010 were being made up. Interestingly, all
of the database access is complete within 0.002 so I thought where do the
other 0.008 come from ?
I found the following happened (pseudo code)
# Checkpoint A - Elapsed : 0.000
&buildpage;
# Checkpoint D - Elapsed 0.010 seconds
sub buildpage
{
# Checkpoint B - Elapsed: 0.001
# Do some DB accessing etc. make a nice webpage
# Checkpoint C - Elapsed 0.002
}
--
I expected all the complicated DB access stuff to make up the time, but
instead it seems to be consuming 0.005 in returning from the subroutine to
the main script.
What's that all about ?
Points:
1. A global variable exists throughout the script to build the webpage
2. Global file handles are used to access the DB (to retain across
subsequent requests)
3. No LOCAL or MY variables are defined in the subroutine.
4. As the webpage is being built into a global variable, the "buildpage"
subroutine doesn't RETURN a value to the calling script.
It SEEMS the subroutine is taking an inordinate amount of time returning to
the main procedure.. why would this be ?
( I'm running Free/BSD, Apache/1.3.22, Mod_perl 1.26 )
