Profiling in Perl

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 drop-in 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:

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 ).

In this case, I can solve the problem by caching the results in between invocations of the subroutine. If I remember what F(N-1) 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 drop-in 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 behind-the-scenes 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.