PERLPERF(1perl)
💖 PERLPERF 💖
okay bestie, welcome to perlperf — the Perl Performance and Optimization Techniques page from the Perl Programmers Reference Guide ✨. This is your girl explaining how to make Perl go zoom zoom without breaking your whole entire program, and I'm gonna keep every single fact while making it, like, readable 💅
🌸 NAME 🌸
perlperf — Perl Performance and Optimization Techniques 🦋
✨ DESCRIPTION ✨
So this is an intro to performance and optimization techniques you can use, specifically with perl programs in mind. Lots of perl devs came from other languages and can totally bring their prior knowledge along — but there's a whole other crowd of people who'd benefit from a few perl-specific pointers. 🫶
If you want the ultra-condensed version, honestly the best advice comes from the renowned Japanese Samurai Miyamoto Musashi, who said:
"Do Not Engage in Useless Activity"
...in 1645. periodt. 👑
🌈 OVERVIEW 🌈
Okay so the most common mistake programmers make is trying to optimize their code before the program actually does anything useful. That's a bad idea. There is literally no point in having an extremely fast program that doesn't work 💀. Your first job is to get a program to correctly do something useful — and yes that includes making sure the test suite is fully functional — and only then should you even think about optimizing it. Once you've decided to optimize existing working code, there are several simple but essential steps that are intrinsic to any optimization process. 🌟
🚶♀️ ONE STEP SIDEWAYS
First up: you need to establish a baseline time for the existing code, and that timing needs to be reliable and repeatable. You'll probably want the Benchmark or Devel::NYTProf modules, or something similar, for this step — or maybe the Unix system time utility, whichever is appropriate. Scroll to the base of this document for a longer list of benchmarking and profiling modules plus recommended further reading. 📚
🚀 ONE STEP FORWARD
Next: having examined the program for hot spots (places where the code seems to run slowly), change the code with the intention of making it run faster. Use version control software, like subversion, so none of your changes are irreversible — future you will thank you 🙏. It is so easy to fiddle here and fiddle there, so do NOT change too much at any one time or you might not discover which piece of code really was the slow bit. 🔍
🎯 ANOTHER STEP SIDEWAYS
It's not enough to say "that will make it run faster" — you have to check it. Rerun the code under control of the benchmarking or profiling modules from the first step above, and check that the new code executed the same task in less time. Save your work and repeat... 🔁
💅 GENERAL GUIDELINES 💅
The critical thing when considering performance is to remember there is no such thing as a "Golden Bullet" — which is why there are no rules, only guidelines. no cap.
It's clear that inline code is going to be faster than subroutine or method calls, because there's less overhead — but this approach has the disadvantage of being less maintainable and it comes at the cost of greater memory usage. There is no such thing as a free lunch. If you're searching for an element in a list, it can be more efficient to store the data in a hash structure and then simply look to see whether the key is defined, rather than looping through the entire array using grep() for instance. substr() may be (a lot) faster than grep() but it's not as flexible, so you've got another trade-off to access. 😭 Your code may contain a line which takes 0.01 of a second to execute — and if you call it 1,000 times, quite likely in a program parsing even medium sized files for instance, you already have a 10 second delay, in just one single code location. And if you call that line 100,000 times, your entire program will slow down to an unbearable crawl. 💀
Using a subroutine as part of your sort is a powerful way to get exactly what you want, but it will usually be slower than the built-in alphabetic cmp and numeric <=> sort operators. It is possible to make multiple passes over your data, building indices to make the upcoming sort more efficient, and to use what is known as the OM (Orcish Maneuver) to cache the sort keys in advance. The cache lookup, while a good idea, can itself be a source of slowdown by enforcing a double pass over the data — once to setup the cache, and once to sort the data. Using pack() to extract the required sort key into a consistent string can be an efficient way to build a single string to compare, instead of using multiple sort keys — which makes it possible to use the standard, written in c and fast, perl sort() function on the output, and is the basis of the GRT (Guttman Rossler Transform). Some string combinations can slow the GRT down, by just being too plain complex for its own good. 😵💫
For applications using database backends, the standard DBIx namespace has tried to help with keeping things nippy — not least because it tries to not query the database until the latest possible moment — but always read the docs which come with your choice of libraries. Among the many issues facing developers dealing with databases, stay aware of this: always use SQL placeholders, and consider pre-fetching data sets when this might prove advantageous. Splitting up a large file by assigning multiple processes to parsing a single file — using say POE, threads or fork — can also be a useful way of optimizing your usage of the available CPU resources, though this technique is fraught with concurrency issues and demands high attention to detail. 🧠
Every case has a specific application and one or more exceptions, and there is no replacement for running a few tests and finding out which method works best for your particular environment. This is why writing optimal code is not an exact science, and why we love using Perl so much — TMTOWTDI. 🌈
🔥 BENCHMARKS 🔥
Here are a few examples to demonstrate usage of Perl's benchmarking tools. ✨
🎀 Assigning and Dereferencing Variables
I'm sure most of us have seen code which looks like, (or worse than), this:
if ( $obj->{_ref}->{_myscore} >= $obj->{_ref}->{_yourscore} ) {
...
}This sort of code can be a real eyesore to read, as well as being very sensitive to typos — and it's much clearer to dereference the variable explicitly. Note: we're side-stepping the issue of working with object-oriented programming techniques to encapsulate variable access via methods, only accessible through an object. Here we're just discussing the technical implementation of choice, and whether this has an effect on performance. 👀
We can see whether this dereferencing operation has any overhead by putting comparative code in a file and running a Benchmark test.
# dereference
#!/usr/bin/perl
use v5.36;
use Benchmark;
my $ref = {
'ref' => {
_myscore => '100 + 1',
_yourscore => '102 - 1',
},
};
timethese(1000000, {
'direct' => sub {
my $x = $ref->{ref}->{_myscore} . $ref->{ref}->{_yourscore} ;
},
'dereference' => sub {
my $ref = $ref->{ref};
my $myscore = $ref->{_myscore};
my $yourscore = $ref->{_yourscore};
my $x = $myscore . $yourscore;
},
});It's essential to run any timing measurements a sufficient number of times so the numbers settle on a numerical average — otherwise each run will naturally fluctuate due to variations in the environment, to reduce the effect of contention for CPU resources and network bandwidth for instance. 🌐 Running the above code for one million iterations, we can take a look at the report output by the Benchmark module, to see which approach is the most effective.
$> perl dereference
Benchmark: timing 1000000 iterations of dereference, direct...
dereference: 2 wallclock secs ( 1.59 usr + 0.00 sys = 1.59 CPU) @ 628930.82/s (n=1000000)
direct: 1 wallclock secs ( 1.20 usr + 0.00 sys = 1.20 CPU) @ 833333.33/s (n=1000000)The difference is clear to see and the dereferencing approach is slower. While it managed to execute an average of 628,930 times a second during our test, the direct approach managed to run an additional 204,403 times, unfortunately. Unfortunately, because there are many examples of code written using the multiple layer direct variable access, and it's usually horrible. It is, however, minusculely faster. The question remains whether the minute gain is actually worth the eyestrain, or the loss of maintainability. 🤔
🌸 Search and replace or tr
If we have a string which needs to be modified, while a regex will almost always be much more flexible, tr — an oft underused tool — can still be useful. One scenario might be to replace all vowels with another character.
The regex solution might look like this:
$str =~ s/[aeiou]/x/gThe tr alternative might look like this:
$str =~ tr/aeiou/xxxxx/We can put that into a test file which we can run to check which approach is the fastest, using a global $STR variable to assign to the my $str variable so as to avoid perl trying to optimize any of the work away by noticing it's assigned only the once. 😌
# regex-transliterate
#!/usr/bin/perl
use v5.36;
use Benchmark;
my $STR = "$$-this and that";
timethese(1000000, {
'sr' => sub { my $str = $STR; $str =~ s/[aeiou]/x/g; return $str; },
'tr' => sub { my $str = $STR; $str =~ tr/aeiou/xxxxx/; return $str; },
});Running the code gives us our results:
$> perl regex-transliterate
Benchmark: timing 1000000 iterations of sr, tr...
sr: 2 wallclock secs ( 1.19 usr + 0.00 sys = 1.19 CPU) @ 840336.13/s (n=1000000)
tr: 0 wallclock secs ( 0.49 usr + 0.00 sys = 0.49 CPU) @ 2040816.33/s (n=1000000)The tr version is a clear winner 🏆. One solution is flexible, the other is fast — and it's appropriately the programmer's choice which to use. 💁♀️
Check the Benchmark docs for further useful techniques. 📖
🦋 PROFILING TOOLS 🦋
A slightly larger piece of code will provide something on which a profiler can produce more extensive reporting statistics. This example uses the simplistic wordmatch program which parses a given input file and spews out a short report on the contents. 🗂️
# wordmatch
#!/usr/bin/perl
use v5.36;
=head1 NAME
filewords - word analysis of input file
=head1 SYNOPSIS
filewords -f inputfilename [-d]
=head1 DESCRIPTION
This program parses the given filename, specified with C<-f>, and
displays a simple analysis of the words found therein. Use the C<-d>
switch to enable debugging messages.
=cut
use FileHandle;
use Getopt::Long;
my $debug = 0;
my $file = '';
my $result = GetOptions (
'debug' => \$debug,
'file=s' => \$file,
);
die("invalid args") unless $result; unless ( -f $file ) {
die("Usage: $0 -f filename [-d]");
}
my $FH = FileHandle->new("< $file")
or die("unable to open file($file): $!");
my $i_LINES = 0;
my $i_WORDS = 0;
my %count = ();
my @lines = <$FH>;
foreach my $line ( @lines ) {
$i_LINES++;
$line =~ s/\n//;
my @words = split(/ +/, $line);
my $i_words = scalar(@words);
$i_WORDS = $i_WORDS + $i_words;
debug("line: $i_LINES supplying $i_words words: @words");
my $i_word = 0;
foreach my $word ( @words ) {
$i_word++;
$count{$i_LINES}{spec} += matches($i_word, $word,
'[^a-zA-Z0-9]');
$count{$i_LINES}{only} += matches($i_word, $word,
'^[^a-zA-Z0-9]+$');
$count{$i_LINES}{cons} += matches($i_word, $word,
'^[(?i:bcdfghjklmnpqrstvwxyz)]+$');
$count{$i_LINES}{vows} += matches($i_word, $word,
'^[(?i:aeiou)]+$');
$count{$i_LINES}{caps} += matches($i_word, $word,
'^[(A-Z)]+$');
}
}
print report( %count );
sub matches {
my $i_wd = shift;
my $word = shift;
my $regex = shift;
my $has = 0;
if ( $word =~ /($regex)/ ) {
$has++ if $1;
}
debug( "word: $i_wd "
. ($has ? 'matches' : 'does not match')
. " chars: /$regex/");
return $has;
}
sub report {
my %report = @_;
my %rep;
foreach my $line ( keys %report ) {
foreach my $key ( keys $report{$line}->%* ) {
$rep{$key} += $report{$line}{$key};
}
}
my $report = qq|
$0 report for $file:
lines in file: $i_LINES
words in file: $i_WORDS
words with special (non-word) characters: $i_spec
words with only special (non-word) characters: $i_only
words with only consonants: $i_cons
words with only capital letters: $i_caps
words with only vowels: $i_vows
|;
return $report;
}
sub debug {
my $message = shift;
if ( $debug ) {
print STDERR "DBG: $message\n";
}
}
exit 0;🕰️ Devel::DProf
Okay so this one is venerable — like, it held the title of de-facto standard for Perl code profiling for more than a decade. But bestie, it's been replaced by a bunch of other modules that brought us back into the 21st century ✨. The page says you're recommended to go evaluate your tool from the several mentioned here and from the CPAN list at the base of this document — and it notes that currently Devel::NYTProf seems to be the weapon of choice 👑 (see below, okay?). But first, we're taking a quick look at the output from Devel::DProf, just to set a baseline for Perl profiling tools. Run the program above under the control of Devel::DProf by using the -d switch on the command-line 🔥.
$> perl -d:DProf wordmatch -f perl5db.pl
<...multiple lines snipped...>
wordmatch report for perl5db.pl:
lines in file: 9428
words in file: 50243
words with special (non-word) characters: 20480
words with only special (non-word) characters: 7790
words with only consonants: 4801
words with only capital letters: 1316
words with only vowels: 1701So Devel::DProf makes a special file, called tmon.out by default, and that file gets read by the dprofpp program, which is already installed as part of the Devel::DProf distribution 🎀. If you call dprofpp with no options, it reads the tmon.out file in the current directory and produces a human readable statistics report of the run of your program. Heads up though: this may take a little time ⏳.
$> dprofpp
Total Elapsed Time = 2.951677 Seconds
User+System Time = 2.871677 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
102. 2.945 3.003 251215 0.0000 0.0000 main::matches
2.40 0.069 0.069 260643 0.0000 0.0000 main::debug
1.74 0.050 0.050 1 0.0500 0.0500 main::report
1.04 0.030 0.049 4 0.0075 0.0123 main::BEGIN
0.35 0.010 0.010 3 0.0033 0.0033 Exporter::as_heavy
0.35 0.010 0.010 7 0.0014 0.0014 IO::File::BEGIN
0.00 - -0.000 1 - - Getopt::Long::FindOption
0.00 - -0.000 1 - - Symbol::BEGIN
0.00 - -0.000 1 - - Fcntl::BEGIN
0.00 - -0.000 1 - - Fcntl::bootstrap
0.00 - -0.000 1 - - warnings::BEGIN
0.00 - -0.000 1 - - IO::bootstrap
0.00 - -0.000 1 - - Getopt::Long::ConfigDefaults
0.00 - -0.000 1 - - Getopt::Long::Configure
0.00 - -0.000 1 - - Symbol::gensymSo dprofpp will produce some quite detailed reporting on the activity of the wordmatch program 🦋. The wallclock, user and system, times are at the top of the analysis, and after this are the main columns defining which define the report. Check the dprofpp docs for details of the many options it supports 📖.
Also peep Apache::DProf, which hooks Devel::DProf into mod_perl 💜.
🌸 Devel::Profiler
Now let's take a look at the same program using a different profiler: Devel::Profiler, a drop-in Perl-only replacement for Devel::DProf ✨. The usage is very slightly different — instead of using the special -d: flag, you pull Devel::Profiler in directly as a module using -M 🫶.
$> perl -MDevel::Profiler wordmatch -f perl5db.pl
<...multiple lines snipped...>
wordmatch report for perl5db.pl:
lines in file: 9428
words in file: 50243
words with special (non-word) characters: 20480
words with only special (non-word) characters: 7790
words with only consonants: 4801
words with only capital letters: 1316
words with only vowels: 1701Devel::Profiler generates a tmon.out file which is compatible with the dprofpp program, which saves you from having to construct a dedicated statistics reader program 😌. So dprofpp usage is therefore identical to the above example.
$> dprofpp
Total Elapsed Time = 20.984 Seconds
User+System Time = 19.981 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
49.0 9.792 14.509 251215 0.0000 0.0001 main::matches
24.4 4.887 4.887 260643 0.0000 0.0000 main::debug
0.25 0.049 0.049 1 0.0490 0.0490 main::report
0.00 0.000 0.000 1 0.0000 0.0000 Getopt::Long::GetOptions
0.00 0.000 0.000 2 0.0000 0.0000 Getopt::Long::ParseOptionSpec
0.00 0.000 0.000 1 0.0000 0.0000 Getopt::Long::FindOption
0.00 0.000 0.000 1 0.0000 0.0000 IO::File::new
0.00 0.000 0.000 1 0.0000 0.0000 IO::Handle::new
0.00 0.000 0.000 1 0.0000 0.0000 Symbol::gensym
0.00 0.000 0.000 1 0.0000 0.0000 IO::File::openInteresting, right?? 👀 We get slightly different results, which is mostly because the algorithm which generates the report is different, even though the output file format was allegedly identical 💀. The elapsed, user and system times are clearly showing the time it took for Devel::Profiler to execute its own run, but the column listings feel more accurate somehow than the ones we had earlier from Devel::DProf. The 102% figure has disappeared, for example ✨. This is where we have to use the tools at our disposal, and recognise their pros and cons, before using them. Interestingly, the numbers of calls for each subroutine are identical in the two reports — it's the percentages which differ 🤯. As the author of Devel::Profiler writes:
...running HTML::Template's test suite under Devel::DProf shows output() taking NO time but Devel::Profiler shows around 10% of the time is in output(). I don't know which to trust but my gut tells me something is wrong with Devel::DProf. HTML::Template::output() is a big routine that's called for every test. Either way, something needs fixing.
YMMV 🫠.
Also check out Devel::Apache::Profiler, which hooks Devel::Profiler into mod_perl 🌈.
🎀 Devel::SmallProf
The Devel::SmallProf profiler examines the runtime of your Perl program and produces a line-by-line listing to show how many times each line was called, and how long each line took to execute 🔍. You call it by supplying the familiar -d flag to Perl at runtime.
$> perl -d:SmallProf wordmatch -f perl5db.pl
<...multiple lines snipped...>
wordmatch report for perl5db.pl:
lines in file: 9428
words in file: 50243
words with special (non-word) characters: 20480
words with only special (non-word) characters: 7790
words with only consonants: 4801
words with only capital letters: 1316
words with only vowels: 1701Devel::SmallProf writes its output into a file called smallprof.out, by default 🍓. The format of the file looks like this:
<num> <time> <ctime> <line>:<text>Once the program has terminated, you can examine and sort the output using any standard text filtering utilities 🧚. Something like the following may be sufficient:
$> cat smallprof.out | grep \d*: | sort -k3 | tac | head -n20
251215 1.65674 7.68000 75: if ( $word =~ /($regex)/ ) {
251215 0.03264 4.40000 79: debug("word: $i_wd ".($has ? 'matches' :
251215 0.02693 4.10000 81: return $has;
260643 0.02841 4.07000 128: if ( $debug ) {
260643 0.02601 4.04000 126: my $message = shift;
251215 0.02641 3.91000 73: my $has = 0;
251215 0.03311 3.71000 70: my $i_wd = shift;
251215 0.02699 3.69000 72: my $regex = shift;
251215 0.02766 3.68000 71: my $word = shift;
50243 0.59726 1.00000 59: $count{$i_LINES}{cons} =
50243 0.48175 0.92000 61: $count{$i_LINES}{spec} =
50243 0.00644 0.89000 56: my $i_cons = matches($i_word, $word,
50243 0.48837 0.88000 63: $count{$i_LINES}{caps} =
50243 0.00516 0.88000 58: my $i_caps = matches($i_word, $word, '^[(A-
50243 0.00631 0.81000 54: my $i_spec = matches($i_word, $word, '[^a-
50243 0.00496 0.80000 57: my $i_vows = matches($i_word, $word,
50243 0.00688 0.80000 53: $i_word++;
50243 0.48469 0.79000 62: $count{$i_LINES}{only} =
50243 0.48928 0.77000 60: $count{$i_LINES}{vows} =
50243 0.00683 0.75000 55: my $i_only = matches($i_word, $word, '^[^a-Like, the second you look at these subroutine profilers you notice they're staring at something slightly different — and suddenly you can clock exactly which line of code is hogging all the time. That regex line? kiiinda sus ngl 👀. And bestie, remember: these tools are meant to be used together. There is genuinely no single best way to profile your code — you just grab the best tool for the job. Periodt.
Also go peek at Apache::SmallProf, which hooks Devel::SmallProf into mod_perl. 💅
🌸 Devel::FastProf 🌸
Devel::FastProf is yet another Perl line profiler, and it was written specifically to be a faster line profiler than what's possible with stuff like Devel::SmallProf — because it's written in C. 😤 To use Devel::FastProf, you hand Perl the -d argument:
$> perl -d:FastProf wordmatch -f perl5db.pl
<...multiple lines snipped...>
wordmatch report for perl5db.pl:
lines in file: 9428
words in file: 50243
words with special (non-word) characters: 20480
words with only special (non-word) characters: 7790
words with only consonants: 4801
words with only capital letters: 1316
words with only vowels: 1701Devel::FastProf writes its statistics into the file fastprof.out in the current directory. That output file — which you can specify — gets interpreted with the fprofpp command-line program.
$> fprofpp | head -n20
# fprofpp output format is:
# filename:line time count: source
wordmatch:75 3.93338 251215: if ( $word =~ /($regex)/ ) {
wordmatch:79 1.77774 251215: debug("word: $i_wd ".($has ? 'matches' : 'does not match')." chars: /$regex/");
wordmatch:81 1.47604 251215: return $has;
wordmatch:126 1.43441 260643: my $message = shift;
wordmatch:128 1.42156 260643: if ( $debug ) {
wordmatch:70 1.36824 251215: my $i_wd = shift;
wordmatch:71 1.36739 251215: my $word = shift;
wordmatch:72 1.35939 251215: my $regex = shift;And straightaway we can see that the number of times each line got called is identical to the Devel::SmallProf output, and the ordering is only very slightly different — it's based on how much time each line took to execute. Take if ( $debug ) { and my $message = shift;, for example. Those disagreements in the actual times recorded might come from the algorithm used internally, or it could just be system resource limitations or contention. 🤷♀️
Also check out the DBIx::Profile, which will profile database queries running under the DBIx::* namespace. ✨
👑 Devel::NYTProf 👑
Devel::NYTProf is the next generation of Perl code profiler, bestie — it fixes so many shortcomings in the other tools and implements a whole pile of cool features. First of all, it can be used as either a line profiler, a block profiler, or a subroutine profiler, all at once. 🤯 It can also use sub-microsecond (100ns) resolution on systems which provide clock_gettime(). It can be started and stopped even by the program being profiled. It's a one-line entry to profile mod_perl applications. It's written in c and it's probably the fastest profiler available for Perl. The list of coolness just keeps going. Anyway, enough of that — let's see how it works: just use the familiar -d switch to plug it in and run the code.
$> perl -d:NYTProf wordmatch -f perl5db.pl
wordmatch report for perl5db.pl:
lines in file: 9427
words in file: 50243
words with special (non-word) characters: 20480
words with only special (non-word) characters: 7790
words with only consonants: 4801
words with only capital letters: 1316
words with only vowels: 1701NYTProf will generate a report database into the file nytprof.out by default. From there you can generate human readable reports using the supplied nytprofhtml (HTML output) and nytprofcsv (CSV output) programs. We've used the Unix system html2text utility to convert the nytprof/index.html file, just for convenience here.
$> html2text nytprof/index.html
Performance Profile Index
For wordmatch
Run on Fri Sep 26 13:46:39 2008
Reported on Fri Sep 26 13:47:23 2008
Top 15 Subroutines -- ordered by exclusive time
|Calls |P |F |Inclusive|Exclusive|Subroutine |
| | | |Time |Time | |
|251215|5 |1 |13.09263 |10.47692 |main:: |matches |
|260642|2 |1 |2.71199 |2.71199 |main:: |debug |
|1 |1 |1 |0.21404 |0.21404 |main:: |report |
|2 |2 |2 |0.00511 |0.00511 |XSLoader:: |load (xsub) |
|14 |14|7 |0.00304 |0.00298 |Exporter:: |import |
|3 |1 |1 |0.00265 |0.00254 |Exporter:: |as_heavy |
|10 |10|4 |0.00140 |0.00140 |vars:: |import |
|13 |13|1 |0.00129 |0.00109 |constant:: |import |
|1 |1 |1 |0.00360 |0.00096 |FileHandle:: |import |
|3 |3 |3 |0.00086 |0.00074 |warnings::register::|import |
|9 |3 |1 |0.00036 |0.00036 |strict:: |bits |
|13 |13|13|0.00032 |0.00029 |strict:: |import |
|2 |2 |2 |0.00020 |0.00020 |warnings:: |import |
|2 |1 |1 |0.00020 |0.00020 |Getopt::Long:: |ParseOptionSpec|
|7 |7 |6 |0.00043 |0.00020 |strict:: |unimport |
For more information see the full list of 189 subroutines.That first chunk of the report already hands you the critical info about which subroutines are burning the most time. The next bit gives you some statistics about the source files that got profiled.
Source Code Files -- ordered by exclusive time then name
|Stmts |Exclusive|Avg. |Reports |Source File |
| |Time | | | |
|2699761|15.66654 |6e-06 |line . block . sub|wordmatch |
|35 |0.02187 |0.00062|line . block . sub|IO/Handle.pm |
|274 |0.01525 |0.00006|line . block . sub|Getopt/Long.pm |
|20 |0.00585 |0.00029|line . block . sub|Fcntl.pm |
|128 |0.00340 |0.00003|line . block . sub|Exporter/Heavy.pm |
|42 |0.00332 |0.00008|line . block . sub|IO/File.pm |
|261 |0.00308 |0.00001|line . block . sub|Exporter.pm |
|323 |0.00248 |8e-06 |line . block . sub|constant.pm |
|12 |0.00246 |0.00021|line . block . sub|File/Spec/Unix.pm |
|191 |0.00240 |0.00001|line . block . sub|vars.pm |
|77 |0.00201 |0.00003|line . block . sub|FileHandle.pm |
|12 |0.00198 |0.00016|line . block . sub|Carp.pm |
|14 |0.00175 |0.00013|line . block . sub|Symbol.pm |
|15 |0.00130 |0.00009|line . block . sub|IO.pm |
|22 |0.00120 |0.00005|line . block . sub|IO/Seekable.pm |
|198 |0.00085 |4e-06 |line . block . sub|warnings/register.pm|
|114 |0.00080 |7e-06 |line . block . sub|strict.pm |
|47 |0.00068 |0.00001|line . block . sub|warnings.pm |
|27 |0.00054 |0.00002|line . block . sub|overload.pm |
|9 |0.00047 |0.00005|line . block . sub|SelectSaver.pm |
|13 |0.00045 |0.00003|line . block . sub|File/Spec.pm |
|2701595|15.73869 | |Total |
|128647 |0.74946 | |Average |
| |0.00201 |0.00003|Median |
| |0.00121 |0.00003|Deviation |
Report produced by the NYTProf 2.03 Perl profiler, developed by Tim Bunce and
Adam Kaplan.At this point, if you're using the HTML report, you can click through all the various links to bore down into each subroutine and each line of code. But since we're doing text reporting here, and there's a whole directory full of reports built for each source file, we'll just show you a part of the corresponding wordmatch-line.html file — enough to give you an idea of the sort of output you can expect from this cool tool. 🫶
$> html2text nytprof/wordmatch-line.html
Performance Profile -- -block view-.-line view-.-sub view-
For wordmatch
Run on Fri Sep 26 13:46:39 2008
Reported on Fri Sep 26 13:47:22 2008
File wordmatch
Subroutines -- ordered by exclusive time
|Calls |P|F|Inclusive|Exclusive|Subroutine |
| | | |Time |Time | |
|251215|5|1|13.09263 |10.47692 |main::|matches|
|260642|2|1|2.71199 |2.71199 |main::|debug |
|1 |1|1|0.21404 |0.21404 |main::|report |
|0 |0|0|0 |0 |main::|BEGIN ||Line|Stmts.|Exclusive|Avg. |Code |
| | |Time | | |
|1 | | | |#!/usr/bin/perl |
|2 | | | | |
| | | | |use strict; |
|3 |3 |0.00086 |0.00029|# spent 0.00003s making 1 calls to strict:: |
| | | | |import |
| | | | |use warnings; |
|4 |3 |0.01563 |0.00521|# spent 0.00012s making 1 calls to warnings:: |
| | | | |import |
|5 | | | | |
|6 | | | |=head1 NAME |
|7 | | | | |
|8 | | | |filewords - word analysis of input file |
<...snip...>
|62 |1 |0.00445 |0.00445|print report( %count ); |
| | | | |# spent 0.21404s making 1 calls to main::report|
|63 | | | | |
| | | | |# spent 23.56955s (10.47692+2.61571) within |
| | | | |main::matches which was called 251215 times, |
| | | | |avg 0.00005s/call: # 50243 times |
| | | | |(2.12134+0.51939s) at line 57 of wordmatch, avg|
| | | | |0.00005s/call # 50243 times (2.17735+0.54550s) |
|64 | | | |at line 56 of wordmatch, avg 0.00005s/call # |
| | | | |50243 times (2.10992+0.51797s) at line 58 of |
| | | | |wordmatch, avg 0.00005s/call # 50243 times |
| | | | |(2.12696+0.51598s) at line 55 of wordmatch, avg|
| | | | |0.00005s/call # 50243 times (1.94134+0.51687s) |
| | | | |at line 54 of wordmatch, avg 0.00005s/call |
| | | | |sub matches { |
<...snip...>
|102 | | | | |
| | | | |# spent 2.71199s within main::debug which was |
| | | | |called 260642 times, avg 0.00001s/call: # |
| | | | |251215 times (2.61571+0s) by main::matches at |
|103 | | | |line 74 of wordmatch, avg 0.00001s/call # 9427 |
| | | | |times (0.09628+0s) at line 50 of wordmatch, avg|
| | | | |0.00001s/call |
| | | | |sub debug { |
|104 |260642|0.58496 |2e-06 |my $message = shift; |
|105 | | | | |
|106 |260642|1.09917 |4e-06 |if ( $debug ) { |
|107 | | | |print STDERR "DBG: $message\n"; |
|108 | | | |} |
|109 | | | |} |
|110 | | | | |
|111 |1 |0.01501 |0.01501|exit 0; |
|112 | | | | |okay and the oodles of genuinely useful info crammed in there?? 😭 bestie that is not a snack, that is a whole meal. this is the way forward, no cap, fr fr 💅✨
Also peep Devel::NYTProf::Apache — it's the one that hooks Devel::NYTProf into mod_perl. 🧚
and we are so not done yet, keep scrolling bestie 🫶
💅 SORTING 💅
okay bestie, so Perl modules are not the only tools in a performance analyst's bag, and system tools like time should NOT be slept on. the next example is literally us taking a quick peek at sorting. like, there are entire books, theses and articles written about efficient sorting algorithms — that is not what we're doing here, no cap, there's a bunch of good sorting modules you should also check out: Sort::Maker, Sort::Key are the two that spring to mind. but it's still possible to make some observations about certain Perl-specific interpretations of sorting data sets, and drop an example or two about how sorting huge data volumes can affect performance. 💖
first thing, and it's the one everybody overlooks when sorting big amounts of data: you can often reduce the data set you're dealing with first, and in loads of cases grep() can be a super useful simple filter:
@data = sort grep { /$filter/ } @incominga command like this can vastly reduce the volume of material you actually have to sort through in the first place, and you should not be too quick to dismiss it just because it's simple. the "KISS" principle is overlooked way too often — the next example uses the simple system time utility to demonstrate. let's look at an actual example of sorting the contents of a large file, an apache logfile will do. this one has over a quarter of a million lines, it's 50M in size, and a snippet of it looks like this:
# logfile
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)"
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)"
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"
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"
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"
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)"
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)"
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)"
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)"
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)"
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"
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"
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"
crawl1.cosmixcorp.com - - [08/Feb/2007:13:27:57 +0000] "GET /robots.txt HTTP/1.0" 200 179 "-" "voyager/1.0"
crawl1.cosmixcorp.com - - [08/Feb/2007:13:28:25 +0000] "GET /links.html HTTP/1.0" 200 3413 "-" "voyager/1.0"
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)"
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)"
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)"
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)"
pop.compuscan.co.za - - [08/Feb/2007:14:10:43 +0000] "GET / HTTP/1.1" 200 3309 "-" "www.clamav.net"
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)"
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)"
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"
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"so the specific task here is to sort the 286,525 lines of this file by Response Code, Query, Browser, Referring Url, and lastly Date. one solution might be to use the following code, which iterates over the files given on the command-line. ✨
# sort-apache-log
#!/usr/bin/perl -n
use v5.36;
my @data;
LINE:
while ( <> ) {
my $line = $_;
if (
$line =~ m/^(
([\w\.\-]+) # client
\s*-\s*-\s*\[
([^]]+) # date
\]\s*"\w+\s*
(\S+) # query
[^"]+"\s*
(\d+) # status
\s+\S+\s+"[^"]*"\s+"
([^"]*) # browser
"
.*
)$/x
) {
my @chunks = split(/ +/, $line);
my $ip = $1;
my $date = $2;
my $query = $3;
my $status = $4;
my $browser = $5;
push(@data, [$ip, $date, $query, $status, $browser, $line]);
}
}
my @sorted = sort {
$a->[3] cmp $b->[3]
||
$a->[2] cmp $b->[2]
||
$a->[0] cmp $b->[0]
||
$a->[1] cmp $b->[1]
||
$a->[4] cmp $b->[4]
} @data;
foreach my $data ( @sorted ) {
print $data->[5];
}
exit 0;when you run this program, redirect STDOUT so you can actually check the output is correct on following test runs, and use the system time utility to check the overall runtime. 🕐
$> time ./sort-apache-log logfile > out-sort
real 0m17.371s
user 0m15.757s
sys 0m0.592sthe program took just over 17 wallclock seconds to run. now note the different values time outputs — it's important to always use the same one, and to not confuse what each one means, bestie. 🙈
- Elapsed Real Time — the overall, or wallclock, time between when
timewas called and when it terminates. the elapsed time includes both user and system times, and time spent waiting for other users and processes on the system. inevitably, this is the most approximate of the measurements given. - User CPU Time — the user time is the amount of time the entire process spent on behalf of the user on this system executing this program.
- System CPU Time — the system time is the amount of time the kernel itself spent executing routines, or system calls, on behalf of this process user.
running this same process as a Schwarzian Transform it is possible to eliminate the input and output arrays for storing all the data, and work on the input directly as it arrives too. otherwise, the code looks fairly similar:
# sort-apache-log-schwarzian
#!/usr/bin/perl -n
use v5.36;
print
map $_->[0] =>
sort {
$a->[4] cmp $b->[4]
||
$a->[3] cmp $b->[3]
||
$a->[1] cmp $b->[1]
||
$a->[2] cmp $b->[2]
||
$a->[5] cmp $b->[5]
}
map [ $_, m/^(
([\w\.\-]+) # client
\s*-\s*-\s*\[
([^]]+) # date
\]\s*"\w+\s*
(\S+) # query
[^"]+"\s*
(\d+) # status
\s+\S+\s+"[^"]*"\s+"
([^"]*) # browser
"
.*
)$/xo ]
=> <>;
exit 0;run the new code against the same logfile, as above, to check the new time. ⏱️
$> time ./sort-apache-log-schwarzian logfile > out-schwarz
real 0m9.664s
user 0m8.873s
sys 0m0.704sthe time has been cut in half, which is a respectable speed improvement by any standard, slay. 💅 naturally, it's important to check the output is consistent with the first program run, and this is where the Unix system cksum utility comes in. 🫶
$> cksum out-sort out-schwarz
3044173777 52029194 out-sort
3044173777 52029194 out-schwarzBTW. beware too of pressure from managers who see you speed a program up by 50% of the runtime once, only to hit you with a request one month later to do the same again (true story) — you'll just have to point out you're only human, even if you are a Perl programmer, and you'll see what you can do... 😭
💅 LOGGING 💅
okay bestie so the tea here is that good error handling with actually-informative messages is a whole essential part of any decent dev process, right? but there's this one school of thought floating around that says log files should be all chatty, like the endless stream of output is somehow keeping the program alive 🫶. and like — if speed matters at all to you, that take is just wrong, no cap.
so the classic cursed sight is code that looks like this:
logger->debug( "A logging message via process-id: $$ INC: "
. Dumper(\%INC) )the problem, bestie? 😭 this thing gets parsed and executed EVERY time, even when the debug level in your logging config file is literally zero. like yeah, once you're inside debug() and it peeks at the internal $debug variable and confirms it's zero, the message you handed over gets discarded and the program just carries on. but by then?? the \%INC hash has already been dumped, the message string has already been constructed — all that work, just to throw it away. 💀
you can dodge the whole thing with a statement-level debug variable, like this:
logger->debug( "A logging message via process-id: $$ INC: "
. Dumper(\%INC) ) if $DEBUG;want proof? set up a test script with both forms, plus a debug() subroutine to emulate your typical logger() functionality. boom:
# ifdebug
#!/usr/bin/perl
use v5.36;
use Benchmark;
use Data::Dumper;
my $DEBUG = 0;
sub debug {
my $msg = shift;
if ( $DEBUG ) {
print "DEBUG: $msg\n";
}
};
timethese(100000, {
'debug' => sub {
debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) )
},
'ifdebug' => sub {
debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) ) if $DEBUG
},
});so let's see what Benchmark makes of this, shall we 👀
$> perl ifdebug
Benchmark: timing 100000 iterations of constant, sub...
ifdebug: 0 wallclock secs ( 0.01 usr + 0.00 sys = 0.01 CPU) @ 10000000.00/s (n=100000)
(warning: too few iterations for a reliable count)
debug: 14 wallclock secs (13.18 usr + 0.04 sys = 13.22 CPU) @ 7564.30/s (n=100000)notice how one case does literally the exact same thing as far as outputting debugging info goes — which is nothing, bestie, absolutely nothing — and it takes 14 seconds?? while the other one takes one hundredth of a second. it's giving definitive, honestly. 🔥
the takeaway: use a $DEBUG variable BEFORE you call the subroutine, instead of relying on the smart functionality inside it. periodt.
Logging if DEBUG (constant) ✨
so you can take that whole idea one step further by using a compile-time DEBUG constant. iconic behaviour:
# ifdebug-constant
#!/usr/bin/perl
use v5.36;
use Benchmark;
use Data::Dumper;
use constant
DEBUG => 0
;
sub debug {
if ( DEBUG ) {
my $msg = shift;
print "DEBUG: $msg\n";
}
};
timethese(100000, {
'debug' => sub {
debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) )
},
'constant' => sub {
debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) ) if DEBUG
},
});running this produces:
$> perl ifdebug-constant
Benchmark: timing 100000 iterations of constant, sub...
constant: 0 wallclock secs (-0.00 usr + 0.00 sys = -0.00 CPU) @ -7205759403792793600000.00/s (n=100000)
(warning: too few iterations for a reliable count)
sub: 14 wallclock secs (13.09 usr + 0.00 sys = 13.09 CPU) @ 7639.42/s (n=100000)the DEBUG constant wipes the floor with even the $debug variable, clocking in at minus zero seconds 😭 and it throws in a warning: too few iterations for a reliable count message as a lil bonus.
so like… why did we get too few iterations when we literally asked for 100000?? to see what's really going on, we hit up the genuinely very useful B::Deparse and inspect the new code:
$> perl -MO=Deparse ifdebug-constant
use Benchmark;
use Data::Dumper;
use constant ('DEBUG', 0);
sub debug {
use warnings;
use strict 'refs';
0;
}
use warnings;
use strict 'refs';
timethese(100000, {'sub', sub {
debug "A $0 logging message via process-id: $$" . Dumper(\%INC);
}
, 'constant', sub {
0;
}
});
ifdebug-constant syntax OKand there it is, bestie — the output shows the constant() subroutine we're testing getting straight-up replaced with the value of the DEBUG constant: zero. the line we're testing has been completely optimized away. you literally cannot get more efficient than that. slay. 👑
🌈 POSTSCRIPT 🌈
so this whole document has walked you through several ways to identify hot-spots and check whether your modifications actually improved the runtime of the code. 💖
and as a final thought — remember that at the time of writing, it's not possible to produce a useful program that runs in zero or negative time. and that basic principle can be written as: useful programs are slow by their very definition. like yeah, you can write a nearly instantaneous program, but it's not gonna do very much. here's a very efficient one:
$> perl -e 0optimizing that any further is a job for p5p. 🫡
👑 SEE ALSO 👑
more reading lives in the modules and links below, bestie.
PERLDOCS 📚
for example: perldoc -f sort.
perlfaq4.
perlfork, perlfunc, perlretut, perlthrtut.
threads.
MAN PAGES 🎀
time.
MODULES 🧚
obviously we can't individually showcase all the performance-related code for Perl here, that would be unhinged, but here's a short list of modules from the CPAN that deserve further attention:
Apache::DProf
Apache::SmallProf
Benchmark
DBIx::Profile
Devel::AutoProfiler
Devel::DProf
Devel::DProfLB
Devel::FastProf
Devel::GraphVizProf
Devel::NYTProf
Devel::NYTProf::Apache
Devel::Profiler
Devel::Profile
Devel::Profit
Devel::SmallProf
Devel::WxProf
POE::Devel::Profiler
Sort::Key
Sort::MakerURLS 🌸
very useful online reference material:
https://web.archive.org/web/20120515021937/http://www.ccl4.org/~nick/P/Fast_Enough/
https://web.archive.org/web/20050706081718/http://www-106.ibm.com/developerworks/library/l-optperl.html
https://perlbuzz.com/2007/11/14/bind_output_variables_in_dbi_for_speed_and_safety/
http://en.wikipedia.org/wiki/Performance_analysis
http://apache.perl.org/docs/1.0/guide/performance.html
http://perlgolf.sourceforge.net/
http://www.sysarch.com/Perl/sort_paper.html💜 AUTHOR 💜
Richard Foley <richard.foley@rfi.net> Copyright (c) 2008
and that's the whole page, babes ✨ this lil manual was brought to you by perl v5.44.0, dated 2026-10-17, filed under PERLPERF(1perl) — go forth and profile responsibly, bestie 💅🦋🍓
📦 where this page comes from
- arch rolling: perl 5.44.0-1 · Artistic-1.0-Perl AND GPL-1.0-or-later
- 💖 girlified by deepseek-ai/DeepSeek-V4.1-Flash on : a language model's rewrite of the original, under its terms