code review: pretty print sub entry/exit

particle has asked for the wisdom of the Perl Monks concerning the following question:

well~

i've created a sub to pretty-print subroutine entry/exit for debugging purposes. i'm not alltogether happy with the way i have to use this. in particular, i MUST add two lines of code to every function, and i must be careful where i place them. also, i wonder if there is a better method to getting the sub name rather than (caller(1))[3]....

i'd be much happier with something transparent that could tell me when i've entered and exited a function, and write that to my output log, as well. is this possible, or should i be satisfied with what i have?

any hints or suggestions GREATLY appreciated!

find my test script below:

Script:

#!/usr/bin/perl -w
use strict;                            # be good!

sub hello;
sub goodbye;
sub imlate;

my $LOG;                               # dummy log this example...
$::DBUG = shift;                       # take from command-line this e
+xample

sub ::f {                              # pretty-print sub entry/exit
    my $n = "\n";                      # shortcut for newline
    my $enter = shift;                 # entering -> 1, exiting -> 0
    $enter && $::FUNC_LEVEL++;         # increment global var if enter
+ing
    # print > times global function level var plus name of calling fun
+ction
    $::DBUG && print(                  # print to screen
        ( ($enter) ? ">" : "<" ) x $::FUNC_LEVEL . 
        ( " " ) . 
        ( caller(1) )[3] . $n          # calling function name
    );
    $::DBUG && $LOG && LOG->print(     # print to log
        ( ($enter) ? ">" : "<" ) x $::FUNC_LEVEL . 
        ( " " ) . 
        ( caller(1) )[3] . $n
    );
    $enter || $::FUNC_LEVEL--;         # decrement global var if exiti
+ng
};

sub hello {                            # standard usage
    ::f(1);                            # function entry
    for(1..2) {
        print "hello!\n" . goodbye();  # call some sub...
    }
    ::f(0);                            # function exit
};

sub goodbye {                          # a tricky bit...
    ::f(1);                            # regular entrance
    ::f(0);                            # must execute BEFORE return
    return "goodbye!\n";
};

sub imlate {                           # just for giggles...
    ::f(1);
    print "i'm late!\n" x 3;
    ::f(0);
};

hello();
imlate();
[download]

Output:

so perl imlate.pl 1 prints

> main::hello
>> main::goodbye
<< main::goodbye
hello!
goodbye!
>> main::goodbye
<< main::goodbye
hello!
goodbye!
< main::hello
> main::imlate
i'm late!
i'm late!
i'm late!
< main::imlate
[download]

~Particle

Comment on code review: pretty print sub entry/exit Select or Download Code

Replies are listed 'Best First'.
Re: code review: pretty print sub entry/exit by bikeNomad (Priest) on Jun 28, 2001 at 08:24 UTC
You want transparent? How about just doing this from a (Unix) command line (after removing all your debugging code): `$ PERLDB_OPTS="f=3 N LineInfo=xxx" perl -d imlate.pl Default die handler restored. hello! goodbye! hello! goodbye! i'm late! i'm late! i'm late!` [download] This will result in the file xxx containing your trace: `$ cat xxx Package imlate.pl. entering main::hello entering main::goodbye exited main::goodbye entering main::goodbye exited main::goodbye exited main::hello entering main::imlate exited main::imlate` [download] By changing the settings of the "f=n" option, you can change the printout (from perldoc perldebguts): In all cases shown above, the line indentation shows the call tree. If bit 2 of "frame" is set, a line is printed on exit from a subroutine as well. If bit 4 is set, the arguments are printed along with the caller info. If bit 8 is set, the arguments are printed even if they are tied or references. If bit 16 is set, the return value is printed, too. Without the `LineInfo=xxx`, the entering/exited messages will end up on stdout (like in yours).	[reply] [d/l] [select]
Re: code review: pretty print sub entry/exit by Zaxo (Archbishop) on Jun 28, 2001 at 08:55 UTC
Here's half a solution, adapted from the Camel(3ed., Ch. 20) to indent for each call. `$ PERL5DB='{package DB;sub DB{} sub sub {print ++$i," "x$i," $sub\n";&$sub;$i--}}' perl -d imlate.pl` It doesn't do anything on sub return, but I expect PERL5DB could be modified to do so. It can be set as an environment variable, or written as a Devel::Xxxx module for the 'perl -d:Xxxx' form of running. The best part is that it works on unmodified code. After Compline, Zaxo	[reply] [d/l]
Re: code review: pretty print sub entry/exit by bikeNomad (Priest) on Jun 28, 2001 at 18:25 UTC
The other way to do this (without using the debugger hooks, which I think make sense) might be to use method wrappers and direct manipulation of the symbol table to replace all the subroutines of interest with wrapped versions of themselves that call your statistics functions. Since this is such a handy tool in general for code instrumentation, it would surprise me if someone hadn't written it already. But the basis of it is: `sub A { print "in A\n" } my $oldA = {main::A}{CODE}; sub A { print "entering A\n"; &$oldA(@_); print "leaving A\n"; }` [download] You'd use that along with the facts that<bl> the symbol table for package X is a global hash named %X::* or %main::X:: you can scan %main:: (recursively) for other symbol tables (their keys end in ::).</bl>	[reply] [d/l]
Re: Re: code review: pretty print sub entry/exit by particle (Vicar) on Jun 28, 2001 at 19:19 UTC
cheers mate! now that's what i'm talking about. this looks like a good way to learn more about programming in general. ~Particle	[reply]
Re: code review: pretty print sub entry/exit by particle (Vicar) on Jun 28, 2001 at 16:11 UTC
wow. well, i'm it makes me feel better that both the solutions presented so far make use of perl guts to do this. i use the debugger frequently, but i've never read through perldebguts before. very enlightening... but scary might be a better word! i'll have to play around with this a bit, since i'm on Win32 and not all is the same as *NIX. thanks for the suggestions! ~Particle	[reply]
Re: Re: code review: pretty print sub entry/exit by bikeNomad (Priest) on Jun 28, 2001 at 18:08 UTC
It's not Unix specific. Under NT's cmd interpreter (I don't know which you're using; under the cygwin bash shell it'd be the same as Unix, and the Win9x command.com is too horrible to consider): `c:\> set PERLDB_OPTS=f=3 N LineInfo=xxx c:\> perl -d imlate.pl Default die handler restored. hello! goodbye! hello! goodbye! i'm late! i'm late! i'm late!` [download]	[reply] [d/l]
Re: Re: Re: code review: pretty print sub entry/exit by particle (Vicar) on Jun 28, 2001 at 19:10 UTC
i see! i'd been typing 'set PERLDB_OPTS="f=3 N LineInfo=xxx"' which gives an error and starts the debugger in interactive mode. this is much better! stanwood as in north of seattle off route 5? i'll be driving by in about a month. i'm driving cross-country, and one of my legs is vancouver - seattle. never been there, hope it's nice! ~Particle	[reply]