Code Profiling Techniques

The profiling process helps you to determine which subroutines or just snippets of code take the longest time to execute and which subroutines are called most often. Probably you will want to optimize those.

When do you need to profile your code? You do that when you suspect that some part of your code is called very often and may be there is a need to optimize it to significantly improve the overall performance.

For example if you have ever used the diagnostics pragma, which extends the terse diagnostics normally emitted by both the Perl compiler and the Perl interpreter, augmenting them with the more verbose and endearing descriptions found in the perldiag manpage. You know that it might tremendously slow you code down, so let's first prove that it is correct.

We will run a benchmark, once with diagnostics enabled and once disabled, on a subroutine called test_code.

The code inside the subroutine does an arithmetic and a numeric comparison of two strings. It assigns one string to another if the condition tests true but the condition always tests false. To demonstrate the diagnostics overhead the comparison operator is intentionally wrong. It should be a string comparison, not a numeric one.

  use Benchmark;
  use diagnostics;
  use strict;

  my  = 50000;

  disable diagnostics;
  my  = timeit(,\&test_code);

  enable  diagnostics;
  my  = timeit(,\&test_code);

  print "Off: ",timestr(),"\n";
  print "On : ",timestr(),"\n";

  sub test_code{
    my (,) = qw(foo bar);
    my ;

    if ( == ) {
       = ;
    }
  }

For only a few lines of code we get:

  Off:  1 wallclock secs ( 0.81 usr +  0.00 sys =  0.81 CPU)
  On : 13 wallclock secs (12.54 usr +  0.01 sys = 12.55 CPU)

With diagnostics enabled, the subroutine test_code() is 16 times slower, than with diagnostics disabled!

Now let's fix the comparison the way it should be, by replacing == with eq, so we get:

    my (,) = qw(foo bar);
    my ;
    if ( eq ) {
       = ;
    }

and run the same benchmark again:

  Off:  1 wallclock secs ( 0.57 usr +  0.00 sys =  0.57 CPU)
  On :  1 wallclock secs ( 0.56 usr +  0.00 sys =  0.56 CPU)

Now there is no overhead at all. The diagnostics pragma slows things down only when warnings are generated.

After we have verified that using the diagnostics pragma might add a big overhead to execution runtime, let's use the code profiling to understand why this happens. We are going to use Devel::DProf to profile the code. Let's use this code:

  diagnostics.pl
  --------------
  use diagnostics;
  print "Content-type:text/html\n\n";
  test_code();
  sub test_code{
    my (,) = qw(foo bar);
    my ;
    if ( == ) {
       = ;
    }
  }