Run-Time Speed

If you don't spend all day playing video games, you will be quite happy without the latest and greatest CPU, and you can save money on hardware while saving power and reducing your personal CO² footprint.

But what happens if a Perl program does not perform as well as you would like? As a first step, you might be able to accelerate the program with very little effort by optimizing the code at neuralgic points.

In most cases, just one or two targeted improvements will help you achieve 90 percent of the total optimization potential. The remaining 10 percent are more likely to involve wide-ranging, architectural changes that take 10 times as long to implement and make the resulting program so difficult to maintain that more experienced developers are likely to turn down the option.

Profilers are programs that discover bottlenecks, or hotspots. They show you where the program spends most of its time and help to optimize these crucial sections in a targeted way.

Perl has many tools of this kind. For example, if a module uses the Log4perl logging framework, it is simple to display the number of milliseconds (msec) that elapse along with the log messages, thus creating a timescale.

Finding Bottlenecks

The simple test script amzntest (Listing 1) uses the CPAN Net::Amazon module to retrieve book details from the Amazon Web API (assuming you enter a valid token, which you can get from Amazon Web Services [2]).

01 #!/usr/bin/perl
02 use warnings;
03 use strict;
04 use Net::Amazon;
05 use Net::Amazon::Request::ASIN;
06
07 my $asin = "0132396556";
08
09 my $ua = Net::Amazon->new(
10     token => 'XXXXXXXXXXXXXXX',
11 );
12
13 my $req = Net::Amazon::Request::ASIN->new(
14     asin  => $asin,
15 );
16
17 my $resp = $ua->request($req);
18
19 if($resp->is_success()) {
20     print $resp->as_string(), "\n";
21 } else {
22     print "Error: ",
23           $resp->message(), "\n";
24 }

A request takes about a second, but what does the script use this time for – picking up the data or the analyzing the XML response? Adding

use Log::Log4perl;
 Log::Log4perl->init("timer.l4p");

to the script header enables the Log4perl statements embedded in Net::Amazon by loading the timer.l4p configuration file. This outputs the date (%d) and the number of milliseconds since the program started (%r) for each message it logs. The logging level is set to DEBUG and is thus fairly verbose.

To cut down on lengthy log messages, the configuration file in Listing 2 uses the abbreviation %S to define a so-called Custom Cspec. This appears in the layout, instead of the more typical %m (for the log message).

The associated Perl subroutine returns a shorter, 25-character message to the screen appender. The layout closes with a platform-dependent newline character defined by %n.

1 log4perl.logger          = DEBUG, App
2 log4perl.appender.App    = Log::Log4perl::Appender::Screen
3 log4perl.appender.App.layout = PatternLayout
4 log4perl.appender.App.layout.ConversionPattern = %d %r %S%n
5 log4perl.PatternLayout.cspec.S = sub { substr($_[1], 0, 25) }

Quick Fix

Figure 1 shows that Net::Amazon sends a web request to Amazon 79msec after the program launches; however, the XML parser does not start working until 739msec have elapsed. Thus, the web request takes 75 percent of the 800msec required by the script.

Figure 1: Log4perl outputs the time of day and the number of milliseconds (79msec) that have elapsed since the program was launched.

As you will agree, it makes sense to use a web cache for frequently retrieved ASIN numbers, and Net::Amazon enables this if we ask it to (see Listing 3). This really does reduce the script run time, which drops to 180msec for repetitions (see Figure 2) with the use of File::Cache as a persistent cache.

Figure 2: The use of a web cache removes the need to issue a web request in case of repetitions, thus reducing the run time by 75 percent.

01 use Cache::File;
02 my $cache = Cache::File->new(
03    cache_root        => '/tmp/mycache',
04    default_expires   => '30 min',
05 );
06
07 my $ua = Net::Amazon->new(
08     token => '0AQN5ZBDW6NXV9M60N82',
09     cache => $cache,
10 );

Quick Results

Now you might argue that tricks of this kind aren't always going to help, but the decisive issue here is that five lines of code and a minute spent thinking about options achieved a speed boost of 400 percent.