How can I print all executed subroutines?

Question

E.g. I have following Perl script

{ 
    package A;

    {
        package B;

        sub _y {
            print "Just Another Perl Hacker\n";

        }

    }

    sub _x {
        print "Hello world!\n";
        B::_y();
    }
}


use strict;
use warnings;

_x();

How can I print every executed sub with package qualifier to STDERR or any log file?

E.g. from the script above I expect to see the following output:

1 A::_x()
2 B::_y()

I presume that it's possible to do with debugger like Devel::NYTProf, but I haven't found particular debugger modules or their params for that simple task.

Any ideas?

Answer 1

Thinking about debugging modules puts you on the right track. When debug mode is enabled, Perl calls the function DB::DB() at every execution step in your program. From here you can extract the subroutine name from the caller builtin (which will include the package name), and output it as you see fit.

Start with a file called Devel/AllSubs.pm somewhere in your @INC path:

package Devel::AllSubs;
my $count = 0;
my $last_sub = '::';
sub DB::DB {
    my ($pkg, $file, $line,$sub) = caller(1);
    if ($sub ne $last_sub) {
        print STDERR ++$count," $sub\n";
        $last_sub = $sub;
    }
}
1;

And then run your program as

$ perl -d:AllSubs script.pl

Sample output:

1 A::_x
Hello world!
2 B::_y
Just Another Perl Hacker

Answer 2

It can be done with the standard perl debugger:

$ PERLDB_OPTS="NonStop frame=1" perl -d prog.pl
  entering CODE(0x260cd78)
   entering strict::import
  entering CODE(0x260cd18)
   entering warnings::import
Package try.pl.
  entering DB::Obj::_init
  entering A::_x
Hello world!
   entering B::_y
Just Another Perl Hacker

(Note that I had to change _x(); to A::_x(); to get your code to run.)

If you want to place the output in a file, add LineInfo=filenamehere. See perldoc perldebug for details. (In particular, if you change the options to say frame=2, you also get messages for returning from subroutines.)

The CODE references are for the implicit BEGIN blocks around use statements:

use strict;

really means

BEGIN {
    require "strict.pm";
    strict->import();
}

Answer 3

An alternative solution, using the already-mentioned Devel::NYTProf (a profiler instead of a debugger, to be more precise), which doesn't require you to write any additional code and gives you a lot more information.

% perl -d:NYTProf yourscript.pl

This will by default create an nytprof.out file. You can then do:

% nytprofcalls nytprof.out

which will give you detailed call information. An example script:

use strict;

sub f1 {
  print "hi;\n";
  f2();
}

sub f2 {
  print "hi2\n";
}

f1();

and sample output:

main::f1;main::f2 30
main::f1;main::CORE:print 124
main::f1;main::f2;main::CORE:print 40
main::BEGIN@1 4262
main::f1 113
main::BEGIN@1;strict::import 39
main::BEGIN@1;strict::BEGIN@7 396
main::BEGIN@1;strict::BEGIN@7;strict::CORE:match 58

You can see that NYTProf also lists calls to core function (CORE::print), among other things.

As a bonus, you can see the whole profile output using:

% nytprofhtml

then open the report page, e.g. using:

% firefox nytprof/index.html

You can see the subroutines that were executed (ordered by how long they run), how many times they were run, and much much more.