Monkey patching all subs with a basic 'starting subname' message

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

While working on an existing Perl package file, I would like to log the start/end of each method call (preferably without adding any new dependencies to the module). I've already added a rudimentary __dbg sub, which I'm fond of, like so...

our $DEBUG_LEVEL = 5;

sub __dbg (&;$) {
    my ($code, $verbosity) = @_;
    if ($DEBUG_LEVEL >= ($verbosity // 1)) {
        my $msg = join('', $code->());
        print STDERR "DEBUG: ", $msg, "\n" if length($msg);
    }
}

# ...the meat of the package is below...
[download]

I think I have been able to monkey-patch all the methods in the package, by adding the following to the bottom of the package file:

# ...the meat of the package is above...

__dbg {
    no strict 'refs';
    no warnings 'redefine';
    my $package = __PACKAGE__;
    my %patched = ('__dbg' => 1);
    foreach (grep { defined &{"${package}::$_"} } keys %{"${package}::
+"}) {
        unless (exists $patched{$_}) {
            $patched{$_} = 1;
            __dbg { "Monkeypatching '${package}::$_' for tracing..." }
+ 5;
            my $fname = $_;
            my $fn = \&{"${package}::$_"};
            *$_ = sub {
                __dbg { "Starting ${package}::${fname}(", join(',', @_
+), ')' } 4;
                my @ret = $fn->(@_);
                __dbg { "Ending ${package}::${fname} with return value
+s: ", join(',', @ret) } 4;
                return unless defined(wantarray);
                return @ret if wantarray;
                return @ret[0] if scalar(@ret);
            }
        }
    }    
};
1;
[download]

Now, whether this is a good thing to do or not (I promise to remove it at the end of the dev cycle), it seems to be working, but now I'm worried that my 'light-touch' profiling will actually have unintended side-effects on the subs it touches. For example:

It warns on subs that have prototypes (e.g. Prototype mismatch: sub MyModule::method1 (&;$) vs none at /MyModule.pm line Y.), where Y is the closing brace to the unless (exists... block. I can suppress with no warnings 'prototype' but does that mean that the interpreter may no longer apply the syntactic distinctions that prototypes intend to provide?
Even though I'm trying to reflect the requirements of the caller using wantarray, am I altering the results of wantarray in the actual wrapped call? Better to check wantarray first?
I think it's also attaching to subs that are imported into the module (i.e. I don't think try, with or time are actually part of the package), but I can't see the 'best' way to exclude them
(Also, it doesn't actually output the arguments, but I can't see the bug -- should I copy @_ to a local variable first (i.e. my @args = @_)?)

Any other wisdom to be shared here (bar the obvious "don't" and "use a cpan module")?

Comment on Monkey patching all subs with a basic 'starting subname' message Select or Download Code

Replies are listed 'Best First'.
Re: Monkey patching all subs with a basic 'starting subname' message by LanX (Saint) on Jul 14, 2017 at 17:41 UTC
If I were you I'd check CPAN for related modules, maybe looking for "advice" (a LISP term) or "around" or "before/after" > Any other wisdom to be shared here (bar the obvious "don't" and "use a cpan module")? Well even if you do it yourself, you are free to look into the code concerning: 1. You can check the target prototype before patching with `prototype` 3. It's possible to inspect the originating "home" package of a sub, again try searching the archives here° Nota bene: Perl has a trace option ( `perlrun` ) and the debugger has many means to "watch" subs ( `perldebug` ) Cheers Rolf _{(addicted to the Perl Programming Language and ☆☆☆☆ :) Je suis Charlie!} update °) See B::svref_2object($subref) in `B`	[reply]
Re^2: Monkey patching all subs with a basic 'starting subname' message by Anonymous Monk on Jul 14, 2017 at 19:53 UTC
Thanks, Rolf; 'Advice' and 'around' are indeed very good search keywords for examples of what I am doing, and point me right to people who I am sure have done it well -- thanks for this. `prototype` is -- now that I have seen it -- obvious, really! Can't believe I missed that on my first scan through perlfunc! I have managed to fold the output of this into my code using `eval`; of course, now the meat of my redefined sub is essentially a string -- is this the sanest way to apply this?	[reply] [d/l] [select]
Re^3: Monkey patching all subs with a basic 'starting subname' message by LanX (Saint) on Jul 14, 2017 at 20:00 UTC
> of course, now the meat of my redefined sub is essentially a string -- is this the sanest way to apply this? Not sure what this "meat" is supposed to mean (?) Could you show some code? Cheers Rolf _{(addicted to the Perl Programming Language and ☆☆☆☆ :) Je suis Charlie!}	[reply]
Re^4: Monkey patching all subs with a basic 'starting subname' message by Anonymous Monk on Jul 17, 2017 at 20:11 UTC
Re^5: Monkey patching all subs with a basic 'starting subname' message by LanX (Saint) on Jul 17, 2017 at 20:18 UTC
Some notes below your chosen depth have not been shown here
Re: Monkey patching all subs with a basic 'starting subname' message by afoken (Chancellor) on Jul 14, 2017 at 17:36 UTC
I would like to log the start/end of each method call So, you are trying to implement a poor man's Devel::NYTProf. Well, you could re-implement what Devel::NYTProf does, starting with its interface to the perl interpreter. Hint: Use the debugger and compiler interfaces (DB, O, B). Plan some months of work. Or, you could simply install Devel::NYTProf and use it. With all of its fancy statistics, timing information, reporting. Plan 5 to 15 min for installation and another 5 to 15 min to learn how to use it. Any other wisdom to be shared here (bar the obvious "don't" and "use a cpan module")? Oh sorry, forget that Devel::NYTProf thing. Have fun doing it the hard and ugly way. Ignore that CPAN exists. And while you start doing everything from scratch, why don't you re-invent perl? You could use your own compiler for own C variant, running your own assembler and of course, your own operating system. CPAN is Perl's strength, not its weakness. Alexander -- Today I will gladly share my knowledge and experience, for there are no sweeter words than "I told you so". ;-)	[reply]
Re^2: Monkey patching all subs with a basic 'starting subname' message by Anonymous Monk on Jul 14, 2017 at 18:38 UTC
Thanks, Alexander; I appreciate that I'm reinventing the wheel, and always expected that to be the case. I'm not adverse to CPAN at all, but I don't always have the luxury at $work; and was interested in thoughts on the code I posted, more for academic reasons than anything else. I will check out Devel::NYTProf, at least in my local dev stack -- I will say that I do not always find it easy to find the right CPAN module for the job, and I appreciate the pointer.	[reply]
Re^3: Monkey patching all subs with a basic 'starting subname' message by Your Mother (Archbishop) on Jul 14, 2017 at 21:49 UTC
I don't always have the luxury at `$work` This is never the case for code or technical reasons. It is sometimes the case for licensing and legal reasons. If so, you should go right to you manager and say, “Look, this is a 10 month project and it’s going to be of pretty low to mediocre quality in the end and not cover some parts because I couldn’t figure out how to stop the segfaults. Or we could do this for free in a half hour today–” I’m not being an a$$ or snarky remarking about the quality. If you could do it better than, or even half as well as, the solution recommended by afoken, you wouldn’t have to ask questions here. You would already know more than the rest of us about it. As a learning exercise, it’s terrific though.	[reply] [d/l]
Re^4: Monkey patching all subs with a basic 'starting subname' message by Anonymous Monk on Jul 17, 2017 at 20:38 UTC
Re: Monkey patching all subs with a basic 'starting subname' message by LanX (Saint) on Jul 14, 2017 at 18:16 UTC
> by adding the following to the bottom of the package file: You may want to consider a CHECK or UNITCHECK block, like this you might be able to hide all magic inside a used module. See perlmod#BEGIN%2c-UNITCHECK%2c-CHECK%2c-INIT-and-END Cheers Rolf _{(addicted to the Perl Programming Language and ☆☆☆☆ :) Je suis Charlie!}	[reply]
Re: Monkey patching all subs with a basic 'starting subname' message by Anonymous Monk on Jul 14, 2017 at 19:14 UTC
Tool to record subroutine calls & return values	[reply]
Re^2: Monkey patching all subs with a basic 'starting subname' message by stevieb (Canon) on Jul 14, 2017 at 23:35 UTC
I responded on that thread, so I'll go another round. When I first started with Perl, I was dropped into a situation where I had a less-than-sane codebase. The very first thing I desired to design was something that could tell me stuff about code. I got familiar with the tools others have mentioned, but still wanted to figure it out. Devel::Trace::Subs was the creation of that, after having to go on another huge tangent with Devel::Examine::Subs as its backbone. This is intrusive; it literally writes to library files: `perl -MDevel::Trace::Subs=install_trace -e 'install_trace(file => "Dat +a::Dump")'` [download] At this point, you've infected your `../Data/Dump.pm` file. This is a global example, you can fine-tune what you're tracing. So a script that looked like this: `use warnings; use strict; use Data::Dump qw(dd); three(); sub one { return {a => 1, b => 2}; } sub two { return one(); } sub three { dd two(); }` [download] That output this: `{ a => 1, b => 2 }` [download] ...now looks like this: `use warnings; use strict; use Data::Dump qw(dd); use Devel::Trace::Subs qw(trace_dump); $ENV{DTS_ENABLE} = 1; three(); trace_dump(); sub one { return {a => 1, b => 2}; } sub two { return one(); } sub three { dd two(); }` [download] ... and outputs: { a => 1, b => 2 } Code flow: 1: Data::Dump::dd 2: Data::Dump::dump 3: Data::Dump::_dump 4: Data::Dump::tied_str 5: Data::Dump::_dump 6: Data::Dump::_dump 7: Data::Dump::format_list Stack trace: in: Data::Dump::dd sub: main::three file: script.pl line: 20 package: main in: Data::Dump::dump sub: Data::Dump::dd file: /usr/local/share/perl/5.22.1/Data/Dump.pm line: 84 package: Data::Dump in: Data::Dump::_dump sub: Data::Dump::dump file: /usr/local/share/perl/5.22.1/Data/Dump.pm line: 36 package: Data::Dump in: Data::Dump::tied_str sub: Data::Dump::_dump file: /usr/local/share/perl/5.22.1/Data/Dump.pm line: 292 package: Data::Dump in: Data::Dump::_dump sub: Data::Dump::_dump file: /usr/local/share/perl/5.22.1/Data/Dump.pm line: 331 package: Data::Dump in: Data::Dump::_dump sub: Data::Dump::_dump file: /usr/local/share/perl/5.22.1/Data/Dump.pm line: 331 package: Data::Dump in: Data::Dump::format_list sub: Data::Dump::dump file: /usr/local/share/perl/5.22.1/Data/Dump.pm line: 65 package: Data::Dump [download] You can then just revert your changes: `perl -MDevel::Trace::Subs=remove_trace -e 'remove_trace(file => "Data: +:Dump")'` [download] The output is kind of configurable in that there are two very basic templates with the ability to send in an html flag for rendering. You can also limit the output to flow or trace. There are many other tools that do this kind of thing that are far better and far more widespread, and unless one is brave, they'd use a non-intrusive proper profiler or something that's been through the ropes. I just like how OP is proud of their `__dbg()` hijacker, so I thought I'd share :) update: Mentioned Devel::NYTProf as a profiler, but if OP wants to get into examining files/code itself, invest in learning some PPI.	[reply] [d/l] [select]
Re^3: Monkey patching all subs with a basic 'starting subname' message by Anonymous Monk on Jul 17, 2017 at 21:48 UTC
> I just like how OP is proud of their __dbg() hijacker, so I thought I'd share :) I feel suitably patted on the head and sent on my way! :) `__dbg` was one of the first things I wrote, so I am fond — not necessarily proud — of it. For me, I just like that it doesn't evaluate the entire code block if the debug level is too low (so I can avoid string-interpolation, etc. if I don't need to see it); that the prototype allows it to achieve this without any significantly obtuse syntax (whereas some other languages I've worked with would want all manner of `function ()` or `() =>` cruft); and that it is distinguishable from any other `if/print` in the code, by naming convention. I also like to set the debug level via an incremental `Getopt::Long`, and run it on the command line. Because I can. Because that's all I needed -- a basic `if/print` that I can leave in place and 'turn off' without worrying about it. But most of all, I like that I devised both the requirement and the implementation myself. Because it meant I knew enough to commence breaking everything I saw! That I used it as part of further attempts to inspect the code I was working on is, of course, an overstretching of its original goals, but all I wanted to do was print the subroutines in the order they were run, without irretrievably changing the original files, so I took my hammer and applied it to this nailish-looking thing. I haven't tried either Devel::Trace::Subs or Devel::Examine::Subs but, from what I have read, I don't know if I like that it modifies the files (although I do appreciate that you can revert it). I really didn't want to change the source files, if I could help it — they aren't mine, and it wasn't my box to play with. Thanks for pointing these out, though, and I may look to evaluate them more thoroughly in the future. PS: I tried NYTProf very quickly, in response to two recommendations, once I got back to my lab environment. I'm sure it's wonderful but I'm nowhere near needing it yet. `nytprofhtml` is very pretty and `nytprofcalls` is very thorough but, if I'd started out with either in my toolchain, I feel I'd still be there now, wondering in what order the subroutines were run in a one-off process I was looking at...	[reply] [d/l] [select]

update