Recursive subroutines are essential for many tasks. But they can slow your app to a crawl if handled incorrectly. Perl's profiler can help pinpoint the bottlenecks.
In the previous article in this series I introduced you to the Perl debugger and showed you how to write your own. As an example, I created a couple of tools that are typically called profilers because they give information about the program being executed. Now let's use one of the popular profilers available from the Comprehensive Perl Archive Network (CPAN).
Profilers allow you to look at the execution of a program from different perspectives. One of the profilers that I created in the last article allowed me to see the number of times a line was executed during the run of the program (a line profiler) so that I could see which statements were being executed the most. The Devel::SmallProf module does that as well as measuring the total execution time of each of the lines. The time that the program spends on a particular bit of code can be more important than the number of times that it is executed (although the two may be related).
Consider one of the examples from the previous article. This one line of code may take several seconds or even minutes, because it does a lot behind the scenes to fetch information over a network:
#!/usr/bin/perl use LWP::Simple; getstore( 'http://www.perl.org', 'www.perl.org.html' ); __END__ 
However, a seemingly more complex line takes no time at all:
#!/usr/bin/perl print map { $_ ** 2 } grep { $_ % 2 } sort { $a <=> $b } @ARGV; __END__ 
You can easily tell where the program spends its time in these simple examples, but in a large project, you probably will not be able to tell simply by inspection. Indeed, this is why programmers created profilers.
You invoke the profiler by specifying which debugger you want to use through the d switch. Remember that perl assumes the module is in the Devel::* namespace.
prompt$ perl d:SmallProf my_script.pl 
The Devel::SmallProf module sends its results (the profile) to a special file called smallprof.out in the current working directory.
To demonstrate this profiler I created a small program with a
recursive subroutine to calculate Fibonacci numbers, which I
call fibonacci.pl
. Around the year 1202 while
travelling the world, Leonardo
Pisano Fibonacci wondered how fast rabbits could breed. If
two rabbits bred to produce two more rabbits, and then each of
those pairs bred, ad infinitum, how many rabbits are there at a
particular point in time? More precisely, Fibonacci asked in
his mathematical treatise Liber abbaci:
A certain man put a pair of rabbits in a place surrounded on all sides by a wall. How many pairs of rabbits can be produced from that pair in a year if it is supposed that every month each pair begets a new pair which from the second month on becomes productive?
To describe this situation, Fibonacci came up with a sequence of numbers such that the next number in the sequence is the sum of the previous two, with the boundary condition that the first two numbers in the sequence are 0 and 1. If I name the function which generates the Nth Fibonacci number F(N), and F(0) is 0 and F(1) is 1 by definition, then F(2) is F( 2  1 ) + F( 2  2 ) which is F(1) + F(0), which turns out to be 1. Going on, F(3) is F( 3  1 ) + F( 3  2 ), which is F(2) + F(1) which we expand to F( 2  1 ) + F( 2  2 ) + F(1), which is F(1) + F(0) + F(1) which is 2. As N gets larger, I have to do a lot more work to compute the Fibonacci number, and a lot more work to take care of all of those rabbits. Since I notice the recursive nature of the computation, I can write a recursive subroutine (that calls itself) to do the work. This example not only shows how computationally expensive recursive subroutines can be, but I can highlight another Perl module that is a dropin fix for that.
#!/usr/bin/perl sub fibonacci { my $index = shift; return 0 if $index == 0; return 1 if $index == 1; return fibonacci( $index  1 ) + fibonacci( $index  2 ); } print "F($ARGV[0]) is ", fibonacci($ARGV[0]), "\n"; __END__ 
My test program takes a single argument (which shows up in the first element of the special @ARGV array, $ARGV[0]) — the Fibonacci number to compute.
prompt$ perl fibonacci.pl 10 F(10) is 55 
The larger N is, the longer the program takes to complete and the time to finish increases exponentially with N. Try it yourself to see if your computer is faster than mine:
Performance of

