1=head1 NAME 2 3perlperf - Perl Performance and Optimization Techniques 4 5=head1 DESCRIPTION 6 7This is an introduction to the use of performance and optimization techniques 8which can be used with particular reference to perl programs. While many perl 9developers have come from other languages, and can use their prior knowledge 10where appropriate, there are many other people who might benefit from a few 11perl specific pointers. If you want the condensed version, perhaps the best 12advice comes from the renowned Japanese Samurai, Miyamoto Musashi, who said: 13 14 "Do Not Engage in Useless Activity" 15 16in 1645. 17 18=head1 OVERVIEW 19 20Perhaps the most common mistake programmers make is to attempt to optimize 21their code before a program actually does anything useful - this is a bad idea. 22There's no point in having an extremely fast program that doesn't work. The 23first job is to get a program to I<correctly> do something B<useful>, (not to 24mention ensuring the test suite is fully functional), and only then to consider 25optimizing it. Having decided to optimize existing working code, there are 26several simple but essential steps to consider which are intrinsic to any 27optimization process. 28 29=head2 ONE STEP SIDEWAYS 30 31Firstly, you need to establish a baseline time for the existing code, which 32timing needs to be reliable and repeatable. You'll probably want to use the 33C<Benchmark> or C<Devel::NYTProf> modules, or something similar, for this step, 34or perhaps the Unix system C<time> utility, whichever is appropriate. See the 35base of this document for a longer list of benchmarking and profiling modules, 36and recommended further reading. 37 38=head2 ONE STEP FORWARD 39 40Next, having examined the program for I<hot spots>, (places where the code 41seems to run slowly), change the code with the intention of making it run 42faster. Using version control software, like C<subversion>, will ensure no 43changes are irreversible. It's too easy to fiddle here and fiddle there - 44don't change too much at any one time or you might not discover which piece of 45code B<really> was the slow bit. 46 47=head2 ANOTHER STEP SIDEWAYS 48 49It's not enough to say: "that will make it run faster", you have to check it. 50Rerun the code under control of the benchmarking or profiling modules, from the 51first step above, and check that the new code executed the B<same task> in 52I<less time>. Save your work and repeat... 53 54=head1 GENERAL GUIDELINES 55 56The critical thing when considering performance is to remember there is no such 57thing as a C<Golden Bullet>, which is why there are no rules, only guidelines. 58 59It is clear that inline code is going to be faster than subroutine or method 60calls, because there is less overhead, but this approach has the disadvantage 61of being less maintainable and comes at the cost of greater memory usage - 62there is no such thing as a free lunch. If you are searching for an element in 63a list, it can be more efficient to store the data in a hash structure, and 64then simply look to see whether the key is defined, rather than to loop through 65the entire array using grep() for instance. substr() may be (a lot) faster 66than grep() but not as flexible, so you have another trade-off to access. Your 67code may contain a line which takes 0.01 of a second to execute which if you 68call it 1,000 times, quite likely in a program parsing even medium sized files 69for instance, you already have a 10 second delay, in just one single code 70location, and if you call that line 100,000 times, your entire program will 71slow down to an unbearable crawl. 72 73Using a subroutine as part of your sort is a powerful way to get exactly what 74you want, but will usually be slower than the built-in I<alphabetic> C<cmp> and 75I<numeric> C<E<lt>=E<gt>> sort operators. It is possible to make multiple 76passes over your data, building indices to make the upcoming sort more 77efficient, and to use what is known as the C<OM> (Orcish Maneuver) to cache the 78sort keys in advance. The cache lookup, while a good idea, can itself be a 79source of slowdown by enforcing a double pass over the data - once to setup the 80cache, and once to sort the data. Using C<pack()> to extract the required sort 81key into a consistent string can be an efficient way to build a single string 82to compare, instead of using multiple sort keys, which makes it possible to use 83the standard, written in C<c> and fast, perl C<sort()> function on the output, 84and is the basis of the C<GRT> (Guttman Rossler Transform). Some string 85combinations can slow the C<GRT> down, by just being too plain complex for its 86own good. 87 88For applications using database backends, the standard C<DBIx> namespace has 89tries to help with keeping things nippy, not least because it tries to I<not> 90query the database until the latest possible moment, but always read the docs 91which come with your choice of libraries. Among the many issues facing 92developers dealing with databases should remain aware of is to always use 93C<SQL> placeholders and to consider pre-fetching data sets when this might 94prove advantageous. Splitting up a large file by assigning multiple processes 95to parsing a single file, using say C<POE>, C<threads> or C<fork> can also be a 96useful way of optimizing your usage of the available C<CPU> resources, though 97this technique is fraught with concurrency issues and demands high attention to 98detail. 99 100Every case has a specific application and one or more exceptions, and there is 101no replacement for running a few tests and finding out which method works best 102for your particular environment, this is why writing optimal code is not an 103exact science, and why we love using Perl so much - TMTOWTDI. 104 105=head1 BENCHMARKS 106 107Here are a few examples to demonstrate usage of Perl's benchmarking tools. 108 109=head2 Assigning and Dereferencing Variables. 110 111I'm sure most of us have seen code which looks like, (or worse than), this: 112 113 if ( $obj->{_ref}->{_myscore} >= $obj->{_ref}->{_yourscore} ) { 114 ... 115 116This sort of code can be a real eyesore to read, as well as being very 117sensitive to typos, and it's much clearer to dereference the variable 118explicitly. We're side-stepping the issue of working with object-oriented 119programming techniques to encapsulate variable access via methods, only 120accessible through an object. Here we're just discussing the technical 121implementation of choice, and whether this has an effect on performance. We 122can see whether this dereferencing operation, has any overhead by putting 123comparative code in a file and running a C<Benchmark> test. 124 125# dereference 126 127 #!/usr/bin/perl 128 129 use v5.36; 130 131 use Benchmark; 132 133 my $ref = { 134 'ref' => { 135 _myscore => '100 + 1', 136 _yourscore => '102 - 1', 137 }, 138 }; 139 140 timethese(1000000, { 141 'direct' => sub { 142 my $x = $ref->{ref}->{_myscore} . $ref->{ref}->{_yourscore} ; 143 }, 144 'dereference' => sub { 145 my $ref = $ref->{ref}; 146 my $myscore = $ref->{_myscore}; 147 my $yourscore = $ref->{_yourscore}; 148 my $x = $myscore . $yourscore; 149 }, 150 }); 151 152It's essential to run any timing measurements a sufficient number of times so 153the numbers settle on a numerical average, otherwise each run will naturally 154fluctuate due to variations in the environment, to reduce the effect of 155contention for C<CPU> resources and network bandwidth for instance. Running 156the above code for one million iterations, we can take a look at the report 157output by the C<Benchmark> module, to see which approach is the most effective. 158 159 $> perl dereference 160 161 Benchmark: timing 1000000 iterations of dereference, direct... 162 dereference: 2 wallclock secs ( 1.59 usr + 0.00 sys = 1.59 CPU) @ 628930.82/s (n=1000000) 163 direct: 1 wallclock secs ( 1.20 usr + 0.00 sys = 1.20 CPU) @ 833333.33/s (n=1000000) 164 165The difference is clear to see and the dereferencing approach is slower. While 166it managed to execute an average of 628,930 times a second during our test, the 167direct approach managed to run an additional 204,403 times, unfortunately. 168Unfortunately, because there are many examples of code written using the 169multiple layer direct variable access, and it's usually horrible. It is, 170however, minusculy faster. The question remains whether the minute gain is 171actually worth the eyestrain, or the loss of maintainability. 172 173=head2 Search and replace or tr 174 175If we have a string which needs to be modified, while a regex will almost 176always be much more flexible, C<tr>, an oft underused tool, can still be a 177useful. One scenario might be replace all vowels with another character. The 178regex solution might look like this: 179 180 $str =~ s/[aeiou]/x/g 181 182The C<tr> alternative might look like this: 183 184 $str =~ tr/aeiou/xxxxx/ 185 186We can put that into a test file which we can run to check which approach is 187the fastest, using a global C<$STR> variable to assign to the C<my $str> 188variable so as to avoid perl trying to optimize any of the work away by 189noticing it's assigned only the once. 190 191# regex-transliterate 192 193 #!/usr/bin/perl 194 195 use v5.36; 196 197 use Benchmark; 198 199 my $STR = "$$-this and that"; 200 201 timethese( 1000000, { 202 'sr' => sub { my $str = $STR; $str =~ s/[aeiou]/x/g; return $str; }, 203 'tr' => sub { my $str = $STR; $str =~ tr/aeiou/xxxxx/; return $str; }, 204 }); 205 206Running the code gives us our results: 207 208 $> perl regex-transliterate 209 210 Benchmark: timing 1000000 iterations of sr, tr... 211 sr: 2 wallclock secs ( 1.19 usr + 0.00 sys = 1.19 CPU) @ 840336.13/s (n=1000000) 212 tr: 0 wallclock secs ( 0.49 usr + 0.00 sys = 0.49 CPU) @ 2040816.33/s (n=1000000) 213 214The C<tr> version is a clear winner. One solution is flexible, the other is 215fast - and it's appropriately the programmer's choice which to use. 216 217Check the C<Benchmark> docs for further useful techniques. 218 219=head1 PROFILING TOOLS 220 221A slightly larger piece of code will provide something on which a profiler can 222produce more extensive reporting statistics. This example uses the simplistic 223C<wordmatch> program which parses a given input file and spews out a short 224report on the contents. 225 226# wordmatch 227 228 #!/usr/bin/perl 229 230 use v5.36; 231 232 =head1 NAME 233 234 filewords - word analysis of input file 235 236 =head1 SYNOPSIS 237 238 filewords -f inputfilename [-d] 239 240 =head1 DESCRIPTION 241 242 This program parses the given filename, specified with C<-f>, and 243 displays a simple analysis of the words found therein. Use the C<-d> 244 switch to enable debugging messages. 245 246 =cut 247 248 use FileHandle; 249 use Getopt::Long; 250 251 my $debug = 0; 252 my $file = ''; 253 254 my $result = GetOptions ( 255 'debug' => \$debug, 256 'file=s' => \$file, 257 ); 258 die("invalid args") unless $result; 259 260 unless ( -f $file ) { 261 die("Usage: $0 -f filename [-d]"); 262 } 263 my $FH = FileHandle->new("< $file") 264 or die("unable to open file($file): $!"); 265 266 my $i_LINES = 0; 267 my $i_WORDS = 0; 268 my %count = (); 269 270 my @lines = <$FH>; 271 foreach my $line ( @lines ) { 272 $i_LINES++; 273 $line =~ s/\n//; 274 my @words = split(/ +/, $line); 275 my $i_words = scalar(@words); 276 $i_WORDS = $i_WORDS + $i_words; 277 debug("line: $i_LINES supplying $i_words words: @words"); 278 my $i_word = 0; 279 foreach my $word ( @words ) { 280 $i_word++; 281 $count{$i_LINES}{spec} += matches($i_word, $word, 282 '[^a-zA-Z0-9]'); 283 $count{$i_LINES}{only} += matches($i_word, $word, 284 '^[^a-zA-Z0-9]+$'); 285 $count{$i_LINES}{cons} += matches($i_word, $word, 286 '^[(?i:bcdfghjklmnpqrstvwxyz)]+$'); 287 $count{$i_LINES}{vows} += matches($i_word, $word, 288 '^[(?i:aeiou)]+$'); 289 $count{$i_LINES}{caps} += matches($i_word, $word, 290 '^[(A-Z)]+$'); 291 } 292 } 293 294 print report( %count ); 295 296 sub matches { 297 my $i_wd = shift; 298 my $word = shift; 299 my $regex = shift; 300 my $has = 0; 301 302 if ( $word =~ /($regex)/ ) { 303 $has++ if $1; 304 } 305 306 debug( "word: $i_wd " 307 . ($has ? 'matches' : 'does not match') 308 . " chars: /$regex/"); 309 310 return $has; 311 } 312 313 sub report { 314 my %report = @_; 315 my %rep; 316 317 foreach my $line ( keys %report ) { 318 foreach my $key ( keys $report{$line}->%* ) { 319 $rep{$key} += $report{$line}{$key}; 320 } 321 } 322 323 my $report = qq| 324 $0 report for $file: 325 lines in file: $i_LINES 326 words in file: $i_WORDS 327 words with special (non-word) characters: $i_spec 328 words with only special (non-word) characters: $i_only 329 words with only consonants: $i_cons 330 words with only capital letters: $i_caps 331 words with only vowels: $i_vows 332 |; 333 334 return $report; 335 } 336 337 sub debug { 338 my $message = shift; 339 340 if ( $debug ) { 341 print STDERR "DBG: $message\n"; 342 } 343 } 344 345 exit 0; 346 347=head2 Devel::DProf 348 349This venerable module has been the de-facto standard for Perl code profiling 350for more than a decade, but has been replaced by a number of other modules 351which have brought us back to the 21st century. Although you're recommended to 352evaluate your tool from the several mentioned here and from the CPAN list at 353the base of this document, (and currently L<Devel::NYTProf> seems to be the 354weapon of choice - see below), we'll take a quick look at the output from 355L<Devel::DProf> first, to set a baseline for Perl profiling tools. Run the 356above program under the control of C<Devel::DProf> by using the C<-d> switch on 357the command-line. 358 359 $> perl -d:DProf wordmatch -f perl5db.pl 360 361 <...multiple lines snipped...> 362 363 wordmatch report for perl5db.pl: 364 lines in file: 9428 365 words in file: 50243 366 words with special (non-word) characters: 20480 367 words with only special (non-word) characters: 7790 368 words with only consonants: 4801 369 words with only capital letters: 1316 370 words with only vowels: 1701 371 372C<Devel::DProf> produces a special file, called F<tmon.out> by default, and 373this file is read by the C<dprofpp> program, which is already installed as part 374of the C<Devel::DProf> distribution. If you call C<dprofpp> with no options, 375it will read the F<tmon.out> file in the current directory and produce a human 376readable statistics report of the run of your program. Note that this may take 377a little time. 378 379 $> dprofpp 380 381 Total Elapsed Time = 2.951677 Seconds 382 User+System Time = 2.871677 Seconds 383 Exclusive Times 384 %Time ExclSec CumulS #Calls sec/call Csec/c Name 385 102. 2.945 3.003 251215 0.0000 0.0000 main::matches 386 2.40 0.069 0.069 260643 0.0000 0.0000 main::debug 387 1.74 0.050 0.050 1 0.0500 0.0500 main::report 388 1.04 0.030 0.049 4 0.0075 0.0123 main::BEGIN 389 0.35 0.010 0.010 3 0.0033 0.0033 Exporter::as_heavy 390 0.35 0.010 0.010 7 0.0014 0.0014 IO::File::BEGIN 391 0.00 - -0.000 1 - - Getopt::Long::FindOption 392 0.00 - -0.000 1 - - Symbol::BEGIN 393 0.00 - -0.000 1 - - Fcntl::BEGIN 394 0.00 - -0.000 1 - - Fcntl::bootstrap 395 0.00 - -0.000 1 - - warnings::BEGIN 396 0.00 - -0.000 1 - - IO::bootstrap 397 0.00 - -0.000 1 - - Getopt::Long::ConfigDefaults 398 0.00 - -0.000 1 - - Getopt::Long::Configure 399 0.00 - -0.000 1 - - Symbol::gensym 400 401C<dprofpp> will produce some quite detailed reporting on the activity of the 402C<wordmatch> program. The wallclock, user and system, times are at the top of 403the analysis, and after this are the main columns defining which define the 404report. Check the C<dprofpp> docs for details of the many options it supports. 405 406See also C<L<Apache::DProf>> which hooks C<Devel::DProf> into C<mod_perl>. 407 408=head2 Devel::Profiler 409 410Let's take a look at the same program using a different profiler: 411C<Devel::Profiler>, a drop-in Perl-only replacement for C<Devel::DProf>. The 412usage is very slightly different in that instead of using the special C<-d:> 413flag, you pull C<Devel::Profiler> in directly as a module using C<-M>. 414 415 $> perl -MDevel::Profiler wordmatch -f perl5db.pl 416 417 <...multiple lines snipped...> 418 419 wordmatch report for perl5db.pl: 420 lines in file: 9428 421 words in file: 50243 422 words with special (non-word) characters: 20480 423 words with only special (non-word) characters: 7790 424 words with only consonants: 4801 425 words with only capital letters: 1316 426 words with only vowels: 1701 427 428 429C<Devel::Profiler> generates a tmon.out file which is compatible with the 430C<dprofpp> program, thus saving the construction of a dedicated statistics 431reader program. C<dprofpp> usage is therefore identical to the above example. 432 433 $> dprofpp 434 435 Total Elapsed Time = 20.984 Seconds 436 User+System Time = 19.981 Seconds 437 Exclusive Times 438 %Time ExclSec CumulS #Calls sec/call Csec/c Name 439 49.0 9.792 14.509 251215 0.0000 0.0001 main::matches 440 24.4 4.887 4.887 260643 0.0000 0.0000 main::debug 441 0.25 0.049 0.049 1 0.0490 0.0490 main::report 442 0.00 0.000 0.000 1 0.0000 0.0000 Getopt::Long::GetOptions 443 0.00 0.000 0.000 2 0.0000 0.0000 Getopt::Long::ParseOptionSpec 444 0.00 0.000 0.000 1 0.0000 0.0000 Getopt::Long::FindOption 445 0.00 0.000 0.000 1 0.0000 0.0000 IO::File::new 446 0.00 0.000 0.000 1 0.0000 0.0000 IO::Handle::new 447 0.00 0.000 0.000 1 0.0000 0.0000 Symbol::gensym 448 0.00 0.000 0.000 1 0.0000 0.0000 IO::File::open 449 450Interestingly we get slightly different results, which is mostly because the 451algorithm which generates the report is different, even though the output file 452format was allegedly identical. The elapsed, user and system times are clearly 453showing the time it took for C<Devel::Profiler> to execute its own run, but 454the column listings feel more accurate somehow than the ones we had earlier 455from C<Devel::DProf>. The 102% figure has disappeared, for example. This is 456where we have to use the tools at our disposal, and recognise their pros and 457cons, before using them. Interestingly, the numbers of calls for each 458subroutine are identical in the two reports, it's the percentages which differ. 459As the author of C<Devel::Profiler> writes: 460 461 ...running HTML::Template's test suite under Devel::DProf shows 462 output() taking NO time but Devel::Profiler shows around 10% of the 463 time is in output(). I don't know which to trust but my gut tells me 464 something is wrong with Devel::DProf. HTML::Template::output() is a 465 big routine that's called for every test. Either way, something needs 466 fixing. 467 468YMMV. 469 470See also C<L<Devel::Apache::Profiler>> which hooks C<Devel::Profiler> 471into C<mod_perl>. 472 473=head2 Devel::SmallProf 474 475The C<Devel::SmallProf> profiler examines the runtime of your Perl program and 476produces a line-by-line listing to show how many times each line was called, 477and how long each line took to execute. It is called by supplying the familiar 478C<-d> flag to Perl at runtime. 479 480 $> perl -d:SmallProf wordmatch -f perl5db.pl 481 482 <...multiple lines snipped...> 483 484 wordmatch report for perl5db.pl: 485 lines in file: 9428 486 words in file: 50243 487 words with special (non-word) characters: 20480 488 words with only special (non-word) characters: 7790 489 words with only consonants: 4801 490 words with only capital letters: 1316 491 words with only vowels: 1701 492 493C<Devel::SmallProf> writes its output into a file called F<smallprof.out>, by 494default. The format of the file looks like this: 495 496 <num> <time> <ctime> <line>:<text> 497 498When the program has terminated, the output may be examined and sorted using 499any standard text filtering utilities. Something like the following may be 500sufficient: 501 502 $> cat smallprof.out | grep \d*: | sort -k3 | tac | head -n20 503 504 251215 1.65674 7.68000 75: if ( $word =~ /($regex)/ ) { 505 251215 0.03264 4.40000 79: debug("word: $i_wd ".($has ? 'matches' : 506 251215 0.02693 4.10000 81: return $has; 507 260643 0.02841 4.07000 128: if ( $debug ) { 508 260643 0.02601 4.04000 126: my $message = shift; 509 251215 0.02641 3.91000 73: my $has = 0; 510 251215 0.03311 3.71000 70: my $i_wd = shift; 511 251215 0.02699 3.69000 72: my $regex = shift; 512 251215 0.02766 3.68000 71: my $word = shift; 513 50243 0.59726 1.00000 59: $count{$i_LINES}{cons} = 514 50243 0.48175 0.92000 61: $count{$i_LINES}{spec} = 515 50243 0.00644 0.89000 56: my $i_cons = matches($i_word, $word, 516 50243 0.48837 0.88000 63: $count{$i_LINES}{caps} = 517 50243 0.00516 0.88000 58: my $i_caps = matches($i_word, $word, '^[(A- 518 50243 0.00631 0.81000 54: my $i_spec = matches($i_word, $word, '[^a- 519 50243 0.00496 0.80000 57: my $i_vows = matches($i_word, $word, 520 50243 0.00688 0.80000 53: $i_word++; 521 50243 0.48469 0.79000 62: $count{$i_LINES}{only} = 522 50243 0.48928 0.77000 60: $count{$i_LINES}{vows} = 523 50243 0.00683 0.75000 55: my $i_only = matches($i_word, $word, '^[^a- 524 525You can immediately see a slightly different focus to the subroutine profiling 526modules, and we start to see exactly which line of code is taking the most 527time. That regex line is looking a bit suspicious, for example. Remember that 528these tools are supposed to be used together, there is no single best way to 529profile your code, you need to use the best tools for the job. 530 531See also C<L<Apache::SmallProf>> which hooks C<Devel::SmallProf> into 532C<mod_perl>. 533 534=head2 Devel::FastProf 535 536C<Devel::FastProf> is another Perl line profiler. This was written with a view 537to getting a faster line profiler, than is possible with for example 538C<Devel::SmallProf>, because it's written in C<C>. To use C<Devel::FastProf>, 539supply the C<-d> argument to Perl: 540 541 $> perl -d:FastProf wordmatch -f perl5db.pl 542 543 <...multiple lines snipped...> 544 545 wordmatch report for perl5db.pl: 546 lines in file: 9428 547 words in file: 50243 548 words with special (non-word) characters: 20480 549 words with only special (non-word) characters: 7790 550 words with only consonants: 4801 551 words with only capital letters: 1316 552 words with only vowels: 1701 553 554C<Devel::FastProf> writes statistics to the file F<fastprof.out> in the current 555directory. The output file, which can be specified, can be interpreted by using 556the C<fprofpp> command-line program. 557 558 $> fprofpp | head -n20 559 560 # fprofpp output format is: 561 # filename:line time count: source 562 wordmatch:75 3.93338 251215: if ( $word =~ /($regex)/ ) { 563 wordmatch:79 1.77774 251215: debug("word: $i_wd ".($has ? 'matches' : 'does not match')." chars: /$regex/"); 564 wordmatch:81 1.47604 251215: return $has; 565 wordmatch:126 1.43441 260643: my $message = shift; 566 wordmatch:128 1.42156 260643: if ( $debug ) { 567 wordmatch:70 1.36824 251215: my $i_wd = shift; 568 wordmatch:71 1.36739 251215: my $word = shift; 569 wordmatch:72 1.35939 251215: my $regex = shift; 570 571Straightaway we can see that the number of times each line has been called is 572identical to the C<Devel::SmallProf> output, and the sequence is only very 573slightly different based on the ordering of the amount of time each line took 574to execute, C<if ( $debug ) { > and C<my $message = shift;>, for example. The 575differences in the actual times recorded might be in the algorithm used 576internally, or it could be due to system resource limitations or contention. 577 578See also the L<DBIx::Profile> which will profile database queries running 579under the C<DBIx::*> namespace. 580 581=head2 Devel::NYTProf 582 583C<Devel::NYTProf> is the B<next generation> of Perl code profiler, fixing many 584shortcomings in other tools and implementing many cool features. First of all it 585can be used as either a I<line> profiler, a I<block> or a I<subroutine> 586profiler, all at once. It can also use sub-microsecond (100ns) resolution on 587systems which provide C<clock_gettime()>. It can be started and stopped even 588by the program being profiled. It's a one-line entry to profile C<mod_perl> 589applications. It's written in C<c> and is probably the fastest profiler 590available for Perl. The list of coolness just goes on. Enough of that, let's 591see how to it works - just use the familiar C<-d> switch to plug it in and run 592the code. 593 594 $> perl -d:NYTProf wordmatch -f perl5db.pl 595 596 wordmatch report for perl5db.pl: 597 lines in file: 9427 598 words in file: 50243 599 words with special (non-word) characters: 20480 600 words with only special (non-word) characters: 7790 601 words with only consonants: 4801 602 words with only capital letters: 1316 603 words with only vowels: 1701 604 605C<NYTProf> will generate a report database into the file F<nytprof.out> by 606default. Human readable reports can be generated from here by using the 607supplied C<nytprofhtml> (HTML output) and C<nytprofcsv> (CSV output) programs. 608We've used the Unix system C<html2text> utility to convert the 609F<nytprof/index.html> file for convenience here. 610 611 $> html2text nytprof/index.html 612 613 Performance Profile Index 614 For wordmatch 615 Run on Fri Sep 26 13:46:39 2008 616 Reported on Fri Sep 26 13:47:23 2008 617 618 Top 15 Subroutines -- ordered by exclusive time 619 |Calls |P |F |Inclusive|Exclusive|Subroutine | 620 | | | |Time |Time | | 621 |251215|5 |1 |13.09263 |10.47692 |main:: |matches | 622 |260642|2 |1 |2.71199 |2.71199 |main:: |debug | 623 |1 |1 |1 |0.21404 |0.21404 |main:: |report | 624 |2 |2 |2 |0.00511 |0.00511 |XSLoader:: |load (xsub) | 625 |14 |14|7 |0.00304 |0.00298 |Exporter:: |import | 626 |3 |1 |1 |0.00265 |0.00254 |Exporter:: |as_heavy | 627 |10 |10|4 |0.00140 |0.00140 |vars:: |import | 628 |13 |13|1 |0.00129 |0.00109 |constant:: |import | 629 |1 |1 |1 |0.00360 |0.00096 |FileHandle:: |import | 630 |3 |3 |3 |0.00086 |0.00074 |warnings::register::|import | 631 |9 |3 |1 |0.00036 |0.00036 |strict:: |bits | 632 |13 |13|13|0.00032 |0.00029 |strict:: |import | 633 |2 |2 |2 |0.00020 |0.00020 |warnings:: |import | 634 |2 |1 |1 |0.00020 |0.00020 |Getopt::Long:: |ParseOptionSpec| 635 |7 |7 |6 |0.00043 |0.00020 |strict:: |unimport | 636 637 For more information see the full list of 189 subroutines. 638 639The first part of the report already shows the critical information regarding 640which subroutines are using the most time. The next gives some statistics 641about the source files profiled. 642 643 Source Code Files -- ordered by exclusive time then name 644 |Stmts |Exclusive|Avg. |Reports |Source File | 645 | |Time | | | | 646 |2699761|15.66654 |6e-06 |line . block . sub|wordmatch | 647 |35 |0.02187 |0.00062|line . block . sub|IO/Handle.pm | 648 |274 |0.01525 |0.00006|line . block . sub|Getopt/Long.pm | 649 |20 |0.00585 |0.00029|line . block . sub|Fcntl.pm | 650 |128 |0.00340 |0.00003|line . block . sub|Exporter/Heavy.pm | 651 |42 |0.00332 |0.00008|line . block . sub|IO/File.pm | 652 |261 |0.00308 |0.00001|line . block . sub|Exporter.pm | 653 |323 |0.00248 |8e-06 |line . block . sub|constant.pm | 654 |12 |0.00246 |0.00021|line . block . sub|File/Spec/Unix.pm | 655 |191 |0.00240 |0.00001|line . block . sub|vars.pm | 656 |77 |0.00201 |0.00003|line . block . sub|FileHandle.pm | 657 |12 |0.00198 |0.00016|line . block . sub|Carp.pm | 658 |14 |0.00175 |0.00013|line . block . sub|Symbol.pm | 659 |15 |0.00130 |0.00009|line . block . sub|IO.pm | 660 |22 |0.00120 |0.00005|line . block . sub|IO/Seekable.pm | 661 |198 |0.00085 |4e-06 |line . block . sub|warnings/register.pm| 662 |114 |0.00080 |7e-06 |line . block . sub|strict.pm | 663 |47 |0.00068 |0.00001|line . block . sub|warnings.pm | 664 |27 |0.00054 |0.00002|line . block . sub|overload.pm | 665 |9 |0.00047 |0.00005|line . block . sub|SelectSaver.pm | 666 |13 |0.00045 |0.00003|line . block . sub|File/Spec.pm | 667 |2701595|15.73869 | |Total | 668 |128647 |0.74946 | |Average | 669 | |0.00201 |0.00003|Median | 670 | |0.00121 |0.00003|Deviation | 671 672 Report produced by the NYTProf 2.03 Perl profiler, developed by Tim Bunce and 673 Adam Kaplan. 674 675At this point, if you're using the I<html> report, you can click through the 676various links to bore down into each subroutine and each line of code. Because 677we're using the text reporting here, and there's a whole directory full of 678reports built for each source file, we'll just display a part of the 679corresponding F<wordmatch-line.html> file, sufficient to give an idea of the 680sort of output you can expect from this cool tool. 681 682 $> html2text nytprof/wordmatch-line.html 683 684 Performance Profile -- -block view-.-line view-.-sub view- 685 For wordmatch 686 Run on Fri Sep 26 13:46:39 2008 687 Reported on Fri Sep 26 13:47:22 2008 688 689 File wordmatch 690 691 Subroutines -- ordered by exclusive time 692 |Calls |P|F|Inclusive|Exclusive|Subroutine | 693 | | | |Time |Time | | 694 |251215|5|1|13.09263 |10.47692 |main::|matches| 695 |260642|2|1|2.71199 |2.71199 |main::|debug | 696 |1 |1|1|0.21404 |0.21404 |main::|report | 697 |0 |0|0|0 |0 |main::|BEGIN | 698 699 700 |Line|Stmts.|Exclusive|Avg. |Code | 701 | | |Time | | | 702 |1 | | | |#!/usr/bin/perl | 703 |2 | | | | | 704 | | | | |use strict; | 705 |3 |3 |0.00086 |0.00029|# spent 0.00003s making 1 calls to strict:: | 706 | | | | |import | 707 | | | | |use warnings; | 708 |4 |3 |0.01563 |0.00521|# spent 0.00012s making 1 calls to warnings:: | 709 | | | | |import | 710 |5 | | | | | 711 |6 | | | |=head1 NAME | 712 |7 | | | | | 713 |8 | | | |filewords - word analysis of input file | 714 <...snip...> 715 |62 |1 |0.00445 |0.00445|print report( %count ); | 716 | | | | |# spent 0.21404s making 1 calls to main::report| 717 |63 | | | | | 718 | | | | |# spent 23.56955s (10.47692+2.61571) within | 719 | | | | |main::matches which was called 251215 times, | 720 | | | | |avg 0.00005s/call: # 50243 times | 721 | | | | |(2.12134+0.51939s) at line 57 of wordmatch, avg| 722 | | | | |0.00005s/call # 50243 times (2.17735+0.54550s) | 723 |64 | | | |at line 56 of wordmatch, avg 0.00005s/call # | 724 | | | | |50243 times (2.10992+0.51797s) at line 58 of | 725 | | | | |wordmatch, avg 0.00005s/call # 50243 times | 726 | | | | |(2.12696+0.51598s) at line 55 of wordmatch, avg| 727 | | | | |0.00005s/call # 50243 times (1.94134+0.51687s) | 728 | | | | |at line 54 of wordmatch, avg 0.00005s/call | 729 | | | | |sub matches { | 730 <...snip...> 731 |102 | | | | | 732 | | | | |# spent 2.71199s within main::debug which was | 733 | | | | |called 260642 times, avg 0.00001s/call: # | 734 | | | | |251215 times (2.61571+0s) by main::matches at | 735 |103 | | | |line 74 of wordmatch, avg 0.00001s/call # 9427 | 736 | | | | |times (0.09628+0s) at line 50 of wordmatch, avg| 737 | | | | |0.00001s/call | 738 | | | | |sub debug { | 739 |104 |260642|0.58496 |2e-06 |my $message = shift; | 740 |105 | | | | | 741 |106 |260642|1.09917 |4e-06 |if ( $debug ) { | 742 |107 | | | |print STDERR "DBG: $message\n"; | 743 |108 | | | |} | 744 |109 | | | |} | 745 |110 | | | | | 746 |111 |1 |0.01501 |0.01501|exit 0; | 747 |112 | | | | | 748 749Oodles of very useful information in there - this seems to be the way forward. 750 751See also C<L<Devel::NYTProf::Apache>> which hooks C<Devel::NYTProf> into 752C<mod_perl>. 753 754=head1 SORTING 755 756Perl modules are not the only tools a performance analyst has at their 757disposal, system tools like C<time> should not be overlooked as the next 758example shows, where we take a quick look at sorting. Many books, theses and 759articles, have been written about efficient sorting algorithms, and this is not 760the place to repeat such work, there's several good sorting modules which 761deserve taking a look at too: C<Sort::Maker>, C<Sort::Key> spring to mind. 762However, it's still possible to make some observations on certain Perl specific 763interpretations on issues relating to sorting data sets and give an example or 764two with regard to how sorting large data volumes can effect performance. 765Firstly, an often overlooked point when sorting large amounts of data, one can 766attempt to reduce the data set to be dealt with and in many cases C<grep()> can 767be quite useful as a simple filter: 768 769 @data = sort grep { /$filter/ } @incoming 770 771A command such as this can vastly reduce the volume of material to actually 772sort through in the first place, and should not be too lightly disregarded 773purely on the basis of its simplicity. The C<KISS> principle is too often 774overlooked - the next example uses the simple system C<time> utility to 775demonstrate. Let's take a look at an actual example of sorting the contents of 776a large file, an apache logfile would do. This one has over a quarter of a 777million lines, is 50M in size, and a snippet of it looks like this: 778 779# logfile 780 781 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)" 782 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)" 783 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" 784 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" 785 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" 786 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)" 787 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)" 788 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)" 789 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)" 790 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)" 791 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" 792 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" 793 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" 794 crawl1.cosmixcorp.com - - [08/Feb/2007:13:27:57 +0000] "GET /robots.txt HTTP/1.0" 200 179 "-" "voyager/1.0" 795 crawl1.cosmixcorp.com - - [08/Feb/2007:13:28:25 +0000] "GET /links.html HTTP/1.0" 200 3413 "-" "voyager/1.0" 796 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)" 797 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)" 798 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)" 799 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)" 800 pop.compuscan.co.za - - [08/Feb/2007:14:10:43 +0000] "GET / HTTP/1.1" 200 3309 "-" "www.clamav.net" 801 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)" 802 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)" 803 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" 804 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" 805 806The specific task here is to sort the 286,525 lines of this file by Response 807Code, Query, Browser, Referring Url, and lastly Date. One solution might be to 808use the following code, which iterates over the files given on the 809command-line. 810 811# sort-apache-log 812 813 #!/usr/bin/perl -n 814 815 use v5.36; 816 817 my @data; 818 819 LINE: 820 while ( <> ) { 821 my $line = $_; 822 if ( 823 $line =~ m/^( 824 ([\w\.\-]+) # client 825 \s*-\s*-\s*\[ 826 ([^]]+) # date 827 \]\s*"\w+\s* 828 (\S+) # query 829 [^"]+"\s* 830 (\d+) # status 831 \s+\S+\s+"[^"]*"\s+" 832 ([^"]*) # browser 833 " 834 .* 835 )$/x 836 ) { 837 my @chunks = split(/ +/, $line); 838 my $ip = $1; 839 my $date = $2; 840 my $query = $3; 841 my $status = $4; 842 my $browser = $5; 843 844 push(@data, [$ip, $date, $query, $status, $browser, $line]); 845 } 846 } 847 848 my @sorted = sort { 849 $a->[3] cmp $b->[3] 850 || 851 $a->[2] cmp $b->[2] 852 || 853 $a->[0] cmp $b->[0] 854 || 855 $a->[1] cmp $b->[1] 856 || 857 $a->[4] cmp $b->[4] 858 } @data; 859 860 foreach my $data ( @sorted ) { 861 print $data->[5]; 862 } 863 864 exit 0; 865 866When running this program, redirect C<STDOUT> so it is possible to check the 867output is correct from following test runs and use the system C<time> utility 868to check the overall runtime. 869 870 $> time ./sort-apache-log logfile > out-sort 871 872 real 0m17.371s 873 user 0m15.757s 874 sys 0m0.592s 875 876The program took just over 17 wallclock seconds to run. Note the different 877values C<time> outputs, it's important to always use the same one, and to not 878confuse what each one means. 879 880=over 4 881 882=item Elapsed Real Time 883 884The overall, or wallclock, time between when C<time> was called, and when it 885terminates. The elapsed time includes both user and system times, and time 886spent waiting for other users and processes on the system. Inevitably, this is 887the most approximate of the measurements given. 888 889=item User CPU Time 890 891The user time is the amount of time the entire process spent on behalf of the 892user on this system executing this program. 893 894=item System CPU Time 895 896The system time is the amount of time the kernel itself spent executing 897routines, or system calls, on behalf of this process user. 898 899=back 900 901Running this same process as a C<Schwarzian Transform> it is possible to 902eliminate the input and output arrays for storing all the data, and work on the 903input directly as it arrives too. Otherwise, the code looks fairly similar: 904 905# sort-apache-log-schwarzian 906 907 #!/usr/bin/perl -n 908 909 use v5.36; 910 911 print 912 913 map $_->[0] => 914 915 sort { 916 $a->[4] cmp $b->[4] 917 || 918 $a->[3] cmp $b->[3] 919 || 920 $a->[1] cmp $b->[1] 921 || 922 $a->[2] cmp $b->[2] 923 || 924 $a->[5] cmp $b->[5] 925 } 926 map [ $_, m/^( 927 ([\w\.\-]+) # client 928 \s*-\s*-\s*\[ 929 ([^]]+) # date 930 \]\s*"\w+\s* 931 (\S+) # query 932 [^"]+"\s* 933 (\d+) # status 934 \s+\S+\s+"[^"]*"\s+" 935 ([^"]*) # browser 936 " 937 .* 938 )$/xo ] 939 940 => <>; 941 942 exit 0; 943 944Run the new code against the same logfile, as above, to check the new time. 945 946 $> time ./sort-apache-log-schwarzian logfile > out-schwarz 947 948 real 0m9.664s 949 user 0m8.873s 950 sys 0m0.704s 951 952The time has been cut in half, which is a respectable speed improvement by any 953standard. Naturally, it is important to check the output is consistent with 954the first program run, this is where the Unix system C<cksum> utility comes in. 955 956 $> cksum out-sort out-schwarz 957 3044173777 52029194 out-sort 958 3044173777 52029194 out-schwarz 959 960BTW. Beware too of pressure from managers who see you speed a program up by 50% 961of the runtime once, only to get a request one month later to do the same again 962(true story) - you'll just have to point out you're only human, even if you are a 963Perl programmer, and you'll see what you can do... 964 965=head1 LOGGING 966 967An essential part of any good development process is appropriate error handling 968with appropriately informative messages, however there exists a school of 969thought which suggests that log files should be I<chatty>, as if the chain of 970unbroken output somehow ensures the survival of the program. If speed is in 971any way an issue, this approach is wrong. 972 973A common sight is code which looks something like this: 974 975 logger->debug( "A logging message via process-id: $$ INC: " 976 . Dumper(\%INC) ) 977 978The problem is that this code will always be parsed and executed, even when the 979debug level set in the logging configuration file is zero. Once the debug() 980subroutine has been entered, and the internal C<$debug> variable confirmed to 981be zero, for example, the message which has been sent in will be discarded and 982the program will continue. In the example given though, the C<\%INC> hash will 983already have been dumped, and the message string constructed, all of which work 984could be bypassed by a debug variable at the statement level, like this: 985 986 logger->debug( "A logging message via process-id: $$ INC: " 987 . Dumper(\%INC) ) if $DEBUG; 988 989This effect can be demonstrated by setting up a test script with both forms, 990including a C<debug()> subroutine to emulate typical C<logger()> functionality. 991 992# ifdebug 993 994 #!/usr/bin/perl 995 996 use v5.36; 997 998 use Benchmark; 999 use Data::Dumper; 1000 my $DEBUG = 0; 1001 1002 sub debug { 1003 my $msg = shift; 1004 1005 if ( $DEBUG ) { 1006 print "DEBUG: $msg\n"; 1007 } 1008 }; 1009 1010 timethese(100000, { 1011 'debug' => sub { 1012 debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) ) 1013 }, 1014 'ifdebug' => sub { 1015 debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) ) if $DEBUG 1016 }, 1017 }); 1018 1019Let's see what C<Benchmark> makes of this: 1020 1021 $> perl ifdebug 1022 Benchmark: timing 100000 iterations of constant, sub... 1023 ifdebug: 0 wallclock secs ( 0.01 usr + 0.00 sys = 0.01 CPU) @ 10000000.00/s (n=100000) 1024 (warning: too few iterations for a reliable count) 1025 debug: 14 wallclock secs (13.18 usr + 0.04 sys = 13.22 CPU) @ 7564.30/s (n=100000) 1026 1027In the one case the code, which does exactly the same thing as far as 1028outputting any debugging information is concerned, in other words nothing, 1029takes 14 seconds, and in the other case the code takes one hundredth of a 1030second. Looks fairly definitive. Use a C<$DEBUG> variable BEFORE you call the 1031subroutine, rather than relying on the smart functionality inside it. 1032 1033=head2 Logging if DEBUG (constant) 1034 1035It's possible to take the previous idea a little further, by using a compile 1036time C<DEBUG> constant. 1037 1038# ifdebug-constant 1039 1040 #!/usr/bin/perl 1041 1042 use v5.36; 1043 1044 use Benchmark; 1045 use Data::Dumper; 1046 use constant 1047 DEBUG => 0 1048 ; 1049 1050 sub debug { 1051 if ( DEBUG ) { 1052 my $msg = shift; 1053 print "DEBUG: $msg\n"; 1054 } 1055 }; 1056 1057 timethese(100000, { 1058 'debug' => sub { 1059 debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) ) 1060 }, 1061 'constant' => sub { 1062 debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) ) if DEBUG 1063 }, 1064 }); 1065 1066Running this program produces the following output: 1067 1068 $> perl ifdebug-constant 1069 Benchmark: timing 100000 iterations of constant, sub... 1070 constant: 0 wallclock secs (-0.00 usr + 0.00 sys = -0.00 CPU) @ -7205759403792793600000.00/s (n=100000) 1071 (warning: too few iterations for a reliable count) 1072 sub: 14 wallclock secs (13.09 usr + 0.00 sys = 13.09 CPU) @ 7639.42/s (n=100000) 1073 1074The C<DEBUG> constant wipes the floor with even the C<$debug> variable, 1075clocking in at minus zero seconds, and generates a "warning: too few iterations 1076for a reliable count" message into the bargain. To see what is really going 1077on, and why we had too few iterations when we thought we asked for 100000, we 1078can use the very useful C<B::Deparse> to inspect the new code: 1079 1080 $> perl -MO=Deparse ifdebug-constant 1081 1082 use Benchmark; 1083 use Data::Dumper; 1084 use constant ('DEBUG', 0); 1085 sub debug { 1086 use warnings; 1087 use strict 'refs'; 1088 0; 1089 } 1090 use warnings; 1091 use strict 'refs'; 1092 timethese(100000, {'sub', sub { 1093 debug "A $0 logging message via process-id: $$" . Dumper(\%INC); 1094 } 1095 , 'constant', sub { 1096 0; 1097 } 1098 }); 1099 ifdebug-constant syntax OK 1100 1101The output shows the constant() subroutine we're testing being replaced with 1102the value of the C<DEBUG> constant: zero. The line to be tested has been 1103completely optimized away, and you can't get much more efficient than that. 1104 1105=head1 POSTSCRIPT 1106 1107This document has provided several way to go about identifying hot-spots, and 1108checking whether any modifications have improved the runtime of the code. 1109 1110As a final thought, remember that it's not (at the time of writing) possible to 1111produce a useful program which will run in zero or negative time and this basic 1112principle can be written as: I<useful programs are slow> by their very 1113definition. It is of course possible to write a nearly instantaneous program, 1114but it's not going to do very much, here's a very efficient one: 1115 1116 $> perl -e 0 1117 1118Optimizing that any further is a job for C<p5p>. 1119 1120=head1 SEE ALSO 1121 1122Further reading can be found using the modules and links below. 1123 1124=head2 PERLDOCS 1125 1126For example: C<perldoc -f sort>. 1127 1128L<perlfaq4>. 1129 1130L<perlfork>, L<perlfunc>, L<perlretut>, L<perlthrtut>. 1131 1132L<threads>. 1133 1134=head2 MAN PAGES 1135 1136C<time>. 1137 1138=head2 MODULES 1139 1140It's not possible to individually showcase all the performance related code for 1141Perl here, naturally, but here's a short list of modules from the CPAN which 1142deserve further attention. 1143 1144 Apache::DProf 1145 Apache::SmallProf 1146 Benchmark 1147 DBIx::Profile 1148 Devel::AutoProfiler 1149 Devel::DProf 1150 Devel::DProfLB 1151 Devel::FastProf 1152 Devel::GraphVizProf 1153 Devel::NYTProf 1154 Devel::NYTProf::Apache 1155 Devel::Profiler 1156 Devel::Profile 1157 Devel::Profit 1158 Devel::SmallProf 1159 Devel::WxProf 1160 POE::Devel::Profiler 1161 Sort::Key 1162 Sort::Maker 1163 1164=head2 URLS 1165 1166Very useful online reference material: 1167 1168 https://web.archive.org/web/20120515021937/http://www.ccl4.org/~nick/P/Fast_Enough/ 1169 1170 https://web.archive.org/web/20050706081718/http://www-106.ibm.com/developerworks/library/l-optperl.html 1171 1172 https://perlbuzz.com/2007/11/14/bind_output_variables_in_dbi_for_speed_and_safety/ 1173 1174 http://en.wikipedia.org/wiki/Performance_analysis 1175 1176 http://apache.perl.org/docs/1.0/guide/performance.html 1177 1178 http://perlgolf.sourceforge.net/ 1179 1180 http://www.sysarch.com/Perl/sort_paper.html 1181 1182=head1 AUTHOR 1183 1184Richard Foley <richard.foley@rfi.net> Copyright (c) 2008 1185 1186=cut 1187