Debugging and Profiling mod_perl Applications

by Frank Wiles
February 09, 2006

Because of the added complexity of being inside of the Apache web server, debugging mod_perl applications is often not as straightforward as it is with regular Perl programs or CGIs. Is the problem with your code, Apache, a CPAN module you are using, or within mod_perl itself? How do you tell? Sometimes traditional debugging techniques will not give you enough information to find your problem.

Perhaps, instead, you're baffled as to why some code you just wrote is running so slow. You're probably asking yourself, "Isn't this mod_perl stuff supposed to improve my code's performance?" Don't worry, slow code happens even to the best of us. How do you profile your code to find the problem?

This article shows how to use the available CPAN modules to debug and profile your mod_perl applications.

Traditional Debugging Methods

The tried-and-true print statement is the debugger's best friend. Used wisely this, can be the easiest and fastest way of figuring out what is amiss in your program. Can't figure out why your sales tax subroutine is always off by 14 cents? Add several print statements just before, just after, and all around inside of that particular subroutine. Use them to show the value of key variables at each step in the process. You can direct the output straight onto the page in your browser, or if you prefer, into hidden HTML comments. Typically this is all that you need to spot your problems. It's flexible and easy to implement and understand.

Another common approach is to place die() and/or warn() statements as you trace through your code, isolating the problem. die() is especially useful if you do not want your program to continue executing, possibly because the errors will corrupt your otherwise valid testing data. The main benefit of using warn over a simple print statement is that the output goes instead to the appropriate Apache error_log. This keeps your debugging information out of the user interface and gives you the ability to log and spot errors long after they occurred for the user. Simply tail your error_log in another window and you can watch it all day long. If you're into that sort of thing.

For example, if you had some code like:

sub handler {
    my $r   =   shift;

    # Set content type
    $r->content_type( 'text/html' );

    my $req = Apache2::Request->new($r);
   
    # Compute sales tax if we are told to do so
    my $tax = 0;
    if( $req->param('compute_sales_tax') ) {
        my $tax = compute_sales_tax($r, $req->param('total_amount');
    }

    # Code to display results to the browser....
}

... you might find a problem during testing. Your initial search leads you to believe that either the code never calls the compute_sales_tax() function or the function always returns zero. You can add some simple debugging statements:

sub handler {
    my $r   =   shift;
   
    # Set content type
    $r->content_type( 'text/html' );

    my $req = Apache2::Request->new($r);
   
    # Compute sales tax if we are told to do so
    my $tax = 0;

    # Debugging statements
    warn("Tax at start '$tax'");
    warn('compute_sales_tax ' . $req->param('compute_sales_tax') );

    if( $req->param('compute_sales_tax') ) {

        # Debugging
        warn("Tax before sub '$tax'");
        my $tax = compute_sales_tax($r, $req->param('total_amount');
        warn("Tax after sub '$tax'");
    }

    warn("Tax after if '$tax'");

    # Code to display results to the browser....
}

Assuming that the page that directs the user to this code has set compute_sales_tax to a true value, you will see something similar to:

Tax at start '0' at line 5
compute_sales_tax 1 at line 6
Tax before sub '0' at line 12
Tax after sub '1.36' at line 14
Tax after if '0' at line 17

If you read through this, you see that compute_sales_tax() is indeed being called, otherwise you would not see the "Tax before/after" warn outputs. Directly after the subroutine call you can see that $tax holds a suitable value. However, after the if block, $tax reverts back to zero. Upon closer examination, you might find that the bug is the my before the call to compute_sales_tax(). This creates a locally scoped variable named $tax and does not assign it to the $tax variable in the outer block, which causes it to stay zero and makes it seem that compute_sales_tax() was never called.

Pages: 1, 2, 3

Next Page