N  F(N)  time, seconds 
5  5  0 
10  55  0 
15  610  0.01 
20  6,765  0.1 
25  75,025  1 
30  832,040  12 
35  9,227,465  136 
40  102,334,155  1607 
Why is this program so slow for N above 30? The Devel::SmallProf module gives me a big hint. I already know why it is slow because I made this program to be slow, but in a much larger code base, especially one you inherit, you may not know ahead of time which parts are slow.
I run fibonacci.pl using the Devel::SmallProf debugger to determine the Fibonacci number for N = 40 — the number of rabbits I would have after about three years.
prompt$ perl d:SmallProf fibonacci.pl 40 
================ SmallProf version 0.9 ================ Profile of fib.pl Page 1 ================================================================= count wall tm cpu time line 0 0.000000 0.000000 1:#!/usr/bin/perl 0 0.000000 0.000000 2: 0 0.000000 0.000000 3:sub fibonacci 331160281 0.000000 0.000000 4: { 331160281 11031.59 16482.02 5: my $index = shift; 0 0.000000 0.000000 6: 331160281 15974.55 20532.39 7: return 0 if $index == 0; 267914295 15604.80 19898.51 8: return 1 if $index == 1; 0 0.000000 0.000000 9: 165580140 16967.53 18064.83 10: return fibonacci( $index  1 ) + 0 0.000000 0.000000 11: } 0 0.000000 0.000000 12: 1 0.000116 0.000000 13:print "F($ARGV[0]) is ", fibonacci($ARGV[0]), 0 0.000000 0.000000 14: 0 0.000000 0.000000 15:__END__ 
The output has several columns. The first column shows the number of times that line was executed. The next two columns show the total real time (i.e. wall clock time) from Time::HiRes and CPU time (the time actually spent on the computation), from times, for the line. Then the line number is displayed in front the line of code.
Simply looking at the first column of smallprof.out I notice that the program executes some lines of code a very large number of times, even though I only directly called the fibonacci() routine once. Every time I want to compute a Fibonacci number, I have to compute other numbers, and the same for each of those. I end up doing the same work over and over again which wastes the computer's time. However, now that I have identified the problem I can fix it.
Now I can rework this table to include the number of times the fibonacci() subroutine is called. Ambitious readers can calculate the coefficient for Omega( 1.6^{N} ).
Performance of fibonacci()

In this case, I can solve the problem by caching the results in between invocations of the subroutine. If I remember what F(N1) is, I do not have to compute it the next time I need it. I could store these previous results in a globally scoped array, but then I would have to do a bit more coding, and I would have to do similar coding for each routine that I wanted to fix. However, laziness is one of the three virtues of a true programmer. Laziness means creating a general solution that we can use over and over again to make our lives easier. I just described the Memoize module.
The Memoize module is a dropin solution that caches the results of subroutines so that we do not have to waste time doing work that we have already done. The module, through its magic, memoizes, or remembers the result of, a call to a subroutine with a particular argument list. In this case, Memoize stores the results of each call to fibonacci() so that we do not have to keep calling the subroutine.
I modified my earlier program to use the Memoize module. I simply tell Memoize which functions need help and let it do the rest.
#!/usr/bin/perl use Memoize; memoize('fibonacci'); sub fibonacci { my $index = shift; return 0 if $index == 0; return 1 if $index == 1; return fibonacci( $index  1 ) + fibonacci( $index  2 ); } print "F($ARGV[0]) is ", fibonacci($ARGV[0]), "\n"; __END__ 
If I run this program for N = 40 I find that it finishes almost instantaneously (at least compared to the last program). If I use the Devel::SmallProf module I can see the change when I run the script again.
prompt$ perl d:SmallProf fibonacci.pl 40 
Since I have run another script under the Devel::SmallProf debugger, the previous results in smallprof.out are overwritten with the new results. Now smallprof.out contains the new profile shown in Example 1.
The smallprof.out file, which I have edited to remove several other pages
of output dealing with behindthescenes magic from Memoize
and its included modules, shows some extra code pulled in from Memoize,
but it takes almost no time to do its magic. However, I notice the same lines
in the fibonacci()
routine run only 41 times. The same lines for
the same input were executed 204,668,309 times in the previous program. The
Memoize
did its magic and drastically sped up my program. The Devel::SmallProf
module is the magic which told me what to fix.
Now that you know how to use a profiler to get information about a program, try the Devel::SmallProf module or some of the other profilers found on Devel::*. Your code will be running faster in no time, which will give you more time to care for all of those rabbits.
brian d foy has been a Perl user since 1994. He is founder of the first Perl users group, NY.pm, and Perl Mongers, the Perl advocacy organization. He has been teaching Perl through Stonehenge Consulting for the past three years, and has been a featured speaker at The Perl Conference, Perl University, YAPC, COMDEX, and Builder.com. Some of brian's other articles have appeared in The Perl Journal.