You can watch your code as it's being compiled and executed by Perl via the -D runtime option. Perl will generate different output according to the extra options (letters or numbers) specified after -D. You can supply one or more options at the same time. Here are the available options for Perl Version 5.6.0 (reproduced from the perlrun manpage):

1  p  Tokenizing and parsing
2  s  Stack snapshots
4  l  Context (loop) stack processing
8  t  Trace execution
     16  o  Method and overloading resolution
     32  c  String/numeric conversions
     64  P  Print preprocessor command for -P
    128  m  Memory allocation
    256  f  Format processing
    512  r  Regular expression parsing and execution
   1024  x  Syntax tree dump
   2048  u  Tainting checks
   4096  L  Memory leaks (needs -DLEAKTEST when compiling Perl)
   8192  H  Hash dump -- usurps values( )
  16384  X  Scratchpad allocation
  32768  D  Cleaning up
  65536  S  Thread synchronization

Let's look at some of these options. Consider this one-line example:

panic% perl -le '$_="yafoo"; s/foo/bar/; print'

which simply substitutes the string "foo" with the string "bar" in the variable $_ and prints out its value. Now let's see how Perl compiles and executes the regular expression substitution part of the code. We will use Perl's -Dr (or -D512) option:

panic% perl -Dr -le '$_="yafoo"; s/foo/bar/; print'
Compiling REx 'foo'
size 3 first at 1
rarest char f at 0
   1: EXACT <foo>(3)
   3: END(0)
anchored 'foo' at 0 (checking anchored isall) minlen 3 
Omitting $` $& $' support.


Guessing start of match, REx 'foo' against 'yafoo'...
Found anchored substr 'foo' at offset 2...
Starting position does not contradict /^/m...
Guessed: match at offset 2
Matching REx 'foo' against 'foo'
  Setting an EVAL scope, savestack=3
   2 <ya> <foo>           |  1:  EXACT <foo>
   5 <yafoo> <>           |  3:  END
Match successful!
Freeing REx: 'foo'

As you can see, there are two stages: compilation and execution. During the compilation stage, Perl records the stages it should go through when matching the string, notes what length it should match for, and notes whether one of the $', $&, or $' special variables will be used.[57] During the execution we can see the actual process of matching. In our example the match was successful.

[57]You should avoid using these at all, since they add a performance hit, and once used in any regular expression they will be set in every other regular expression, even if you didn't ask for them.

The trace doesn't mention the replace segment of the s/// construct, since it's not a part of the regular expression per se.

The -Dx (or -D1024) option tells Perl to print the syntax tree dump. We'll use some very simple code so the execution tree will not be too long to be presented here:

panic% perl -Dx -le 'print 12*60*60'
6   TYPE = leave  =  ==> DONE
    REFCNT = 0
1       TYPE = enter  =  ==> 2
2       TYPE = nextstate  =  ==> 3
        FLAGS = (VOID)
        LINE = 1
        PACKAGE = "main"
5       TYPE = print  =  ==> 6
        FLAGS = (VOID,KIDS)
3           TYPE = pushmark  =  ==> 4
            FLAGS = (SCALAR)
4           TYPE = const  =  ==> 5
            FLAGS = (SCALAR)
            SV = IV(43200)

This code shows us the tree of opcodes after the compilation process. Each opcode is prefixed with a number, which then is used to determine the order of execution. You can see that each opcode is linked to some other opcode (a number following the = = => tag). If you start from the opcode numbered 1, jump to the opcode it's linked to (2, in this example), and continue this way, you will see the execution pass of the code. Since the code might have conditional branches, Perl cannot predetermine a definite order at compile time; therefore, when you follow the execution, the numbers will not necessarily be in sequence.

Of course, internally Perl uses opcode pointers in memory, not numbers. Numbers are used in the debug printout only for our convenience.

Another interesting fact that we learn from this output is that Perl optimizes everything it can at compile time. For example, when you need to know how many seconds are in 12 hours, you could calculate it manually and use the resulting number. But, as we see from:

SV = IV(43200)

Perl has already done the calculation at compile time, so no runtime overhead occurs if you say 12*60*60 and not 43200. The former is also more self-explanatory, while the latter may require an explicit comment to tell us what it is.

Now let's bundle a few other options together and see a subroutine argument stack snapshot via s, context stack processing via l, and trace execution via t all at once:

panic% perl -Dtls -le 'print 12*60*60'
(-e:1)    const(IV(12))
    =>  IV(12)  
(-e:1)    const(IV(60))
    =>  IV(12)  IV(60)  
(-e:1)    multiply
(-e:1)    const(IV(720))
    =>  IV(720)  
(-e:1)    const(IV(60))
    =>  IV(720)  IV(60)  
(-e:1)    multiply
(-e:1)    ENTER scope 2 at op.c:6501
(-e:1)    LEAVE scope 2 at op.c:6811
(-e:0)    LEAVE scope 1 at perl.c:1319
(-e:0)    ENTER scope 1 at perl.c:1327
(-e:0)    Setting up jumplevel 0xbffff8cc, was 0x40129f40

You can see how Perl pushes constants 12 and 60 onto an argument stack, executes multiply( ), gets a result of 720, pushes it back onto the stack, pushes 60 again, and executes another multiplication. The tracing and argument stack options show us this information. All this happens at compile time.

In addition, we see a number of scope entering and leaving messages, which come from the context stack status report. These options might be helpful when you want to see Perl entering and leaving block scopes (loops, subroutines, files, etc.). As you can see, bundling a few options together gives very useful reports.

Since we have been using command-line execution rather than code placed in the file, Perl uses -e as the code's filename. Line 0 doesn't exist; it's used for special purposes.

Having finished the compilation, now we proceed to the execution part:


(-e:0)    enter
(-e:0)    ENTER scope 2 at pp_hot.c:1535
Entering block 0, type BLOCK
(-e:0)    nextstate
(-e:1)    pushmark
    =>  *  
(-e:1)    const(IV(43200))
    =>  *  IV(43200)  
(-e:1)    print
    =>  SV_YES
(-e:1)    leave
Leaving block 0, type BLOCK
(-e:0)    LEAVE scope 2 at pp_hot.c:1657
(-e:0)    LEAVE scope 1 at perl.c:395

Here you can see what Perl does on each line of your source code. So basically the gist of this code (bolded in the example) is pushing the constant integer scalar (const(IV)) onto the execution stack, and then calling print( ). The SV_YESsymbol indicates that print( ) returns a scalar value. The rest of the output consists of controlling messages, where Perl changes scopes.

Of course, as the code gets more complicated, the traces will get longer and trickier to understand. But sometimes these traces can be as indispensable as interactive debugging.

You can use the -D[letter|number] techniques from within mod_perl as well by setting the PERL5OPT environment variable. For example, using the bashshell to see the compilation and execution traces, you can start the server in this way:

panic% PERL5OPT=-Dt ./httpd_perl -X

You will see a lot of output while the server starts. Once it finishes the tracing, open the error_log file and issue a request to your code. The tracing output will show up in this file.