Finding bottlenecks in the code

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

Speed Demons,

In the begining I had simple code, and it ran fast, and it was good. Then I changed my text file data to a SQLite database, mucked around for a while, created a lot of complicated code, and it all became slow. The code is a wiki/blog hybrid I have been writing for a while using the usual web-type modules (CGI::Simple, HTML::Template, DBD::SQLite, etc.)

I set up a home-grown profiling system using Time::HiRes and gettimeofday and tv_interval. I wrapped every sub in my $start_time, $end_time, and tv_interval($start_time, $end_time) "debugger" and got some indication of where relative time was going. However, the total time taken for the script to do its work is of course way more than what my debugger reports. I did mention, it is a home-grown debugger.

So, I decided to go the pro way and called on Devel::Profiler. I got the tmon.out alright, but dprofpp quits with the infamous Garbled profile, missing an enter time stamp at /usr/bin/dprofpp line 792, <fh> line 518.

504: & 57 DBD::_::st fetchall_arrayref
505: * 57
506: + 28
507: @ 0 0 1
508: * 29
509: * 22
510: - 22
511: * 30
512: - 30
513: @ 0 0 1
514: - 57
515: + 31
516: - 31
517: @ 0 0 1
518: - 55
[download]

Seems like another monk had a similar problem, and, like mine, it was also related to DBD calls. Unfortunately, that thread led to no resolution.

So... what do I do next? I ask both for help with profiling my code, as well as possible improvements to it by way of possible gotchas that could be slowing it down. I know I haven't provided the code here, but I am really looking for the "usual suspects" that I should look for. As I said, the web-server is not a problem -- it is just my localhost, and serves up other sites of mine quite briskly.

--

when small people start casting long shadows, it is time to go to bed

Comment on Finding bottlenecks in the code Select or Download Code

