Re: Subroutines taking time to return..
Great feedback, many thanks. But as always, one problem becomes another ! I've compiled + installed Apache-DB I've compiled + installed DProf-19990108 I've added this to my httpd.conf: PerlModule Apache::DProf I've added this to my modperl.conf (called by httpd.conf): use Apache::DProf; use Apache::DB; Apache::DB-init; When Apache startsup I get: [notice] Apache::DB initialized in child 55178 All good and well I thought.. But erm.. nothing is being created in the dprof directory in the server-root. What am I doing wrong ? Regards
Re: Subroutines taking time to return..
David Brown wrote: Great feedback, many thanks. But as always, one problem becomes another ! I've compiled + installed Apache-DB I've compiled + installed DProf-19990108 I've added this to my httpd.conf: PerlModule Apache::DProf I've added this to my modperl.conf (called by httpd.conf): use Apache::DProf; use Apache::DB; Apache::DB-init; When Apache startsup I get: [notice] Apache::DB initialized in child 55178 All good and well I thought.. But erm.. nothing is being created in the dprof directory in the server-root. What am I doing wrong ? You aren't doing it wrong. Next step is to run the script and usually it helps to read the docs :) http://thingy.kcilink.com/modperlguide/performance/Code_Profiling_Techniques.html _ Stas Bekman JAm_pH -- Just Another mod_perl Hacker http://stason.org/ mod_perl Guide http://perl.apache.org/guide mailto:[EMAIL PROTECTED] http://ticketmaster.com http://apacheweek.com http://singlesheaven.com http://perl.apache.org http://perlmonth.com/
Re: Subroutines taking time to return..
Thankyou, but I have read the documentation. Nothing gets written to a rootdir/dprof directory, not even an empty file when the scripts are run. You aren't doing it wrong. Next step is to run the script and usually it helps to read the docs :)
Re: Subroutines taking time to return..
David Brown wrote: Thankyou, but I have read the documentation. Nothing gets written to a rootdir/dprof directory, not even an empty file when the scripts are run. sorry, you should have told this :0) Could be write permissions? Can you profile a normal perl script? You aren't doing it wrong. Next step is to run the script and usually it helps to read the docs :) -- _ Stas Bekman JAm_pH -- Just Another mod_perl Hacker http://stason.org/ mod_perl Guide http://perl.apache.org/guide mailto:[EMAIL PROTECTED] http://ticketmaster.com http://apacheweek.com http://singlesheaven.com http://perl.apache.org http://perlmonth.com/
Re: Subroutines taking time to return..
David Brown wrote: All good and well I thought.. But erm.. nothing is being created in the dprof directory in the server-root. When you call the script, do you get segfaults in the error log? Make sure that you do the DProf stuff, including Apache::DB-init(), before you load any of your other modules. Otherwise, the debugging symbols don't get put into your code. - Perrin
Re: Subroutines taking time to return..
OK, I have it working now. I had to manually create the dprof directory in APACHEROOT/logs (I had expected it to be created), and then set the permissions such that apache (running as user: nobody) could write to it. Sorted. Thanks for your guidance guys. - Original Message - From: Perrin Harkins [EMAIL PROTECTED] To: David Brown [EMAIL PROTECTED] Cc: [EMAIL PROTECTED] Sent: Thursday, March 21, 2002 7:07 PM Subject: Re: Subroutines taking time to return.. David Brown wrote: All good and well I thought.. But erm.. nothing is being created in the dprof directory in the server-root. When you call the script, do you get segfaults in the error log? Make sure that you do the DProf stuff, including Apache::DB-init(), before you load any of your other modules. Otherwise, the debugging symbols don't get put into your code.
Re: Subroutines taking time to return..
Hi there, On Thu, 21 Mar 2002, Perrin Harkins wrote: When you call the script, do you get segfaults in the error log? Coming into this thread a little late, so sorry if you already said, what version of Perl are you using? I had problems with Devel::Dprof and dprofpp on 5.7.1 which were fixed by upgrading to 5.7.2 although Dprof itself didn't change at all. 73, Ged.
Re: Subroutines taking time to return..
Hi again, On Thu, 21 Mar 2002, David Brown wrote: OK, I have it working now. Guess I shold read ALL my mail before replying to any of it... 73, Ged.
Subroutines taking time to return..
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 )
Re: Subroutines taking time to return..
Have you tried using Apache::DProf? Using this is a lot easier than
trying to add tons of debug messages. If you haven't used it or the
regular DProf, it does what your doing automatically. It generates a
file of data that you run 'dprofpp' on and you can get a list of the top
10 or so most time consuming functions. Using Apache::DProf usually
reveals time consuming methods in my code that I would never have
expected to take so long.
In your case, however thourough you were in placing debug statements,
its possible (and likely) that you've missed the key subroutine.
G
On Wed, 2002-03-20 at 09:59, David Brown wrote:
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 )
Re: Subroutines taking time to return..
Hi there, On Wed, 20 Mar 2002, David Brown wrote: I've been profiling my MySQL driven Mod_Perl website [snip] (using Time::HiRes) [snip] I expected all the complicated DB access stuff to make up the time MySQL is pretty quick. :) instead it seems to be consuming 0.005 in returning from the subroutine to the main script. What's that all about ? [snip] It SEEMS the subroutine is taking an inordinate amount of time returning to the main procedure.. why would this be ? What else is the machine doing? Is it reapeatable (i.e. not just OS timeslices or something)? Post the code? 73, Ged.
Re: Subroutines taking time to return..
Perrin Harkins wrote: You cannot reliably measure CPU clocks with wallclock on the multi-processor machine, unless you are running on Dos :) Even so, wall time is what most people actually care about, and it's fine to use if you're the only one doing work on that machine. Yes, for counting the total run-time of the code that does something. No, for benchmarking nearly-empty subroutines run times. Since the error here can be 1000% and more. You are still running on time-sharing machine and if your sub didn't fit into one CPU timeslice, but the other did, the relative difference can be tremendous, while in fact both subs consume approximately the same number of CPU clocks. This can lead to very wrong conclusions. Also search the archives, about a year ago I've posted a subclass to DBI that measures the SQL execution profiling. I'm not sure if Tim has this unctionality in the latest DBI. DBIx::Profile does a good job of this. cool :) -- _ Stas Bekman JAm_pH -- Just Another mod_perl Hacker http://stason.org/ mod_perl Guide http://perl.apache.org/guide mailto:[EMAIL PROTECTED] http://ticketmaster.com http://apacheweek.com http://singlesheaven.com http://perl.apache.org http://perlmonth.com/
