21.4 Tracing mod_perl-Specific Perl Calls

When we are interested in mod_perl-level events, it's quite hard to use system-level tracing, both because of the system trace's verbosity and because it's hard to find the boundary between events. Therefore, we need to do mod_perl-level tracing.

To enable mod_perl debug tracing, configure mod_perl with the PERL_TRACE option:

panic% perl Makefile.PL PERL_TRACE=1 ...

The trace levels can then be enabled via the MOD_PERL_TRACE environment variable which can contain any combination of the following options.

For startup processing:

c

Trace directive handling during Apache (non-mod_perl) configuration-directive handling

d

Trace directive handling during mod_perl directive processing during configuration read

s

Trace processing of <Perl> sections

For runtime processing:

h

Trace Perl handler callbacks during the processing of incoming requests and during startup (PerlChildInitHandler)

g

Trace global variable handling, interpreter construction, END blocks, etc.

Alternatively, setting the environment variable to all will include all the options listed above.

One way of setting this variable is by adding this directive to httpd.conf:

PerlSetEnv MOD_PERL_TRACE all

For example, if you want to see a trace of the PerlRequire and PerlModule directives as they are executed, use:

PerlSetEnv MOD_PERL_TRACE d

You can also use the command-line environment, setting:

panic% setenv MOD_PERL_TRACE all
panic% ./httpd -X

If running under a Bourne-style shell, you can set the environment variable for only the duration of a single command:

panic% MOD_PERL_TRACE=all ./httpd -X

If using a different shell, you should try using the env utility, which has a similar effect:

panic% env MOD_PERL_TRACE=all ./httpd -X

For example, if you want to trace the processing of the Apache::Reload setting during startup and you want to see what happens when the following directives are processed:

PerlModule Apache::Reload
PerlInitHandler Apache::Reload
PerlSetVar ReloadAll Off
PerlSetVar ReloadModules "Apache::* Book::*"

do:

panic% setenv MOD_PERL_TRACE d
panic% ./httpd -X
PerlModule: arg='Apache::Reload'
loading perl module 'Apache::Reload'...ok
loading perl module 'Apache'...ok
loading perl module 'Tie::IxHash'...not ok

init `PerlInitHandler' stack
perl_cmd_push_handlers: @PerlInitHandler, 'Apache::Reload'
pushing `Apache::Reload' into `PerlInitHandler' handlers

perl_cmd_var: 'ReloadAll' = 'Off'

perl_cmd_var: 'ReloadModules' = 'Apache::* Book::*'

We have removed the rest of the trace and separated the output trace into four groups, each equivalent to the appropriate setting from our configuration example. So we can see that:

PerlModule Apache::Reload

loads the Apache::Reload and Apache modules but fails to load Tie::IxHash, since we don't have it installed (which is not a fatal error in the case of Apache::Reload).

The following initializes the PerlInitHandler stack, as it wasn't yet used, and pushes Apache::Reload there:

PerlInitHandler Apache::Reload

The last two directives call perl_cmd_var( ) to set the Perl variables that can be retrieved in the code with dir_config( ), as explained in Chapter 4:

PerlSetVar ReloadAll Off
PerlSetVar ReloadModules "Apache::* Book::*"

Now let's look at the trace of the handlers called during the execution of this code:

use strict;
my $r = shift;
$r->send_http_header("text/plain");
$r->print("Hello");

We set MOD_PERL_TRACE to trace handler calls with h:

panic% setenv MOD_PERL_TRACE h
panic% ./httpd -X &
panic% tail -f /home/httpd/httpd_perl/logs/error_log
running 1 server configured stacked handlers for /perl/test.pl...
calling &{PerlInitHandler->[0]} (1 total)
&{PerlInitHandler->[0]} returned status=0
`PerlInitHandler' push_handlers( ) stack is empty
PerlInitHandler handlers returned 0

running 1 server configured stacked handlers for /perl/test.pl...
calling &{PerlPostReadRequestHandler->[0]} (1 total)
&{PerlPostReadRequestHandler->[0]} returned status=0
`PerlPostReadRequestHandler' push_handlers( ) stack is empty
PerlPostReadRequestHandler handlers returned 0

`PerlTransHandler' push_handlers( ) stack is empty
PerlTransHandler handlers returned -1

`PerlInitHandler' push_handlers( ) stack is empty
PerlInitHandler handlers returned -1

`PerlHeaderParserHandler' push_handlers( ) stack is empty

`PerlAccessHandler' push_handlers( ) stack is empty
PerlAccessHandler handlers returned -1

`PerlTypeHandler' push_handlers( ) stack is empty
PerlTypeHandler handlers returned -1

running 1 server configured stacked handlers for /perl/test.pl...
calling &{PerlFixupHandler->[0]} (1 total)
registering PerlCleanupHandler
&{PerlFixupHandler->[0]} returned status=-1
`PerlFixupHandler' push_handlers( ) stack is empty
PerlFixupHandler handlers returned -1

running 1 server configured stacked handlers for /perl/test.pl...
calling &{PerlHandler->[0]} (1 total)
&{PerlHandler->[0]} returned status=0
`PerlHandler' push_handlers( ) stack is empty
PerlHandler handlers returned 0

`PerlLogHandler' push_handlers( ) stack is empty
PerlLogHandler handlers returned -1

running registered cleanup handlers...
perl_call: handler is a cached CV
`PerlCleanupHandler' push_handlers( ) stack is empty
PerlCleanupHandler handlers returned -1

You can see what handlers were registered to be executed during the processing of this simple script. In our configuration we had these relevant directives:

PerlInitHandler Apache::Reload
PerlPostReadRequestHandler  Book::ProxyRemoteAddr
PerlFixupHandler Apache::GTopLimit

And you can see that they were all called:

calling &{PerlInitHandler->[0]} (1 total)
&{PerlInitHandler->[0]} returned status=0

calling &{PerlPostReadRequestHandler->[0]} (1 total)
&{PerlPostReadRequestHandler->[0]} returned status=0

calling &{PerlFixupHandler->[0]} (1 total)
registering PerlCleanupHandler
&{PerlFixupHandler->[0]} returned status=-1

In addition, when Apache::GTopLimit was running, it registered a PerlCleanupHandler, which was executed at the end:

running registered cleanup handlers...
perl_call: handler is a cached CV

Since we were executing an Apache::Registry script, the PerlHandler was executed as well:

running 1 server configured stacked handlers for /perl/test.pl...
calling &{PerlHandler->[0]} (1 total)
&{PerlHandler->[0]} returned status=0
`PerlHandler' push_handlers( ) stack is empty
PerlHandler handlers returned 0

So if you debug your handlers, you can see what handlers were called, whether they have registered some new handlers on the fly, and what the return status from the executed handler was.