143003dfeSmillert=head1 NAME 243003dfeSmillert 343003dfeSmillertperlperf - Perl Performance and Optimization Techniques 443003dfeSmillert 543003dfeSmillert=head1 DESCRIPTION 643003dfeSmillert 743003dfeSmillertThis is an introduction to the use of performance and optimization techniques 843003dfeSmillertwhich can be used with particular reference to perl programs. While many perl 943003dfeSmillertdevelopers have come from other languages, and can use their prior knowledge 1043003dfeSmillertwhere appropriate, there are many other people who might benefit from a few 1143003dfeSmillertperl specific pointers. If you want the condensed version, perhaps the best 1243003dfeSmillertadvice comes from the renowned Japanese Samurai, Miyamoto Musashi, who said: 1343003dfeSmillert 1443003dfeSmillert "Do Not Engage in Useless Activity" 1543003dfeSmillert 1643003dfeSmillertin 1645. 1743003dfeSmillert 1843003dfeSmillert=head1 OVERVIEW 1943003dfeSmillert 2043003dfeSmillertPerhaps the most common mistake programmers make is to attempt to optimize 2143003dfeSmillerttheir code before a program actually does anything useful - this is a bad idea. 2243003dfeSmillertThere's no point in having an extremely fast program that doesn't work. The 2343003dfeSmillertfirst job is to get a program to I<correctly> do something B<useful>, (not to 2443003dfeSmillertmention ensuring the test suite is fully functional), and only then to consider 2543003dfeSmillertoptimizing it. Having decided to optimize existing working code, there are 2643003dfeSmillertseveral simple but essential steps to consider which are intrinsic to any 2743003dfeSmillertoptimization process. 2843003dfeSmillert 2943003dfeSmillert=head2 ONE STEP SIDEWAYS 3043003dfeSmillert 3143003dfeSmillertFirstly, you need to establish a baseline time for the existing code, which 3243003dfeSmillerttiming needs to be reliable and repeatable. You'll probably want to use the 33898184e3SsthenC<Benchmark> or C<Devel::NYTProf> modules, or something similar, for this step, 34b39c5158Smillertor perhaps the Unix system C<time> utility, whichever is appropriate. See the 3543003dfeSmillertbase of this document for a longer list of benchmarking and profiling modules, 3643003dfeSmillertand recommended further reading. 3743003dfeSmillert 3843003dfeSmillert=head2 ONE STEP FORWARD 3943003dfeSmillert 4043003dfeSmillertNext, having examined the program for I<hot spots>, (places where the code 4143003dfeSmillertseems to run slowly), change the code with the intention of making it run 4243003dfeSmillertfaster. Using version control software, like C<subversion>, will ensure no 4343003dfeSmillertchanges are irreversible. It's too easy to fiddle here and fiddle there - 4443003dfeSmillertdon't change too much at any one time or you might not discover which piece of 4543003dfeSmillertcode B<really> was the slow bit. 4643003dfeSmillert 4743003dfeSmillert=head2 ANOTHER STEP SIDEWAYS 4843003dfeSmillert 4943003dfeSmillertIt's not enough to say: "that will make it run faster", you have to check it. 5043003dfeSmillertRerun the code under control of the benchmarking or profiling modules, from the 5143003dfeSmillertfirst step above, and check that the new code executed the B<same task> in 5243003dfeSmillertI<less time>. Save your work and repeat... 5343003dfeSmillert 5443003dfeSmillert=head1 GENERAL GUIDELINES 5543003dfeSmillert 5643003dfeSmillertThe critical thing when considering performance is to remember there is no such 5743003dfeSmillertthing as a C<Golden Bullet>, which is why there are no rules, only guidelines. 5843003dfeSmillert 5943003dfeSmillertIt is clear that inline code is going to be faster than subroutine or method 6043003dfeSmillertcalls, because there is less overhead, but this approach has the disadvantage 6143003dfeSmillertof being less maintainable and comes at the cost of greater memory usage - 6243003dfeSmillertthere is no such thing as a free lunch. If you are searching for an element in 6343003dfeSmillerta list, it can be more efficient to store the data in a hash structure, and 6443003dfeSmillertthen simply look to see whether the key is defined, rather than to loop through 6543003dfeSmillertthe entire array using grep() for instance. substr() may be (a lot) faster 6643003dfeSmillertthan grep() but not as flexible, so you have another trade-off to access. Your 6743003dfeSmillertcode may contain a line which takes 0.01 of a second to execute which if you 6843003dfeSmillertcall it 1,000 times, quite likely in a program parsing even medium sized files 6943003dfeSmillertfor instance, you already have a 10 second delay, in just one single code 7043003dfeSmillertlocation, and if you call that line 100,000 times, your entire program will 7143003dfeSmillertslow down to an unbearable crawl. 7243003dfeSmillert 7343003dfeSmillertUsing a subroutine as part of your sort is a powerful way to get exactly what 7443003dfeSmillertyou want, but will usually be slower than the built-in I<alphabetic> C<cmp> and 7543003dfeSmillertI<numeric> C<E<lt>=E<gt>> sort operators. It is possible to make multiple 7643003dfeSmillertpasses over your data, building indices to make the upcoming sort more 7743003dfeSmillertefficient, and to use what is known as the C<OM> (Orcish Maneuver) to cache the 7843003dfeSmillertsort keys in advance. The cache lookup, while a good idea, can itself be a 7943003dfeSmillertsource of slowdown by enforcing a double pass over the data - once to setup the 8043003dfeSmillertcache, and once to sort the data. Using C<pack()> to extract the required sort 8143003dfeSmillertkey into a consistent string can be an efficient way to build a single string 8243003dfeSmillertto compare, instead of using multiple sort keys, which makes it possible to use 8343003dfeSmillertthe standard, written in C<c> and fast, perl C<sort()> function on the output, 8443003dfeSmillertand is the basis of the C<GRT> (Guttman Rossler Transform). Some string 85b8851fccSafresh1combinations can slow the C<GRT> down, by just being too plain complex for its 8643003dfeSmillertown good. 8743003dfeSmillert 8843003dfeSmillertFor applications using database backends, the standard C<DBIx> namespace has 8943003dfeSmillerttries to help with keeping things nippy, not least because it tries to I<not> 9043003dfeSmillertquery the database until the latest possible moment, but always read the docs 9143003dfeSmillertwhich come with your choice of libraries. Among the many issues facing 9243003dfeSmillertdevelopers dealing with databases should remain aware of is to always use 9343003dfeSmillertC<SQL> placeholders and to consider pre-fetching data sets when this might 9443003dfeSmillertprove advantageous. Splitting up a large file by assigning multiple processes 9543003dfeSmillertto parsing a single file, using say C<POE>, C<threads> or C<fork> can also be a 9643003dfeSmillertuseful way of optimizing your usage of the available C<CPU> resources, though 9743003dfeSmillertthis technique is fraught with concurrency issues and demands high attention to 9843003dfeSmillertdetail. 9943003dfeSmillert 10043003dfeSmillertEvery case has a specific application and one or more exceptions, and there is 10143003dfeSmillertno replacement for running a few tests and finding out which method works best 10243003dfeSmillertfor your particular environment, this is why writing optimal code is not an 10343003dfeSmillertexact science, and why we love using Perl so much - TMTOWTDI. 10443003dfeSmillert 10543003dfeSmillert=head1 BENCHMARKS 10643003dfeSmillert 10743003dfeSmillertHere are a few examples to demonstrate usage of Perl's benchmarking tools. 10843003dfeSmillert 10943003dfeSmillert=head2 Assigning and Dereferencing Variables. 11043003dfeSmillert 11143003dfeSmillertI'm sure most of us have seen code which looks like, (or worse than), this: 11243003dfeSmillert 11343003dfeSmillert if ( $obj->{_ref}->{_myscore} >= $obj->{_ref}->{_yourscore} ) { 11443003dfeSmillert ... 11543003dfeSmillert 11643003dfeSmillertThis sort of code can be a real eyesore to read, as well as being very 11743003dfeSmillertsensitive to typos, and it's much clearer to dereference the variable 11843003dfeSmillertexplicitly. We're side-stepping the issue of working with object-oriented 11943003dfeSmillertprogramming techniques to encapsulate variable access via methods, only 12043003dfeSmillertaccessible through an object. Here we're just discussing the technical 12143003dfeSmillertimplementation of choice, and whether this has an effect on performance. We 12243003dfeSmillertcan see whether this dereferencing operation, has any overhead by putting 12343003dfeSmillertcomparative code in a file and running a C<Benchmark> test. 12443003dfeSmillert 12543003dfeSmillert# dereference 12643003dfeSmillert 12743003dfeSmillert #!/usr/bin/perl 12843003dfeSmillert 129eac174f2Safresh1 use v5.36; 13043003dfeSmillert 13143003dfeSmillert use Benchmark; 13243003dfeSmillert 13343003dfeSmillert my $ref = { 13443003dfeSmillert 'ref' => { 13543003dfeSmillert _myscore => '100 + 1', 13643003dfeSmillert _yourscore => '102 - 1', 13743003dfeSmillert }, 13843003dfeSmillert }; 13943003dfeSmillert 14043003dfeSmillert timethese(1000000, { 14143003dfeSmillert 'direct' => sub { 14243003dfeSmillert my $x = $ref->{ref}->{_myscore} . $ref->{ref}->{_yourscore} ; 14343003dfeSmillert }, 14443003dfeSmillert 'dereference' => sub { 14543003dfeSmillert my $ref = $ref->{ref}; 14643003dfeSmillert my $myscore = $ref->{_myscore}; 14743003dfeSmillert my $yourscore = $ref->{_yourscore}; 14843003dfeSmillert my $x = $myscore . $yourscore; 14943003dfeSmillert }, 15043003dfeSmillert }); 15143003dfeSmillert 15243003dfeSmillertIt's essential to run any timing measurements a sufficient number of times so 15343003dfeSmillertthe numbers settle on a numerical average, otherwise each run will naturally 15443003dfeSmillertfluctuate due to variations in the environment, to reduce the effect of 15543003dfeSmillertcontention for C<CPU> resources and network bandwidth for instance. Running 15643003dfeSmillertthe above code for one million iterations, we can take a look at the report 15743003dfeSmillertoutput by the C<Benchmark> module, to see which approach is the most effective. 15843003dfeSmillert 15943003dfeSmillert $> perl dereference 16043003dfeSmillert 16143003dfeSmillert Benchmark: timing 1000000 iterations of dereference, direct... 16243003dfeSmillert dereference: 2 wallclock secs ( 1.59 usr + 0.00 sys = 1.59 CPU) @ 628930.82/s (n=1000000) 16343003dfeSmillert direct: 1 wallclock secs ( 1.20 usr + 0.00 sys = 1.20 CPU) @ 833333.33/s (n=1000000) 16443003dfeSmillert 16543003dfeSmillertThe difference is clear to see and the dereferencing approach is slower. While 16643003dfeSmillertit managed to execute an average of 628,930 times a second during our test, the 16743003dfeSmillertdirect approach managed to run an additional 204,403 times, unfortunately. 16843003dfeSmillertUnfortunately, because there are many examples of code written using the 16943003dfeSmillertmultiple layer direct variable access, and it's usually horrible. It is, 170b39c5158Smillerthowever, minusculy faster. The question remains whether the minute gain is 17143003dfeSmillertactually worth the eyestrain, or the loss of maintainability. 17243003dfeSmillert 17343003dfeSmillert=head2 Search and replace or tr 17443003dfeSmillert 17543003dfeSmillertIf we have a string which needs to be modified, while a regex will almost 17643003dfeSmillertalways be much more flexible, C<tr>, an oft underused tool, can still be a 17743003dfeSmillertuseful. One scenario might be replace all vowels with another character. The 17843003dfeSmillertregex solution might look like this: 17943003dfeSmillert 18043003dfeSmillert $str =~ s/[aeiou]/x/g 18143003dfeSmillert 18243003dfeSmillertThe C<tr> alternative might look like this: 18343003dfeSmillert 18443003dfeSmillert $str =~ tr/aeiou/xxxxx/ 18543003dfeSmillert 18643003dfeSmillertWe can put that into a test file which we can run to check which approach is 18743003dfeSmillertthe fastest, using a global C<$STR> variable to assign to the C<my $str> 18843003dfeSmillertvariable so as to avoid perl trying to optimize any of the work away by 18943003dfeSmillertnoticing it's assigned only the once. 19043003dfeSmillert 19143003dfeSmillert# regex-transliterate 19243003dfeSmillert 19343003dfeSmillert #!/usr/bin/perl 19443003dfeSmillert 195eac174f2Safresh1 use v5.36; 19643003dfeSmillert 19743003dfeSmillert use Benchmark; 19843003dfeSmillert 19943003dfeSmillert my $STR = "$$-this and that"; 20043003dfeSmillert 20143003dfeSmillert timethese( 1000000, { 20243003dfeSmillert 'sr' => sub { my $str = $STR; $str =~ s/[aeiou]/x/g; return $str; }, 20343003dfeSmillert 'tr' => sub { my $str = $STR; $str =~ tr/aeiou/xxxxx/; return $str; }, 20443003dfeSmillert }); 20543003dfeSmillert 20643003dfeSmillertRunning the code gives us our results: 20743003dfeSmillert 20843003dfeSmillert $> perl regex-transliterate 20943003dfeSmillert 21043003dfeSmillert Benchmark: timing 1000000 iterations of sr, tr... 21143003dfeSmillert sr: 2 wallclock secs ( 1.19 usr + 0.00 sys = 1.19 CPU) @ 840336.13/s (n=1000000) 21243003dfeSmillert tr: 0 wallclock secs ( 0.49 usr + 0.00 sys = 0.49 CPU) @ 2040816.33/s (n=1000000) 21343003dfeSmillert 21443003dfeSmillertThe C<tr> version is a clear winner. One solution is flexible, the other is 215b39c5158Smillertfast - and it's appropriately the programmer's choice which to use. 21643003dfeSmillert 21743003dfeSmillertCheck the C<Benchmark> docs for further useful techniques. 21843003dfeSmillert 21943003dfeSmillert=head1 PROFILING TOOLS 22043003dfeSmillert 22143003dfeSmillertA slightly larger piece of code will provide something on which a profiler can 22243003dfeSmillertproduce more extensive reporting statistics. This example uses the simplistic 22343003dfeSmillertC<wordmatch> program which parses a given input file and spews out a short 22443003dfeSmillertreport on the contents. 22543003dfeSmillert 22643003dfeSmillert# wordmatch 22743003dfeSmillert 22843003dfeSmillert #!/usr/bin/perl 22943003dfeSmillert 230eac174f2Safresh1 use v5.36; 23143003dfeSmillert 23243003dfeSmillert =head1 NAME 23343003dfeSmillert 23443003dfeSmillert filewords - word analysis of input file 23543003dfeSmillert 23643003dfeSmillert =head1 SYNOPSIS 23743003dfeSmillert 23843003dfeSmillert filewords -f inputfilename [-d] 23943003dfeSmillert 24043003dfeSmillert =head1 DESCRIPTION 24143003dfeSmillert 242b8851fccSafresh1 This program parses the given filename, specified with C<-f>, and 243b8851fccSafresh1 displays a simple analysis of the words found therein. Use the C<-d> 244b8851fccSafresh1 switch to enable debugging messages. 24543003dfeSmillert 24643003dfeSmillert =cut 24743003dfeSmillert 24843003dfeSmillert use FileHandle; 24943003dfeSmillert use Getopt::Long; 25043003dfeSmillert 25143003dfeSmillert my $debug = 0; 25243003dfeSmillert my $file = ''; 25343003dfeSmillert 25443003dfeSmillert my $result = GetOptions ( 25543003dfeSmillert 'debug' => \$debug, 25643003dfeSmillert 'file=s' => \$file, 25743003dfeSmillert ); 25843003dfeSmillert die("invalid args") unless $result; 25943003dfeSmillert 26043003dfeSmillert unless ( -f $file ) { 26143003dfeSmillert die("Usage: $0 -f filename [-d]"); 26243003dfeSmillert } 263b8851fccSafresh1 my $FH = FileHandle->new("< $file") 264b8851fccSafresh1 or die("unable to open file($file): $!"); 26543003dfeSmillert 26643003dfeSmillert my $i_LINES = 0; 26743003dfeSmillert my $i_WORDS = 0; 26843003dfeSmillert my %count = (); 26943003dfeSmillert 27043003dfeSmillert my @lines = <$FH>; 27143003dfeSmillert foreach my $line ( @lines ) { 27243003dfeSmillert $i_LINES++; 27343003dfeSmillert $line =~ s/\n//; 27443003dfeSmillert my @words = split(/ +/, $line); 27543003dfeSmillert my $i_words = scalar(@words); 27643003dfeSmillert $i_WORDS = $i_WORDS + $i_words; 27743003dfeSmillert debug("line: $i_LINES supplying $i_words words: @words"); 27843003dfeSmillert my $i_word = 0; 27943003dfeSmillert foreach my $word ( @words ) { 28043003dfeSmillert $i_word++; 281b8851fccSafresh1 $count{$i_LINES}{spec} += matches($i_word, $word, 282b8851fccSafresh1 '[^a-zA-Z0-9]'); 283b8851fccSafresh1 $count{$i_LINES}{only} += matches($i_word, $word, 284b8851fccSafresh1 '^[^a-zA-Z0-9]+$'); 285b8851fccSafresh1 $count{$i_LINES}{cons} += matches($i_word, $word, 286b8851fccSafresh1 '^[(?i:bcdfghjklmnpqrstvwxyz)]+$'); 287b8851fccSafresh1 $count{$i_LINES}{vows} += matches($i_word, $word, 288b8851fccSafresh1 '^[(?i:aeiou)]+$'); 289b8851fccSafresh1 $count{$i_LINES}{caps} += matches($i_word, $word, 290b8851fccSafresh1 '^[(A-Z)]+$'); 29143003dfeSmillert } 29243003dfeSmillert } 29343003dfeSmillert 29443003dfeSmillert print report( %count ); 29543003dfeSmillert 29643003dfeSmillert sub matches { 29743003dfeSmillert my $i_wd = shift; 29843003dfeSmillert my $word = shift; 29943003dfeSmillert my $regex = shift; 30043003dfeSmillert my $has = 0; 30143003dfeSmillert 30243003dfeSmillert if ( $word =~ /($regex)/ ) { 30343003dfeSmillert $has++ if $1; 30443003dfeSmillert } 30543003dfeSmillert 306b8851fccSafresh1 debug( "word: $i_wd " 307b8851fccSafresh1 . ($has ? 'matches' : 'does not match') 308b8851fccSafresh1 . " chars: /$regex/"); 30943003dfeSmillert 31043003dfeSmillert return $has; 31143003dfeSmillert } 31243003dfeSmillert 31343003dfeSmillert sub report { 31443003dfeSmillert my %report = @_; 31543003dfeSmillert my %rep; 31643003dfeSmillert 31743003dfeSmillert foreach my $line ( keys %report ) { 318eac174f2Safresh1 foreach my $key ( keys $report{$line}->%* ) { 31943003dfeSmillert $rep{$key} += $report{$line}{$key}; 32043003dfeSmillert } 32143003dfeSmillert } 32243003dfeSmillert 32343003dfeSmillert my $report = qq| 32443003dfeSmillert $0 report for $file: 32543003dfeSmillert lines in file: $i_LINES 32643003dfeSmillert words in file: $i_WORDS 32743003dfeSmillert words with special (non-word) characters: $i_spec 32843003dfeSmillert words with only special (non-word) characters: $i_only 32943003dfeSmillert words with only consonants: $i_cons 33043003dfeSmillert words with only capital letters: $i_caps 33143003dfeSmillert words with only vowels: $i_vows 33243003dfeSmillert |; 33343003dfeSmillert 33443003dfeSmillert return $report; 33543003dfeSmillert } 33643003dfeSmillert 33743003dfeSmillert sub debug { 33843003dfeSmillert my $message = shift; 33943003dfeSmillert 34043003dfeSmillert if ( $debug ) { 34143003dfeSmillert print STDERR "DBG: $message\n"; 34243003dfeSmillert } 34343003dfeSmillert } 34443003dfeSmillert 34543003dfeSmillert exit 0; 34643003dfeSmillert 34743003dfeSmillert=head2 Devel::DProf 34843003dfeSmillert 34943003dfeSmillertThis venerable module has been the de-facto standard for Perl code profiling 35043003dfeSmillertfor more than a decade, but has been replaced by a number of other modules 35143003dfeSmillertwhich have brought us back to the 21st century. Although you're recommended to 35243003dfeSmillertevaluate your tool from the several mentioned here and from the CPAN list at 35343003dfeSmillertthe base of this document, (and currently L<Devel::NYTProf> seems to be the 35443003dfeSmillertweapon of choice - see below), we'll take a quick look at the output from 35543003dfeSmillertL<Devel::DProf> first, to set a baseline for Perl profiling tools. Run the 35643003dfeSmillertabove program under the control of C<Devel::DProf> by using the C<-d> switch on 35743003dfeSmillertthe command-line. 35843003dfeSmillert 35943003dfeSmillert $> perl -d:DProf wordmatch -f perl5db.pl 36043003dfeSmillert 36143003dfeSmillert <...multiple lines snipped...> 36243003dfeSmillert 36343003dfeSmillert wordmatch report for perl5db.pl: 36443003dfeSmillert lines in file: 9428 36543003dfeSmillert words in file: 50243 36643003dfeSmillert words with special (non-word) characters: 20480 36743003dfeSmillert words with only special (non-word) characters: 7790 36843003dfeSmillert words with only consonants: 4801 36943003dfeSmillert words with only capital letters: 1316 37043003dfeSmillert words with only vowels: 1701 37143003dfeSmillert 37243003dfeSmillertC<Devel::DProf> produces a special file, called F<tmon.out> by default, and 37343003dfeSmillertthis file is read by the C<dprofpp> program, which is already installed as part 37443003dfeSmillertof the C<Devel::DProf> distribution. If you call C<dprofpp> with no options, 37543003dfeSmillertit will read the F<tmon.out> file in the current directory and produce a human 37643003dfeSmillertreadable statistics report of the run of your program. Note that this may take 37743003dfeSmillerta little time. 37843003dfeSmillert 37943003dfeSmillert $> dprofpp 38043003dfeSmillert 38143003dfeSmillert Total Elapsed Time = 2.951677 Seconds 38243003dfeSmillert User+System Time = 2.871677 Seconds 38343003dfeSmillert Exclusive Times 38443003dfeSmillert %Time ExclSec CumulS #Calls sec/call Csec/c Name 38543003dfeSmillert 102. 2.945 3.003 251215 0.0000 0.0000 main::matches 38643003dfeSmillert 2.40 0.069 0.069 260643 0.0000 0.0000 main::debug 38743003dfeSmillert 1.74 0.050 0.050 1 0.0500 0.0500 main::report 38843003dfeSmillert 1.04 0.030 0.049 4 0.0075 0.0123 main::BEGIN 38943003dfeSmillert 0.35 0.010 0.010 3 0.0033 0.0033 Exporter::as_heavy 39043003dfeSmillert 0.35 0.010 0.010 7 0.0014 0.0014 IO::File::BEGIN 39143003dfeSmillert 0.00 - -0.000 1 - - Getopt::Long::FindOption 39243003dfeSmillert 0.00 - -0.000 1 - - Symbol::BEGIN 39343003dfeSmillert 0.00 - -0.000 1 - - Fcntl::BEGIN 39443003dfeSmillert 0.00 - -0.000 1 - - Fcntl::bootstrap 39543003dfeSmillert 0.00 - -0.000 1 - - warnings::BEGIN 39643003dfeSmillert 0.00 - -0.000 1 - - IO::bootstrap 39743003dfeSmillert 0.00 - -0.000 1 - - Getopt::Long::ConfigDefaults 39843003dfeSmillert 0.00 - -0.000 1 - - Getopt::Long::Configure 39943003dfeSmillert 0.00 - -0.000 1 - - Symbol::gensym 40043003dfeSmillert 40143003dfeSmillertC<dprofpp> will produce some quite detailed reporting on the activity of the 40243003dfeSmillertC<wordmatch> program. The wallclock, user and system, times are at the top of 40343003dfeSmillertthe analysis, and after this are the main columns defining which define the 40443003dfeSmillertreport. Check the C<dprofpp> docs for details of the many options it supports. 40543003dfeSmillert 4069f11ffb7Safresh1See also C<L<Apache::DProf>> which hooks C<Devel::DProf> into C<mod_perl>. 40743003dfeSmillert 40843003dfeSmillert=head2 Devel::Profiler 40943003dfeSmillert 41043003dfeSmillertLet's take a look at the same program using a different profiler: 41143003dfeSmillertC<Devel::Profiler>, a drop-in Perl-only replacement for C<Devel::DProf>. The 41243003dfeSmillertusage is very slightly different in that instead of using the special C<-d:> 41343003dfeSmillertflag, you pull C<Devel::Profiler> in directly as a module using C<-M>. 41443003dfeSmillert 41543003dfeSmillert $> perl -MDevel::Profiler wordmatch -f perl5db.pl 41643003dfeSmillert 41743003dfeSmillert <...multiple lines snipped...> 41843003dfeSmillert 41943003dfeSmillert wordmatch report for perl5db.pl: 42043003dfeSmillert lines in file: 9428 42143003dfeSmillert words in file: 50243 42243003dfeSmillert words with special (non-word) characters: 20480 42343003dfeSmillert words with only special (non-word) characters: 7790 42443003dfeSmillert words with only consonants: 4801 42543003dfeSmillert words with only capital letters: 1316 42643003dfeSmillert words with only vowels: 1701 42743003dfeSmillert 42843003dfeSmillert 42943003dfeSmillertC<Devel::Profiler> generates a tmon.out file which is compatible with the 43043003dfeSmillertC<dprofpp> program, thus saving the construction of a dedicated statistics 43143003dfeSmillertreader program. C<dprofpp> usage is therefore identical to the above example. 43243003dfeSmillert 43343003dfeSmillert $> dprofpp 43443003dfeSmillert 43543003dfeSmillert Total Elapsed Time = 20.984 Seconds 43643003dfeSmillert User+System Time = 19.981 Seconds 43743003dfeSmillert Exclusive Times 43843003dfeSmillert %Time ExclSec CumulS #Calls sec/call Csec/c Name 43943003dfeSmillert 49.0 9.792 14.509 251215 0.0000 0.0001 main::matches 44043003dfeSmillert 24.4 4.887 4.887 260643 0.0000 0.0000 main::debug 44143003dfeSmillert 0.25 0.049 0.049 1 0.0490 0.0490 main::report 44243003dfeSmillert 0.00 0.000 0.000 1 0.0000 0.0000 Getopt::Long::GetOptions 44343003dfeSmillert 0.00 0.000 0.000 2 0.0000 0.0000 Getopt::Long::ParseOptionSpec 44443003dfeSmillert 0.00 0.000 0.000 1 0.0000 0.0000 Getopt::Long::FindOption 44543003dfeSmillert 0.00 0.000 0.000 1 0.0000 0.0000 IO::File::new 44643003dfeSmillert 0.00 0.000 0.000 1 0.0000 0.0000 IO::Handle::new 44743003dfeSmillert 0.00 0.000 0.000 1 0.0000 0.0000 Symbol::gensym 44843003dfeSmillert 0.00 0.000 0.000 1 0.0000 0.0000 IO::File::open 44943003dfeSmillert 45043003dfeSmillertInterestingly we get slightly different results, which is mostly because the 45143003dfeSmillertalgorithm which generates the report is different, even though the output file 45243003dfeSmillertformat was allegedly identical. The elapsed, user and system times are clearly 453b39c5158Smillertshowing the time it took for C<Devel::Profiler> to execute its own run, but 45443003dfeSmillertthe column listings feel more accurate somehow than the ones we had earlier 45543003dfeSmillertfrom C<Devel::DProf>. The 102% figure has disappeared, for example. This is 45643003dfeSmillertwhere we have to use the tools at our disposal, and recognise their pros and 45743003dfeSmillertcons, before using them. Interestingly, the numbers of calls for each 45843003dfeSmillertsubroutine are identical in the two reports, it's the percentages which differ. 459*e0680481Safresh1As the author of C<Devel::Profiler> writes: 46043003dfeSmillert 461b8851fccSafresh1 ...running HTML::Template's test suite under Devel::DProf shows 462b8851fccSafresh1 output() taking NO time but Devel::Profiler shows around 10% of the 463b8851fccSafresh1 time is in output(). I don't know which to trust but my gut tells me 464b8851fccSafresh1 something is wrong with Devel::DProf. HTML::Template::output() is a 465b8851fccSafresh1 big routine that's called for every test. Either way, something needs 466b8851fccSafresh1 fixing. 46743003dfeSmillert 46843003dfeSmillertYMMV. 46943003dfeSmillert 4709f11ffb7Safresh1See also C<L<Devel::Apache::Profiler>> which hooks C<Devel::Profiler> 4719f11ffb7Safresh1into C<mod_perl>. 47243003dfeSmillert 47343003dfeSmillert=head2 Devel::SmallProf 47443003dfeSmillert 47543003dfeSmillertThe C<Devel::SmallProf> profiler examines the runtime of your Perl program and 47643003dfeSmillertproduces a line-by-line listing to show how many times each line was called, 47743003dfeSmillertand how long each line took to execute. It is called by supplying the familiar 47843003dfeSmillertC<-d> flag to Perl at runtime. 47943003dfeSmillert 48043003dfeSmillert $> perl -d:SmallProf wordmatch -f perl5db.pl 48143003dfeSmillert 48243003dfeSmillert <...multiple lines snipped...> 48343003dfeSmillert 48443003dfeSmillert wordmatch report for perl5db.pl: 48543003dfeSmillert lines in file: 9428 48643003dfeSmillert words in file: 50243 48743003dfeSmillert words with special (non-word) characters: 20480 48843003dfeSmillert words with only special (non-word) characters: 7790 48943003dfeSmillert words with only consonants: 4801 49043003dfeSmillert words with only capital letters: 1316 49143003dfeSmillert words with only vowels: 1701 49243003dfeSmillert 493*e0680481Safresh1C<Devel::SmallProf> writes its output into a file called F<smallprof.out>, by 49443003dfeSmillertdefault. The format of the file looks like this: 49543003dfeSmillert 49643003dfeSmillert <num> <time> <ctime> <line>:<text> 49743003dfeSmillert 49843003dfeSmillertWhen the program has terminated, the output may be examined and sorted using 49943003dfeSmillertany standard text filtering utilities. Something like the following may be 50043003dfeSmillertsufficient: 50143003dfeSmillert 50243003dfeSmillert $> cat smallprof.out | grep \d*: | sort -k3 | tac | head -n20 50343003dfeSmillert 50443003dfeSmillert 251215 1.65674 7.68000 75: if ( $word =~ /($regex)/ ) { 50543003dfeSmillert 251215 0.03264 4.40000 79: debug("word: $i_wd ".($has ? 'matches' : 50643003dfeSmillert 251215 0.02693 4.10000 81: return $has; 50743003dfeSmillert 260643 0.02841 4.07000 128: if ( $debug ) { 50843003dfeSmillert 260643 0.02601 4.04000 126: my $message = shift; 50943003dfeSmillert 251215 0.02641 3.91000 73: my $has = 0; 51043003dfeSmillert 251215 0.03311 3.71000 70: my $i_wd = shift; 51143003dfeSmillert 251215 0.02699 3.69000 72: my $regex = shift; 51243003dfeSmillert 251215 0.02766 3.68000 71: my $word = shift; 51343003dfeSmillert 50243 0.59726 1.00000 59: $count{$i_LINES}{cons} = 51443003dfeSmillert 50243 0.48175 0.92000 61: $count{$i_LINES}{spec} = 51543003dfeSmillert 50243 0.00644 0.89000 56: my $i_cons = matches($i_word, $word, 51643003dfeSmillert 50243 0.48837 0.88000 63: $count{$i_LINES}{caps} = 51743003dfeSmillert 50243 0.00516 0.88000 58: my $i_caps = matches($i_word, $word, '^[(A- 51843003dfeSmillert 50243 0.00631 0.81000 54: my $i_spec = matches($i_word, $word, '[^a- 51943003dfeSmillert 50243 0.00496 0.80000 57: my $i_vows = matches($i_word, $word, 52043003dfeSmillert 50243 0.00688 0.80000 53: $i_word++; 52143003dfeSmillert 50243 0.48469 0.79000 62: $count{$i_LINES}{only} = 52243003dfeSmillert 50243 0.48928 0.77000 60: $count{$i_LINES}{vows} = 52343003dfeSmillert 50243 0.00683 0.75000 55: my $i_only = matches($i_word, $word, '^[^a- 52443003dfeSmillert 52543003dfeSmillertYou can immediately see a slightly different focus to the subroutine profiling 52643003dfeSmillertmodules, and we start to see exactly which line of code is taking the most 52743003dfeSmillerttime. That regex line is looking a bit suspicious, for example. Remember that 52843003dfeSmillertthese tools are supposed to be used together, there is no single best way to 52943003dfeSmillertprofile your code, you need to use the best tools for the job. 53043003dfeSmillert 5319f11ffb7Safresh1See also C<L<Apache::SmallProf>> which hooks C<Devel::SmallProf> into 5329f11ffb7Safresh1C<mod_perl>. 53343003dfeSmillert 53443003dfeSmillert=head2 Devel::FastProf 53543003dfeSmillert 53643003dfeSmillertC<Devel::FastProf> is another Perl line profiler. This was written with a view 53743003dfeSmillertto getting a faster line profiler, than is possible with for example 53843003dfeSmillertC<Devel::SmallProf>, because it's written in C<C>. To use C<Devel::FastProf>, 53943003dfeSmillertsupply the C<-d> argument to Perl: 54043003dfeSmillert 54143003dfeSmillert $> perl -d:FastProf wordmatch -f perl5db.pl 54243003dfeSmillert 54343003dfeSmillert <...multiple lines snipped...> 54443003dfeSmillert 54543003dfeSmillert wordmatch report for perl5db.pl: 54643003dfeSmillert lines in file: 9428 54743003dfeSmillert words in file: 50243 54843003dfeSmillert words with special (non-word) characters: 20480 54943003dfeSmillert words with only special (non-word) characters: 7790 55043003dfeSmillert words with only consonants: 4801 55143003dfeSmillert words with only capital letters: 1316 55243003dfeSmillert words with only vowels: 1701 55343003dfeSmillert 55443003dfeSmillertC<Devel::FastProf> writes statistics to the file F<fastprof.out> in the current 55543003dfeSmillertdirectory. The output file, which can be specified, can be interpreted by using 55643003dfeSmillertthe C<fprofpp> command-line program. 55743003dfeSmillert 55843003dfeSmillert $> fprofpp | head -n20 55943003dfeSmillert 56043003dfeSmillert # fprofpp output format is: 56143003dfeSmillert # filename:line time count: source 56243003dfeSmillert wordmatch:75 3.93338 251215: if ( $word =~ /($regex)/ ) { 56343003dfeSmillert wordmatch:79 1.77774 251215: debug("word: $i_wd ".($has ? 'matches' : 'does not match')." chars: /$regex/"); 56443003dfeSmillert wordmatch:81 1.47604 251215: return $has; 56543003dfeSmillert wordmatch:126 1.43441 260643: my $message = shift; 56643003dfeSmillert wordmatch:128 1.42156 260643: if ( $debug ) { 56743003dfeSmillert wordmatch:70 1.36824 251215: my $i_wd = shift; 56843003dfeSmillert wordmatch:71 1.36739 251215: my $word = shift; 56943003dfeSmillert wordmatch:72 1.35939 251215: my $regex = shift; 57043003dfeSmillert 57143003dfeSmillertStraightaway we can see that the number of times each line has been called is 57243003dfeSmillertidentical to the C<Devel::SmallProf> output, and the sequence is only very 57343003dfeSmillertslightly different based on the ordering of the amount of time each line took 57443003dfeSmillertto execute, C<if ( $debug ) { > and C<my $message = shift;>, for example. The 57543003dfeSmillertdifferences in the actual times recorded might be in the algorithm used 57643003dfeSmillertinternally, or it could be due to system resource limitations or contention. 57743003dfeSmillert 578898184e3SsthenSee also the L<DBIx::Profile> which will profile database queries running 57943003dfeSmillertunder the C<DBIx::*> namespace. 58043003dfeSmillert 58143003dfeSmillert=head2 Devel::NYTProf 58243003dfeSmillert 58343003dfeSmillertC<Devel::NYTProf> is the B<next generation> of Perl code profiler, fixing many 58443003dfeSmillertshortcomings in other tools and implementing many cool features. First of all it 58543003dfeSmillertcan be used as either a I<line> profiler, a I<block> or a I<subroutine> 58643003dfeSmillertprofiler, all at once. It can also use sub-microsecond (100ns) resolution on 58743003dfeSmillertsystems which provide C<clock_gettime()>. It can be started and stopped even 58843003dfeSmillertby the program being profiled. It's a one-line entry to profile C<mod_perl> 58943003dfeSmillertapplications. It's written in C<c> and is probably the fastest profiler 59043003dfeSmillertavailable for Perl. The list of coolness just goes on. Enough of that, let's 59143003dfeSmillertsee how to it works - just use the familiar C<-d> switch to plug it in and run 59243003dfeSmillertthe code. 59343003dfeSmillert 59443003dfeSmillert $> perl -d:NYTProf wordmatch -f perl5db.pl 59543003dfeSmillert 59643003dfeSmillert wordmatch report for perl5db.pl: 59743003dfeSmillert lines in file: 9427 59843003dfeSmillert words in file: 50243 59943003dfeSmillert words with special (non-word) characters: 20480 60043003dfeSmillert words with only special (non-word) characters: 7790 60143003dfeSmillert words with only consonants: 4801 60243003dfeSmillert words with only capital letters: 1316 60343003dfeSmillert words with only vowels: 1701 60443003dfeSmillert 60543003dfeSmillertC<NYTProf> will generate a report database into the file F<nytprof.out> by 60643003dfeSmillertdefault. Human readable reports can be generated from here by using the 60743003dfeSmillertsupplied C<nytprofhtml> (HTML output) and C<nytprofcsv> (CSV output) programs. 608898184e3SsthenWe've used the Unix system C<html2text> utility to convert the 60943003dfeSmillertF<nytprof/index.html> file for convenience here. 61043003dfeSmillert 61143003dfeSmillert $> html2text nytprof/index.html 61243003dfeSmillert 61343003dfeSmillert Performance Profile Index 61443003dfeSmillert For wordmatch 61543003dfeSmillert Run on Fri Sep 26 13:46:39 2008 61643003dfeSmillert Reported on Fri Sep 26 13:47:23 2008 61743003dfeSmillert 61843003dfeSmillert Top 15 Subroutines -- ordered by exclusive time 61943003dfeSmillert |Calls |P |F |Inclusive|Exclusive|Subroutine | 62043003dfeSmillert | | | |Time |Time | | 62143003dfeSmillert |251215|5 |1 |13.09263 |10.47692 |main:: |matches | 62243003dfeSmillert |260642|2 |1 |2.71199 |2.71199 |main:: |debug | 62343003dfeSmillert |1 |1 |1 |0.21404 |0.21404 |main:: |report | 62443003dfeSmillert |2 |2 |2 |0.00511 |0.00511 |XSLoader:: |load (xsub) | 62543003dfeSmillert |14 |14|7 |0.00304 |0.00298 |Exporter:: |import | 62643003dfeSmillert |3 |1 |1 |0.00265 |0.00254 |Exporter:: |as_heavy | 62743003dfeSmillert |10 |10|4 |0.00140 |0.00140 |vars:: |import | 62843003dfeSmillert |13 |13|1 |0.00129 |0.00109 |constant:: |import | 62943003dfeSmillert |1 |1 |1 |0.00360 |0.00096 |FileHandle:: |import | 63043003dfeSmillert |3 |3 |3 |0.00086 |0.00074 |warnings::register::|import | 63143003dfeSmillert |9 |3 |1 |0.00036 |0.00036 |strict:: |bits | 63243003dfeSmillert |13 |13|13|0.00032 |0.00029 |strict:: |import | 63343003dfeSmillert |2 |2 |2 |0.00020 |0.00020 |warnings:: |import | 63443003dfeSmillert |2 |1 |1 |0.00020 |0.00020 |Getopt::Long:: |ParseOptionSpec| 63543003dfeSmillert |7 |7 |6 |0.00043 |0.00020 |strict:: |unimport | 63643003dfeSmillert 63743003dfeSmillert For more information see the full list of 189 subroutines. 63843003dfeSmillert 63943003dfeSmillertThe first part of the report already shows the critical information regarding 64043003dfeSmillertwhich subroutines are using the most time. The next gives some statistics 64143003dfeSmillertabout the source files profiled. 64243003dfeSmillert 64343003dfeSmillert Source Code Files -- ordered by exclusive time then name 64443003dfeSmillert |Stmts |Exclusive|Avg. |Reports |Source File | 64543003dfeSmillert | |Time | | | | 64643003dfeSmillert |2699761|15.66654 |6e-06 |line . block . sub|wordmatch | 64743003dfeSmillert |35 |0.02187 |0.00062|line . block . sub|IO/Handle.pm | 64843003dfeSmillert |274 |0.01525 |0.00006|line . block . sub|Getopt/Long.pm | 64943003dfeSmillert |20 |0.00585 |0.00029|line . block . sub|Fcntl.pm | 65043003dfeSmillert |128 |0.00340 |0.00003|line . block . sub|Exporter/Heavy.pm | 65143003dfeSmillert |42 |0.00332 |0.00008|line . block . sub|IO/File.pm | 65243003dfeSmillert |261 |0.00308 |0.00001|line . block . sub|Exporter.pm | 65343003dfeSmillert |323 |0.00248 |8e-06 |line . block . sub|constant.pm | 65443003dfeSmillert |12 |0.00246 |0.00021|line . block . sub|File/Spec/Unix.pm | 65543003dfeSmillert |191 |0.00240 |0.00001|line . block . sub|vars.pm | 65643003dfeSmillert |77 |0.00201 |0.00003|line . block . sub|FileHandle.pm | 65743003dfeSmillert |12 |0.00198 |0.00016|line . block . sub|Carp.pm | 65843003dfeSmillert |14 |0.00175 |0.00013|line . block . sub|Symbol.pm | 65943003dfeSmillert |15 |0.00130 |0.00009|line . block . sub|IO.pm | 66043003dfeSmillert |22 |0.00120 |0.00005|line . block . sub|IO/Seekable.pm | 66143003dfeSmillert |198 |0.00085 |4e-06 |line . block . sub|warnings/register.pm| 66243003dfeSmillert |114 |0.00080 |7e-06 |line . block . sub|strict.pm | 66343003dfeSmillert |47 |0.00068 |0.00001|line . block . sub|warnings.pm | 66443003dfeSmillert |27 |0.00054 |0.00002|line . block . sub|overload.pm | 66543003dfeSmillert |9 |0.00047 |0.00005|line . block . sub|SelectSaver.pm | 66643003dfeSmillert |13 |0.00045 |0.00003|line . block . sub|File/Spec.pm | 66743003dfeSmillert |2701595|15.73869 | |Total | 66843003dfeSmillert |128647 |0.74946 | |Average | 66943003dfeSmillert | |0.00201 |0.00003|Median | 67043003dfeSmillert | |0.00121 |0.00003|Deviation | 67143003dfeSmillert 67243003dfeSmillert Report produced by the NYTProf 2.03 Perl profiler, developed by Tim Bunce and 67343003dfeSmillert Adam Kaplan. 67443003dfeSmillert 67543003dfeSmillertAt this point, if you're using the I<html> report, you can click through the 67643003dfeSmillertvarious links to bore down into each subroutine and each line of code. Because 67743003dfeSmillertwe're using the text reporting here, and there's a whole directory full of 67843003dfeSmillertreports built for each source file, we'll just display a part of the 67943003dfeSmillertcorresponding F<wordmatch-line.html> file, sufficient to give an idea of the 68043003dfeSmillertsort of output you can expect from this cool tool. 68143003dfeSmillert 68243003dfeSmillert $> html2text nytprof/wordmatch-line.html 68343003dfeSmillert 68443003dfeSmillert Performance Profile -- -block view-.-line view-.-sub view- 68543003dfeSmillert For wordmatch 68643003dfeSmillert Run on Fri Sep 26 13:46:39 2008 68743003dfeSmillert Reported on Fri Sep 26 13:47:22 2008 68843003dfeSmillert 68943003dfeSmillert File wordmatch 69043003dfeSmillert 69143003dfeSmillert Subroutines -- ordered by exclusive time 69243003dfeSmillert |Calls |P|F|Inclusive|Exclusive|Subroutine | 69343003dfeSmillert | | | |Time |Time | | 69443003dfeSmillert |251215|5|1|13.09263 |10.47692 |main::|matches| 69543003dfeSmillert |260642|2|1|2.71199 |2.71199 |main::|debug | 69643003dfeSmillert |1 |1|1|0.21404 |0.21404 |main::|report | 69743003dfeSmillert |0 |0|0|0 |0 |main::|BEGIN | 69843003dfeSmillert 69943003dfeSmillert 70043003dfeSmillert |Line|Stmts.|Exclusive|Avg. |Code | 70143003dfeSmillert | | |Time | | | 70243003dfeSmillert |1 | | | |#!/usr/bin/perl | 70343003dfeSmillert |2 | | | | | 70443003dfeSmillert | | | | |use strict; | 70543003dfeSmillert |3 |3 |0.00086 |0.00029|# spent 0.00003s making 1 calls to strict:: | 70643003dfeSmillert | | | | |import | 70743003dfeSmillert | | | | |use warnings; | 70843003dfeSmillert |4 |3 |0.01563 |0.00521|# spent 0.00012s making 1 calls to warnings:: | 70943003dfeSmillert | | | | |import | 71043003dfeSmillert |5 | | | | | 71143003dfeSmillert |6 | | | |=head1 NAME | 71243003dfeSmillert |7 | | | | | 71343003dfeSmillert |8 | | | |filewords - word analysis of input file | 71443003dfeSmillert <...snip...> 71543003dfeSmillert |62 |1 |0.00445 |0.00445|print report( %count ); | 71643003dfeSmillert | | | | |# spent 0.21404s making 1 calls to main::report| 71743003dfeSmillert |63 | | | | | 71843003dfeSmillert | | | | |# spent 23.56955s (10.47692+2.61571) within | 71943003dfeSmillert | | | | |main::matches which was called 251215 times, | 72043003dfeSmillert | | | | |avg 0.00005s/call: # 50243 times | 72143003dfeSmillert | | | | |(2.12134+0.51939s) at line 57 of wordmatch, avg| 72243003dfeSmillert | | | | |0.00005s/call # 50243 times (2.17735+0.54550s) | 72343003dfeSmillert |64 | | | |at line 56 of wordmatch, avg 0.00005s/call # | 72443003dfeSmillert | | | | |50243 times (2.10992+0.51797s) at line 58 of | 72543003dfeSmillert | | | | |wordmatch, avg 0.00005s/call # 50243 times | 72643003dfeSmillert | | | | |(2.12696+0.51598s) at line 55 of wordmatch, avg| 72743003dfeSmillert | | | | |0.00005s/call # 50243 times (1.94134+0.51687s) | 72843003dfeSmillert | | | | |at line 54 of wordmatch, avg 0.00005s/call | 72943003dfeSmillert | | | | |sub matches { | 73043003dfeSmillert <...snip...> 73143003dfeSmillert |102 | | | | | 73243003dfeSmillert | | | | |# spent 2.71199s within main::debug which was | 73343003dfeSmillert | | | | |called 260642 times, avg 0.00001s/call: # | 73443003dfeSmillert | | | | |251215 times (2.61571+0s) by main::matches at | 73543003dfeSmillert |103 | | | |line 74 of wordmatch, avg 0.00001s/call # 9427 | 73643003dfeSmillert | | | | |times (0.09628+0s) at line 50 of wordmatch, avg| 73743003dfeSmillert | | | | |0.00001s/call | 73843003dfeSmillert | | | | |sub debug { | 73943003dfeSmillert |104 |260642|0.58496 |2e-06 |my $message = shift; | 74043003dfeSmillert |105 | | | | | 74143003dfeSmillert |106 |260642|1.09917 |4e-06 |if ( $debug ) { | 74243003dfeSmillert |107 | | | |print STDERR "DBG: $message\n"; | 74343003dfeSmillert |108 | | | |} | 74443003dfeSmillert |109 | | | |} | 74543003dfeSmillert |110 | | | | | 74643003dfeSmillert |111 |1 |0.01501 |0.01501|exit 0; | 74743003dfeSmillert |112 | | | | | 74843003dfeSmillert 74943003dfeSmillertOodles of very useful information in there - this seems to be the way forward. 75043003dfeSmillert 7519f11ffb7Safresh1See also C<L<Devel::NYTProf::Apache>> which hooks C<Devel::NYTProf> into 7529f11ffb7Safresh1C<mod_perl>. 75343003dfeSmillert 75443003dfeSmillert=head1 SORTING 75543003dfeSmillert 75643003dfeSmillertPerl modules are not the only tools a performance analyst has at their 75743003dfeSmillertdisposal, system tools like C<time> should not be overlooked as the next 75843003dfeSmillertexample shows, where we take a quick look at sorting. Many books, theses and 75943003dfeSmillertarticles, have been written about efficient sorting algorithms, and this is not 76043003dfeSmillertthe place to repeat such work, there's several good sorting modules which 76143003dfeSmillertdeserve taking a look at too: C<Sort::Maker>, C<Sort::Key> spring to mind. 76243003dfeSmillertHowever, it's still possible to make some observations on certain Perl specific 76343003dfeSmillertinterpretations on issues relating to sorting data sets and give an example or 76443003dfeSmillerttwo with regard to how sorting large data volumes can effect performance. 76543003dfeSmillertFirstly, an often overlooked point when sorting large amounts of data, one can 76643003dfeSmillertattempt to reduce the data set to be dealt with and in many cases C<grep()> can 76743003dfeSmillertbe quite useful as a simple filter: 76843003dfeSmillert 76943003dfeSmillert @data = sort grep { /$filter/ } @incoming 77043003dfeSmillert 77143003dfeSmillertA command such as this can vastly reduce the volume of material to actually 77243003dfeSmillertsort through in the first place, and should not be too lightly disregarded 773b39c5158Smillertpurely on the basis of its simplicity. The C<KISS> principle is too often 77443003dfeSmillertoverlooked - the next example uses the simple system C<time> utility to 77543003dfeSmillertdemonstrate. Let's take a look at an actual example of sorting the contents of 77643003dfeSmillerta large file, an apache logfile would do. This one has over a quarter of a 77743003dfeSmillertmillion lines, is 50M in size, and a snippet of it looks like this: 77843003dfeSmillert 77943003dfeSmillert# logfile 78043003dfeSmillert 78143003dfeSmillert 188.209-65-87.adsl-dyn.isp.belgacom.be - - [08/Feb/2007:12:57:16 +0000] "GET /favicon.ico HTTP/1.1" 404 209 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)" 78243003dfeSmillert 188.209-65-87.adsl-dyn.isp.belgacom.be - - [08/Feb/2007:12:57:16 +0000] "GET /favicon.ico HTTP/1.1" 404 209 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)" 78343003dfeSmillert 151.56.71.198 - - [08/Feb/2007:12:57:41 +0000] "GET /suse-on-vaio.html HTTP/1.1" 200 2858 "http://www.linux-on-laptops.com/sony.html" "Mozilla/5.0 (Windows; U; Windows NT 5.2; en-US; rv:1.8.1.1) Gecko/20061204 Firefox/2.0.0.1" 78443003dfeSmillert 151.56.71.198 - - [08/Feb/2007:12:57:42 +0000] "GET /data/css HTTP/1.1" 404 206 "http://www.rfi.net/suse-on-vaio.html" "Mozilla/5.0 (Windows; U; Windows NT 5.2; en-US; rv:1.8.1.1) Gecko/20061204 Firefox/2.0.0.1" 78543003dfeSmillert 151.56.71.198 - - [08/Feb/2007:12:57:43 +0000] "GET /favicon.ico HTTP/1.1" 404 209 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.2; en-US; rv:1.8.1.1) Gecko/20061204 Firefox/2.0.0.1" 78643003dfeSmillert 217.113.68.60 - - [08/Feb/2007:13:02:15 +0000] "GET / HTTP/1.1" 304 - "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)" 78743003dfeSmillert 217.113.68.60 - - [08/Feb/2007:13:02:16 +0000] "GET /data/css HTTP/1.1" 404 206 "http://www.rfi.net/" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)" 78843003dfeSmillert debora.to.isac.cnr.it - - [08/Feb/2007:13:03:58 +0000] "GET /suse-on-vaio.html HTTP/1.1" 200 2858 "http://www.linux-on-laptops.com/sony.html" "Mozilla/5.0 (compatible; Konqueror/3.4; Linux) KHTML/3.4.0 (like Gecko)" 78943003dfeSmillert debora.to.isac.cnr.it - - [08/Feb/2007:13:03:58 +0000] "GET /data/css HTTP/1.1" 404 206 "http://www.rfi.net/suse-on-vaio.html" "Mozilla/5.0 (compatible; Konqueror/3.4; Linux) KHTML/3.4.0 (like Gecko)" 79043003dfeSmillert debora.to.isac.cnr.it - - [08/Feb/2007:13:03:58 +0000] "GET /favicon.ico HTTP/1.1" 404 209 "-" "Mozilla/5.0 (compatible; Konqueror/3.4; Linux) KHTML/3.4.0 (like Gecko)" 79143003dfeSmillert 195.24.196.99 - - [08/Feb/2007:13:26:48 +0000] "GET / HTTP/1.0" 200 3309 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; fr; rv:1.8.0.9) Gecko/20061206 Firefox/1.5.0.9" 79243003dfeSmillert 195.24.196.99 - - [08/Feb/2007:13:26:58 +0000] "GET /data/css HTTP/1.0" 404 206 "http://www.rfi.net/" "Mozilla/5.0 (Windows; U; Windows NT 5.1; fr; rv:1.8.0.9) Gecko/20061206 Firefox/1.5.0.9" 79343003dfeSmillert 195.24.196.99 - - [08/Feb/2007:13:26:59 +0000] "GET /favicon.ico HTTP/1.0" 404 209 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; fr; rv:1.8.0.9) Gecko/20061206 Firefox/1.5.0.9" 79443003dfeSmillert crawl1.cosmixcorp.com - - [08/Feb/2007:13:27:57 +0000] "GET /robots.txt HTTP/1.0" 200 179 "-" "voyager/1.0" 79543003dfeSmillert crawl1.cosmixcorp.com - - [08/Feb/2007:13:28:25 +0000] "GET /links.html HTTP/1.0" 200 3413 "-" "voyager/1.0" 79643003dfeSmillert fhm226.internetdsl.tpnet.pl - - [08/Feb/2007:13:37:32 +0000] "GET /suse-on-vaio.html HTTP/1.1" 200 2858 "http://www.linux-on-laptops.com/sony.html" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)" 79743003dfeSmillert fhm226.internetdsl.tpnet.pl - - [08/Feb/2007:13:37:34 +0000] "GET /data/css HTTP/1.1" 404 206 "http://www.rfi.net/suse-on-vaio.html" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)" 79843003dfeSmillert 80.247.140.134 - - [08/Feb/2007:13:57:35 +0000] "GET / HTTP/1.1" 200 3309 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; .NET CLR 1.1.4322)" 79943003dfeSmillert 80.247.140.134 - - [08/Feb/2007:13:57:37 +0000] "GET /data/css HTTP/1.1" 404 206 "http://www.rfi.net" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; .NET CLR 1.1.4322)" 80043003dfeSmillert pop.compuscan.co.za - - [08/Feb/2007:14:10:43 +0000] "GET / HTTP/1.1" 200 3309 "-" "www.clamav.net" 80143003dfeSmillert livebot-207-46-98-57.search.live.com - - [08/Feb/2007:14:12:04 +0000] "GET /robots.txt HTTP/1.0" 200 179 "-" "msnbot/1.0 (+http://search.msn.com/msnbot.htm)" 80243003dfeSmillert livebot-207-46-98-57.search.live.com - - [08/Feb/2007:14:12:04 +0000] "GET /html/oracle.html HTTP/1.0" 404 214 "-" "msnbot/1.0 (+http://search.msn.com/msnbot.htm)" 80343003dfeSmillert dslb-088-064-005-154.pools.arcor-ip.net - - [08/Feb/2007:14:12:15 +0000] "GET / HTTP/1.1" 200 3309 "-" "www.clamav.net" 80443003dfeSmillert 196.201.92.41 - - [08/Feb/2007:14:15:01 +0000] "GET / HTTP/1.1" 200 3309 "-" "MOT-L7/08.B7.DCR MIB/2.2.1 Profile/MIDP-2.0 Configuration/CLDC-1.1" 80543003dfeSmillert 80643003dfeSmillertThe specific task here is to sort the 286,525 lines of this file by Response 80743003dfeSmillertCode, Query, Browser, Referring Url, and lastly Date. One solution might be to 80843003dfeSmillertuse the following code, which iterates over the files given on the 80943003dfeSmillertcommand-line. 81043003dfeSmillert 81143003dfeSmillert# sort-apache-log 81243003dfeSmillert 81343003dfeSmillert #!/usr/bin/perl -n 81443003dfeSmillert 815eac174f2Safresh1 use v5.36; 81643003dfeSmillert 81743003dfeSmillert my @data; 81843003dfeSmillert 81943003dfeSmillert LINE: 82043003dfeSmillert while ( <> ) { 82143003dfeSmillert my $line = $_; 82243003dfeSmillert if ( 82343003dfeSmillert $line =~ m/^( 82443003dfeSmillert ([\w\.\-]+) # client 82543003dfeSmillert \s*-\s*-\s*\[ 82643003dfeSmillert ([^]]+) # date 82743003dfeSmillert \]\s*"\w+\s* 82843003dfeSmillert (\S+) # query 82943003dfeSmillert [^"]+"\s* 83043003dfeSmillert (\d+) # status 83143003dfeSmillert \s+\S+\s+"[^"]*"\s+" 83243003dfeSmillert ([^"]*) # browser 83343003dfeSmillert " 83443003dfeSmillert .* 83543003dfeSmillert )$/x 83643003dfeSmillert ) { 83743003dfeSmillert my @chunks = split(/ +/, $line); 83843003dfeSmillert my $ip = $1; 83943003dfeSmillert my $date = $2; 84043003dfeSmillert my $query = $3; 84143003dfeSmillert my $status = $4; 84243003dfeSmillert my $browser = $5; 84343003dfeSmillert 84443003dfeSmillert push(@data, [$ip, $date, $query, $status, $browser, $line]); 84543003dfeSmillert } 84643003dfeSmillert } 84743003dfeSmillert 84843003dfeSmillert my @sorted = sort { 84943003dfeSmillert $a->[3] cmp $b->[3] 85043003dfeSmillert || 85143003dfeSmillert $a->[2] cmp $b->[2] 85243003dfeSmillert || 85343003dfeSmillert $a->[0] cmp $b->[0] 85443003dfeSmillert || 85543003dfeSmillert $a->[1] cmp $b->[1] 85643003dfeSmillert || 85743003dfeSmillert $a->[4] cmp $b->[4] 85843003dfeSmillert } @data; 85943003dfeSmillert 86043003dfeSmillert foreach my $data ( @sorted ) { 86143003dfeSmillert print $data->[5]; 86243003dfeSmillert } 86343003dfeSmillert 86443003dfeSmillert exit 0; 86543003dfeSmillert 86643003dfeSmillertWhen running this program, redirect C<STDOUT> so it is possible to check the 86743003dfeSmillertoutput is correct from following test runs and use the system C<time> utility 86843003dfeSmillertto check the overall runtime. 86943003dfeSmillert 87043003dfeSmillert $> time ./sort-apache-log logfile > out-sort 87143003dfeSmillert 87243003dfeSmillert real 0m17.371s 87343003dfeSmillert user 0m15.757s 87443003dfeSmillert sys 0m0.592s 87543003dfeSmillert 87643003dfeSmillertThe program took just over 17 wallclock seconds to run. Note the different 87743003dfeSmillertvalues C<time> outputs, it's important to always use the same one, and to not 87843003dfeSmillertconfuse what each one means. 87943003dfeSmillert 88043003dfeSmillert=over 4 88143003dfeSmillert 88243003dfeSmillert=item Elapsed Real Time 88343003dfeSmillert 88443003dfeSmillertThe overall, or wallclock, time between when C<time> was called, and when it 88543003dfeSmillertterminates. The elapsed time includes both user and system times, and time 88643003dfeSmillertspent waiting for other users and processes on the system. Inevitably, this is 88743003dfeSmillertthe most approximate of the measurements given. 88843003dfeSmillert 88943003dfeSmillert=item User CPU Time 89043003dfeSmillert 89143003dfeSmillertThe user time is the amount of time the entire process spent on behalf of the 89243003dfeSmillertuser on this system executing this program. 89343003dfeSmillert 89443003dfeSmillert=item System CPU Time 89543003dfeSmillert 89643003dfeSmillertThe system time is the amount of time the kernel itself spent executing 89743003dfeSmillertroutines, or system calls, on behalf of this process user. 89843003dfeSmillert 89943003dfeSmillert=back 90043003dfeSmillert 90143003dfeSmillertRunning this same process as a C<Schwarzian Transform> it is possible to 90243003dfeSmillerteliminate the input and output arrays for storing all the data, and work on the 90343003dfeSmillertinput directly as it arrives too. Otherwise, the code looks fairly similar: 90443003dfeSmillert 90543003dfeSmillert# sort-apache-log-schwarzian 90643003dfeSmillert 90743003dfeSmillert #!/usr/bin/perl -n 90843003dfeSmillert 909eac174f2Safresh1 use v5.36; 91043003dfeSmillert 91143003dfeSmillert print 91243003dfeSmillert 91343003dfeSmillert map $_->[0] => 91443003dfeSmillert 91543003dfeSmillert sort { 91643003dfeSmillert $a->[4] cmp $b->[4] 91743003dfeSmillert || 91843003dfeSmillert $a->[3] cmp $b->[3] 91943003dfeSmillert || 92043003dfeSmillert $a->[1] cmp $b->[1] 92143003dfeSmillert || 92243003dfeSmillert $a->[2] cmp $b->[2] 92343003dfeSmillert || 92443003dfeSmillert $a->[5] cmp $b->[5] 92543003dfeSmillert } 92643003dfeSmillert map [ $_, m/^( 92743003dfeSmillert ([\w\.\-]+) # client 92843003dfeSmillert \s*-\s*-\s*\[ 92943003dfeSmillert ([^]]+) # date 93043003dfeSmillert \]\s*"\w+\s* 93143003dfeSmillert (\S+) # query 93243003dfeSmillert [^"]+"\s* 93343003dfeSmillert (\d+) # status 93443003dfeSmillert \s+\S+\s+"[^"]*"\s+" 93543003dfeSmillert ([^"]*) # browser 93643003dfeSmillert " 93743003dfeSmillert .* 93843003dfeSmillert )$/xo ] 93943003dfeSmillert 94043003dfeSmillert => <>; 94143003dfeSmillert 94243003dfeSmillert exit 0; 94343003dfeSmillert 94443003dfeSmillertRun the new code against the same logfile, as above, to check the new time. 94543003dfeSmillert 94643003dfeSmillert $> time ./sort-apache-log-schwarzian logfile > out-schwarz 94743003dfeSmillert 94843003dfeSmillert real 0m9.664s 94943003dfeSmillert user 0m8.873s 95043003dfeSmillert sys 0m0.704s 95143003dfeSmillert 95243003dfeSmillertThe time has been cut in half, which is a respectable speed improvement by any 95343003dfeSmillertstandard. Naturally, it is important to check the output is consistent with 954b39c5158Smillertthe first program run, this is where the Unix system C<cksum> utility comes in. 95543003dfeSmillert 95643003dfeSmillert $> cksum out-sort out-schwarz 95743003dfeSmillert 3044173777 52029194 out-sort 95843003dfeSmillert 3044173777 52029194 out-schwarz 95943003dfeSmillert 96043003dfeSmillertBTW. Beware too of pressure from managers who see you speed a program up by 50% 96143003dfeSmillertof the runtime once, only to get a request one month later to do the same again 962b8851fccSafresh1(true story) - you'll just have to point out you're only human, even if you are a 96343003dfeSmillertPerl programmer, and you'll see what you can do... 96443003dfeSmillert 96543003dfeSmillert=head1 LOGGING 96643003dfeSmillert 96743003dfeSmillertAn essential part of any good development process is appropriate error handling 96843003dfeSmillertwith appropriately informative messages, however there exists a school of 96943003dfeSmillertthought which suggests that log files should be I<chatty>, as if the chain of 97043003dfeSmillertunbroken output somehow ensures the survival of the program. If speed is in 97143003dfeSmillertany way an issue, this approach is wrong. 97243003dfeSmillert 97343003dfeSmillertA common sight is code which looks something like this: 97443003dfeSmillert 975b8851fccSafresh1 logger->debug( "A logging message via process-id: $$ INC: " 976b8851fccSafresh1 . Dumper(\%INC) ) 97743003dfeSmillert 97843003dfeSmillertThe problem is that this code will always be parsed and executed, even when the 97943003dfeSmillertdebug level set in the logging configuration file is zero. Once the debug() 98043003dfeSmillertsubroutine has been entered, and the internal C<$debug> variable confirmed to 98143003dfeSmillertbe zero, for example, the message which has been sent in will be discarded and 982b8851fccSafresh1the program will continue. In the example given though, the C<\%INC> hash will 98343003dfeSmillertalready have been dumped, and the message string constructed, all of which work 98443003dfeSmillertcould be bypassed by a debug variable at the statement level, like this: 98543003dfeSmillert 986b8851fccSafresh1 logger->debug( "A logging message via process-id: $$ INC: " 987b8851fccSafresh1 . Dumper(\%INC) ) if $DEBUG; 98843003dfeSmillert 98943003dfeSmillertThis effect can be demonstrated by setting up a test script with both forms, 99043003dfeSmillertincluding a C<debug()> subroutine to emulate typical C<logger()> functionality. 99143003dfeSmillert 99243003dfeSmillert# ifdebug 99343003dfeSmillert 99443003dfeSmillert #!/usr/bin/perl 99543003dfeSmillert 996eac174f2Safresh1 use v5.36; 99743003dfeSmillert 99843003dfeSmillert use Benchmark; 99943003dfeSmillert use Data::Dumper; 100043003dfeSmillert my $DEBUG = 0; 100143003dfeSmillert 100243003dfeSmillert sub debug { 100343003dfeSmillert my $msg = shift; 100443003dfeSmillert 100543003dfeSmillert if ( $DEBUG ) { 100643003dfeSmillert print "DEBUG: $msg\n"; 100743003dfeSmillert } 100843003dfeSmillert }; 100943003dfeSmillert 101043003dfeSmillert timethese(100000, { 101143003dfeSmillert 'debug' => sub { 101243003dfeSmillert debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) ) 101343003dfeSmillert }, 101443003dfeSmillert 'ifdebug' => sub { 101543003dfeSmillert debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) ) if $DEBUG 101643003dfeSmillert }, 101743003dfeSmillert }); 101843003dfeSmillert 101943003dfeSmillertLet's see what C<Benchmark> makes of this: 102043003dfeSmillert 102143003dfeSmillert $> perl ifdebug 102243003dfeSmillert Benchmark: timing 100000 iterations of constant, sub... 102343003dfeSmillert ifdebug: 0 wallclock secs ( 0.01 usr + 0.00 sys = 0.01 CPU) @ 10000000.00/s (n=100000) 102443003dfeSmillert (warning: too few iterations for a reliable count) 102543003dfeSmillert debug: 14 wallclock secs (13.18 usr + 0.04 sys = 13.22 CPU) @ 7564.30/s (n=100000) 102643003dfeSmillert 102743003dfeSmillertIn the one case the code, which does exactly the same thing as far as 102843003dfeSmillertoutputting any debugging information is concerned, in other words nothing, 102943003dfeSmillerttakes 14 seconds, and in the other case the code takes one hundredth of a 103043003dfeSmillertsecond. Looks fairly definitive. Use a C<$DEBUG> variable BEFORE you call the 103143003dfeSmillertsubroutine, rather than relying on the smart functionality inside it. 103243003dfeSmillert 103343003dfeSmillert=head2 Logging if DEBUG (constant) 103443003dfeSmillert 103543003dfeSmillertIt's possible to take the previous idea a little further, by using a compile 103643003dfeSmillerttime C<DEBUG> constant. 103743003dfeSmillert 103843003dfeSmillert# ifdebug-constant 103943003dfeSmillert 104043003dfeSmillert #!/usr/bin/perl 104143003dfeSmillert 1042eac174f2Safresh1 use v5.36; 104343003dfeSmillert 104443003dfeSmillert use Benchmark; 104543003dfeSmillert use Data::Dumper; 104643003dfeSmillert use constant 104743003dfeSmillert DEBUG => 0 104843003dfeSmillert ; 104943003dfeSmillert 105043003dfeSmillert sub debug { 105143003dfeSmillert if ( DEBUG ) { 105243003dfeSmillert my $msg = shift; 105343003dfeSmillert print "DEBUG: $msg\n"; 105443003dfeSmillert } 105543003dfeSmillert }; 105643003dfeSmillert 105743003dfeSmillert timethese(100000, { 105843003dfeSmillert 'debug' => sub { 105943003dfeSmillert debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) ) 106043003dfeSmillert }, 106143003dfeSmillert 'constant' => sub { 106243003dfeSmillert debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) ) if DEBUG 106343003dfeSmillert }, 106443003dfeSmillert }); 106543003dfeSmillert 106643003dfeSmillertRunning this program produces the following output: 106743003dfeSmillert 106843003dfeSmillert $> perl ifdebug-constant 106943003dfeSmillert Benchmark: timing 100000 iterations of constant, sub... 107043003dfeSmillert constant: 0 wallclock secs (-0.00 usr + 0.00 sys = -0.00 CPU) @ -7205759403792793600000.00/s (n=100000) 107143003dfeSmillert (warning: too few iterations for a reliable count) 107243003dfeSmillert sub: 14 wallclock secs (13.09 usr + 0.00 sys = 13.09 CPU) @ 7639.42/s (n=100000) 107343003dfeSmillert 107443003dfeSmillertThe C<DEBUG> constant wipes the floor with even the C<$debug> variable, 107543003dfeSmillertclocking in at minus zero seconds, and generates a "warning: too few iterations 107643003dfeSmillertfor a reliable count" message into the bargain. To see what is really going 107743003dfeSmillerton, and why we had too few iterations when we thought we asked for 100000, we 107843003dfeSmillertcan use the very useful C<B::Deparse> to inspect the new code: 107943003dfeSmillert 108043003dfeSmillert $> perl -MO=Deparse ifdebug-constant 108143003dfeSmillert 108243003dfeSmillert use Benchmark; 108343003dfeSmillert use Data::Dumper; 108443003dfeSmillert use constant ('DEBUG', 0); 108543003dfeSmillert sub debug { 108643003dfeSmillert use warnings; 108743003dfeSmillert use strict 'refs'; 108843003dfeSmillert 0; 108943003dfeSmillert } 109043003dfeSmillert use warnings; 109143003dfeSmillert use strict 'refs'; 109243003dfeSmillert timethese(100000, {'sub', sub { 109343003dfeSmillert debug "A $0 logging message via process-id: $$" . Dumper(\%INC); 109443003dfeSmillert } 109543003dfeSmillert , 'constant', sub { 109643003dfeSmillert 0; 109743003dfeSmillert } 109843003dfeSmillert }); 109943003dfeSmillert ifdebug-constant syntax OK 110043003dfeSmillert 110143003dfeSmillertThe output shows the constant() subroutine we're testing being replaced with 110243003dfeSmillertthe value of the C<DEBUG> constant: zero. The line to be tested has been 110343003dfeSmillertcompletely optimized away, and you can't get much more efficient than that. 110443003dfeSmillert 110543003dfeSmillert=head1 POSTSCRIPT 110643003dfeSmillert 110743003dfeSmillertThis document has provided several way to go about identifying hot-spots, and 110843003dfeSmillertchecking whether any modifications have improved the runtime of the code. 110943003dfeSmillert 111043003dfeSmillertAs a final thought, remember that it's not (at the time of writing) possible to 111143003dfeSmillertproduce a useful program which will run in zero or negative time and this basic 111243003dfeSmillertprinciple can be written as: I<useful programs are slow> by their very 111343003dfeSmillertdefinition. It is of course possible to write a nearly instantaneous program, 111443003dfeSmillertbut it's not going to do very much, here's a very efficient one: 111543003dfeSmillert 111643003dfeSmillert $> perl -e 0 111743003dfeSmillert 111843003dfeSmillertOptimizing that any further is a job for C<p5p>. 111943003dfeSmillert 112043003dfeSmillert=head1 SEE ALSO 112143003dfeSmillert 112243003dfeSmillertFurther reading can be found using the modules and links below. 112343003dfeSmillert 112443003dfeSmillert=head2 PERLDOCS 112543003dfeSmillert 112643003dfeSmillertFor example: C<perldoc -f sort>. 112743003dfeSmillert 112843003dfeSmillertL<perlfaq4>. 112943003dfeSmillert 113043003dfeSmillertL<perlfork>, L<perlfunc>, L<perlretut>, L<perlthrtut>. 113143003dfeSmillert 113243003dfeSmillertL<threads>. 113343003dfeSmillert 113443003dfeSmillert=head2 MAN PAGES 113543003dfeSmillert 113643003dfeSmillertC<time>. 113743003dfeSmillert 113843003dfeSmillert=head2 MODULES 113943003dfeSmillert 114043003dfeSmillertIt's not possible to individually showcase all the performance related code for 114143003dfeSmillertPerl here, naturally, but here's a short list of modules from the CPAN which 114243003dfeSmillertdeserve further attention. 114343003dfeSmillert 114443003dfeSmillert Apache::DProf 114543003dfeSmillert Apache::SmallProf 114643003dfeSmillert Benchmark 1147898184e3Ssthen DBIx::Profile 114843003dfeSmillert Devel::AutoProfiler 114943003dfeSmillert Devel::DProf 115043003dfeSmillert Devel::DProfLB 115143003dfeSmillert Devel::FastProf 115243003dfeSmillert Devel::GraphVizProf 115343003dfeSmillert Devel::NYTProf 115443003dfeSmillert Devel::NYTProf::Apache 115543003dfeSmillert Devel::Profiler 115643003dfeSmillert Devel::Profile 115743003dfeSmillert Devel::Profit 115843003dfeSmillert Devel::SmallProf 115943003dfeSmillert Devel::WxProf 116043003dfeSmillert POE::Devel::Profiler 116143003dfeSmillert Sort::Key 116243003dfeSmillert Sort::Maker 116343003dfeSmillert 116443003dfeSmillert=head2 URLS 116543003dfeSmillert 116643003dfeSmillertVery useful online reference material: 116743003dfeSmillert 1168eac174f2Safresh1 https://web.archive.org/web/20120515021937/http://www.ccl4.org/~nick/P/Fast_Enough/ 116943003dfeSmillert 1170eac174f2Safresh1 https://web.archive.org/web/20050706081718/http://www-106.ibm.com/developerworks/library/l-optperl.html 117143003dfeSmillert 1172eac174f2Safresh1 https://perlbuzz.com/2007/11/14/bind_output_variables_in_dbi_for_speed_and_safety/ 117343003dfeSmillert 117443003dfeSmillert http://en.wikipedia.org/wiki/Performance_analysis 117543003dfeSmillert 117643003dfeSmillert http://apache.perl.org/docs/1.0/guide/performance.html 117743003dfeSmillert 117843003dfeSmillert http://perlgolf.sourceforge.net/ 117943003dfeSmillert 118043003dfeSmillert http://www.sysarch.com/Perl/sort_paper.html 118143003dfeSmillert 118243003dfeSmillert=head1 AUTHOR 118343003dfeSmillert 118443003dfeSmillertRichard Foley <richard.foley@rfi.net> Copyright (c) 2008 118543003dfeSmillert 118643003dfeSmillert=cut 1187