April 09, 2001
Profiling in Perl
brian d foy
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.
Dr. Dobb's Journal 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:
Performance of fibonacci()
| 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.6N ).
Performance of fibonacci()
| N | F(N) | Subroutine calls | time, seconds |
| 5 | 5 | 15 | 0 |
| 10 | 55 | 177 | 0 |
| 15 | 610 | 1,973 | 0.01 |
| 20 | 6,765 | 21,891 | 0.1 |
| 25 | 75,025 | 242,785 | 1 |
| 30 | 832,040 | 2,692,537 | 12 |
| 35 | 9,227,465 | 29,860,703 | 136 |
| 40 | 102,334,155 | 331,160,281 | 1607 |
|
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.
1
|
2
Next Page
more