Replies are listed 'Best First'.
Re: Finding bottlenecks in the code by BrowserUk (Patriarch) on Jun 12, 2005 at 15:47 UTC
I've had less problems using Devel::SmallProf than many others. Be warned, it profiles line by line and so really slows down the runtime of your code, but the results seem pretty accurate. Examine what is said, not who speaks -- Silence betokens consent -- Love the truth but pardon error. Lingua non convalesco, consenesco et abolesco. -- Rule 1 has a caveat! -- Who broke the cabal? "Science is about questioning the status quo. Questioning authority". The "good enough" maybe good enough for the now, and perfection maybe unobtainable, but that should not preclude us from striving for perfection, when time, circumstance or desire allow.	[reply] [d/l]
Re^2: Finding bottlenecks in the code by punkish (Priest) on Jun 12, 2005 at 16:36 UTC
Yes, better luck with Devel::SmallProf, however, as you say, it is line-by-line profiling. Most of the profiling seems to be going on in the packages that are not in my control (HTML::Template, DBI, etc.). So, I am still in unhappy-town. I am going with the assumption that it is my code that is wrong, and solving that is a task as it is. Trying to figure out what is going on in something like H::T or DBI or CGI::Simple is way beyond me. -- when small people start casting long shadows, it is time to go to bed	[reply]
Re^3: Finding bottlenecks in the code by BrowserUk (Patriarch) on Jun 12, 2005 at 18:23 UTC
Being selective in what you profile may help. From the Devel::SmallProf POD %DB::packages To only profile code in a certain package, set the %DB::packages array. For example, to see only the code in packages main and Test1, do this: `%DB::packages = ( 'main' => 1, 'Test1' => 1 );` [download] Examine what is said, not who speaks -- Silence betokens consent -- Love the truth but pardon error. Lingua non convalesco, consenesco et abolesco. -- Rule 1 has a caveat! -- Who broke the cabal? "Science is about questioning the status quo. Questioning authority". The "good enough" maybe good enough for the now, and perfection maybe unobtainable, but that should not preclude us from striving for perfection, when time, circumstance or desire allow.	[reply] [d/l]
Re: Finding bottlenecks in the code by davidrw (Prior) on Jun 12, 2005 at 15:34 UTC
Devel::Cover can make you a nicely formatted output that shows the relative expense of every line. For example, it might show that a certain `$sth->execute($sql)` takes a ton of time, which is my first 'usual suspect' -- the db calls. are you _sure_ there's no slow queries (everything has, and is using, an index, etc)? Is there any code (or even sql) you can provide? Maybe just a small segment that is known or suspected to be slow?	[reply] [d/l]
Re^2: Finding bottlenecks in the code by punkish (Priest) on Jun 12, 2005 at 16:27 UTC
Well, I installed Devel::Cover and got, really nothing. `perl -MDevel::Cover index.cgi Devel::Cover 0.53: Collecting coverage data for branch, condition, pod +, statement, subroutine and time. Selecting packages matching: Ignoring packages matching: /Devel/Cover[./] Ignoring packages in: . /Library/Perl /Library/Perl/5.8.1 /Library/Perl/5.8.1/darwin-thread-multi-2level /System/Library/Perl/5.8.1 /System/Library/Perl/5.8.1/darwin-thread-multi-2level .. bunch of output from my index.cgi .. bus error` [download] Then, an empty coverage.html -- when small people start casting long shadows, it is time to go to bed	[reply] [d/l]
Re^3: Finding bottlenecks in the code by davidrw (Prior) on Jun 12, 2005 at 16:59 UTC
You have to explicitly tell Devel::Cover what files to cover. See the docs for specifics, but something along the lines of (note it sets the output to go into /tmp/covertest/): `/usr/bin/perl -MDevel::Cover=-db,/tmp/covertest,-silent,0,-ignore,.,-s +elect,/home/you/your_pm index.cgi` [download]	[reply] [d/l]
Re: Finding bottlenecks in the code by dragonchild (Archbishop) on Jun 12, 2005 at 21:07 UTC
99% of the time, the cost of an action involving a database call is in the database. Especially, if you're using DBD::SQLite for anything more than a toy. DBD::SQLite is, frankly, less than optimizable. The biggest problem is how the columns are compared, especially dates. I would look at DBM::Deep over DBD::SQLite. I guarantee you'll notice a large speedup if you're at least halfway decent. In general, if you think something isn't in Perl, try it out, because it usually is. :-) "What is the sound of Perl? Is it not the sound of a wall that people have stopped banging their heads against?"	[reply]
Re: Finding bottlenecks in the code by TedPride (Priest) on Jun 12, 2005 at 20:42 UTC
The delay isn't going to be in CGI::Simple. It's either in the templating or the database calls. Separate your database calls from the rest of the code and compare run time with overall time. If the database calls are only a small fraction of overall time, you need to speed up your templating system, most likely by hard coding your highest traffic pages rather than templating. If your database calls use up most of the overall time, look into indexes and optimizing your database fairly often. EDIT: This node may help: Clocking Portion of Your Perl Code	[reply]
Re: Finding bottlenecks in the code by punkish (Priest) on Jun 13, 2005 at 04:45 UTC
Update: It was Filter::Indent::HereDoc which depends on Filter::Simple, which I believe depends on Text::Balanced. Took out F::I::H, re-indented all my HereDocs, and things fly. I am back in happy land, partially. I really do hate having to slide my HereDocs to the 0th column of the page instead of aligning neatly with the other prettily indented code. How do monks deal with this, if they do? Thanks to BrowserUk's guidance, I got valuable mileage out of Devel::SmallProf. Fiddling around with various options, then going through the output, I have narrowed down the problem to Text::Balanced (see the top 8 worst perf hits below). `Text/Balanced.pm count wall tm cpu time line 47236 14.17731 13.93000 921: if (ref($func) eq 'CODE') 21983 7.933862 7.570000 952: if ($$textref =~ /\G(.)/gcs) 47236 1.307192 3.120000 918: $func = $func[$i]; 47236 1.252747 3.180000 930: if (defined($field) && length($field +)) 47236 1.168986 2.850000 919: $class = $class[$i]; 47236 1.068727 3.260000 920: $lastpos = pos $$textref; 47236 1.064919 3.290000 929: $pref \|\|= ""; 25253 1.048240 2.080000 915: foreach my $i ( 0..$#func )` [download] Since I didn't directly call this module in use, obviously I am doing something that is calling its services. The modules I am using are -- HTML::Template CGI::Simple CGI::Carp qw(fatalsToBrowser set_message) Exporter Time::Local DBI HTML::Template Filter::Indent::HereDoc Time::HiRes qw(gettimeofday tv_interval) I am also doing a bunch of regexp matching (does that call T::B?), but that seems to be very, very fast in the smallprof.out. More guidance welcome. Where I am bringing in T::B? What can I do to avoid it, or to speed it. Many thanks to everyone thus far. -- when small people start casting long shadows, it is time to go to bed	[reply] [d/l]