DTrace and Perl

After reading Bryan's DTrace and PHP and DTrace and PHP, demonstrated blog entries, I thought I'd better have a crack at doing the same for Perl - after all, anything PHP can do, Perl can do better - right? ;-)

I posted a question on the perl5-porters list about the best way of doing this for Perl, and Dave Mitchell kindly stepped up to help - many thanks to Dave, and he should take most of the credit for figuring out how best to do this.

The PHP DTrace probes instrument the function entry and return points within a PHP script so I thought I'd do the same for Perl. After some to-and-fro-ing with Dave it became apparent that the easiest way was to add DTrace probes to the PUSHSUB and POPSUB macros. As the names suggest, these are called each time a Perl subroutine is entered and exited. This doesn't get all of the potential entry points, for example eval and require but it's a good start, at least for the purposes of prototyping. The first step is to define the DTrace probes that we will be using:

provider perl {
        probe sub__entry(char*, char*, int);
        probe sub__return(char*, char*, int);
};

The arguments are the sub name, the filename and line number. Here's the changes that are required to cop.h for the PUSHSUB case:

        DTRACE_PROBE3(perl, sub__entry, GvENAME(CvGV(cv)),              \
            CopFILE((COP*)CvSTART(cv)), CopLINE((COP*)CvSTART(cv)));

The fiddly bits are the dereferencing of the current cv to extract the sub name, file name and line number. The next bit is to hack Makefile to call dtrace to postprocess the object files before building libperl.so. This builds an extra object file which we then need to include in the file list used to build libperl.so:

$(LIBPERL): $& perl$(OBJ_EXT) $(obj) $(LIBPERLEXPORT)
        dtrace -G -s dtrace.d -o dtrace.o $(obj) miniperlmain.o perl.o
        $(LD) -o $@ $(SHRPLDFLAGS) perl$(OBJ_EXT) $(obj) dtrace.o $(libs)

Job done. There are a couple of caveats however - firstly, adding the probes has a worst-case performance hit of about 5% even when they aren't enabled. The hit depends on what you are doing in your script - the worst case is for a script that does nothing but call an empty sub. The DTrace probes themselves are NOP'd out when they are inactive, but the code used to calculate the sub name, file name and line number and put them on the stack is still executed even when DTrace is inactive. I've discussed this with the DTrace crew and a way to minimise the overhead is to use a DTrace translator - a shim that sits between the application and the DTrace script and gives a stable view of application data strucures. This would take a pointer to the current cv and do the various dereferencing ops to get the sub name, file name and line number only when the probe was actually active rather than all the time, as in the prototype. This is a good idea not just because of the performance improvement, but also because it means that we can provide a stable API that will be immune to changes in the perl interpreter.

The second caveat is that at the moment some tests in the perl test suite fail with the DTrace macros inserted. Most of these happen because the object files that go into some of the extensions aren't postprocessed with DTrace, so if the extension uses the modified PUSHSUB and POPSUB macros it will fail. Two solutions spring to mind - either modify MakeMaker so that module objects are postprocessed with DTrace, or conditionally add the DTrace probes only when compiling libperl. Overall, I think I prefer the second option, at least as a first pass option.

Anyway, without further ado I present a simple example of it in use. The following D script aggregates page faults by the sub that generated them. Page faults that are caused by the perl interpreter when it isn't actually executing perl code (e.g. during startup) are aggregated under PERL

#pragma D option quiet

BEGIN
{
        self->sub = "PERL";
        self->file = "PERL";
}

perl$target:::sub-entry
{
        self->sub = copyinstr(arg0);
        self->file = copyinstr(arg1);
}

perl$target:::sub-return
{
        self->sub = "PERL";
        self->file = "PERL";
}

vminfo:::maj_fault,
vminfo:::zfod,
vminfo:::as_fault
/self->sub != 0/
{
        @pf[self->sub, self->file] = count();
}

END
{
        printa("%@8d  %-20s %s\n", @pf);
}

And here is the output when run on pod2text perl.pod:

       1  import               /demo/lib/Exporter.pm
       1  import               /demo/lib/strict.pm
       1  import               /demo/lib/warnings/register.pm
       1  output               /demo/lib/Pod/Text.pm
       2  GetOptions           /demo/lib/Getopt/Long.pm
       2  bits                 /demo/lib/strict.pm
       2  interpolate          /demo/lib/Pod/Parser.pm
       2  seq_c                /demo/lib/Pod/Text.pm
       2  wrap                 /demo/lib/Pod/Text.pm
       4  as_heavy             /demo/lib/Exporter.pm
       6  verbatim             /demo/lib/Pod/Text.pm
       8  BEGIN                /demo/lib/Pod/Select.pm
       8  BEGIN                /demo/lib/Pod/Usage.pm
      10  BEGIN                /demo/lib/Pod/Text.pm
      11  import               /demo/lib/vars.pm
      13  BEGIN                /demo/lib/Pod/Parser.pm
      18  BEGIN                /demo/lib/vars.pm
      25  BEGIN                pod/pod2text
      28  BEGIN                /demo/lib/Getopt/Long.pm
      51  BEGIN                /demo/lib/warnings.pm
    1580  PERL                 PERL

Of course that's just a really simplistic sample, the full power of DTrace can be used to find out exactly what your perl script is doing sub-by-sub, whether it be in libperl, libc or the kernel itself. Here's an example which shows which perl subs result in kernel locks being taken, the output is for the same pod2text perl.pod command. If you want to know what all the scary numbers mean, the DTrace lockstat provider documentation explains all.

       1 adaptive BEGIN                          /demo/lib/Symbol.pm
       1 adaptive ConfigDefaults                 /demo/lib/Getopt/Long.pm
       1 adaptive DESTROY                        /demo/lib/Config.pm
       1 adaptive FindOption                     /demo/lib/Getopt/Long.pm
       1 adaptive MAIN                           pod/pod2text
       1 adaptive TIEHASH                        /demo/lib/Config.pm
       1 adaptive _pop_input_stream              /demo/lib/Pod/Parser.pm
       1 adaptive _push_input_stream             /demo/lib/Pod/Parser.pm
       1 adaptive begin_input                    /demo/lib/Pod/Parser.pm
       1 adaptive begin_pod                      /demo/lib/Pod/Parser.pm
       1 adaptive cmd_back                       /demo/lib/Pod/Text.pm
       1 adaptive cmd_over                       /demo/lib/Pod/Text.pm
       1 adaptive config                         /demo/lib/Getopt/Long.pm
       1 adaptive end_input                      /demo/lib/Pod/Parser.pm
       1 adaptive end_pod                        /demo/lib/Pod/Parser.pm
       1 adaptive export                         /demo/lib/Exporter.pm
       1 adaptive import                         /demo/lib/Config.pm
       1 adaptive import                         /demo/lib/Getopt/Long.pm
       1 adaptive initialize                     /demo/lib/Pod/Parser.pm
       1 adaptive initialize                     /demo/lib/Pod/Text.pm
       1 adaptive new                            /demo/lib/Pod/Parser.pm
       1 adaptive parse_from_file                /demo/lib/Pod/Parser.pm
       1 adaptive parse_from_filehandle          /demo/lib/Pod/Parser.pm
       1 adaptive was_cutting                    /demo/lib/Pod/InputObjects.pm
       2 adaptive BEGIN                          /demo/lib/Config.pm
       2 adaptive BEGIN                          /demo/lib/Exporter/Heavy.pm
       2 adaptive BEGIN                          /demo/lib/File/Spec.pm
       2 adaptive Configure                      /demo/lib/Getopt/Long.pm
       2 adaptive gensym                         /demo/lib/Symbol.pm
       2 spin     import                         /demo/lib/vars.pm
       2 spin     interpolate                    /demo/lib/Pod/Parser.pm
       2 spin     seq_c                          /demo/lib/Pod/Text.pm
       2 spin     verbatim                       /demo/lib/Pod/Text.pm
       3 adaptive BEGIN                          /demo/lib/File/Spec/Unix.pm
       3 adaptive BEGIN                          /demo/lib/Pod/InputObjects.pm
       3 adaptive BEGIN                          /demo/lib/Pod/ParseLink.pm
       3 spin     __ANON__                       /demo/lib/Pod/Parser.pm
       3 spin     input_file                     /demo/lib/Pod/Parser.pm
       3 spin     parse_text                     /demo/lib/Pod/Parser.pm
       3 spin     preprocess_line                /demo/lib/Pod/Parser.pm
       3 spin     wrap                           /demo/lib/Pod/Text.pm
       4 adaptive BEGIN                          /demo/lib/constant.pm
       4 adaptive mkMask                         /demo/lib/warnings/register.pm
       4 adaptive unimport                       /demo/lib/strict.pm
       6 spin     new                            /demo/lib/Pod/InputObjects.pm
       7 adaptive cmd_head2                      /demo/lib/Pod/Text.pm
       8 adaptive seq_f                          /demo/lib/Pod/Text.pm
       9 adaptive import                         /demo/lib/constant.pm
       9 spin     as_heavy                       /demo/lib/Exporter.pm
      11 adaptive cmd_head1                      /demo/lib/Pod/Text.pm
      12 adaptive ParseOptionSpec                /demo/lib/Getopt/Long.pm
      12 adaptive cmd_item                       /demo/lib/Pod/Text.pm
      12 adaptive item                           /demo/lib/Pod/Text.pm
      12 spin     BEGIN                          /demo/lib/Pod/Select.pm
      15 adaptive seq_i                          /demo/lib/Pod/Text.pm
      18 adaptive heading                        /demo/lib/Pod/Text.pm
      18 adaptive import                         /demo/lib/warnings/register.pm
      18 spin     BEGIN                          /demo/lib/Pod/Usage.pm
      26 spin     BEGIN                          /demo/lib/Pod/Text.pm
      32 adaptive command                        /demo/lib/Pod/Text.pm
      33 adaptive GetOptions                     /demo/lib/Getopt/Long.pm
      34 adaptive seq_c                          /demo/lib/Pod/Text.pm
      35 adaptive left_delimiter                 /demo/lib/Pod/InputObjects.pm
      38 adaptive seq_b                          /demo/lib/Pod/Text.pm
      39 adaptive _infer_text                    /demo/lib/Pod/ParseLink.pm
      39 adaptive _parse_section                 /demo/lib/Pod/ParseLink.pm
      39 adaptive file_line                      /demo/lib/Pod/InputObjects.pm
      39 adaptive parselink                      /demo/lib/Pod/ParseLink.pm
      39 adaptive seq_l                          /demo/lib/Pod/Text.pm
      42 spin     BEGIN                          /demo/lib/Getopt/Long.pm
      42 spin     BEGIN                          /demo/lib/Pod/Parser.pm
      42 spin     BEGIN                          pod/pod2text
      57 adaptive reformat                       /demo/lib/Pod/Text.pm
      57 adaptive textblock                      /demo/lib/Pod/Text.pm
      92 adaptive wrap                           /demo/lib/Pod/Text.pm
      96 spin     BEGIN                          /demo/lib/vars.pm
      99 adaptive import                         /demo/lib/Exporter.pm
      99 adaptive verbatim                       /demo/lib/Pod/Text.pm
     100 adaptive import                         /demo/lib/strict.pm
     104 adaptive output_handle                  /demo/lib/Pod/Parser.pm
     111 adaptive as_heavy                       /demo/lib/Exporter.pm
     113 adaptive interior_sequence              /demo/lib/Pod/Text.pm
     113 adaptive parse_tree                     /demo/lib/Pod/InputObjects.pm
     114 adaptive __ANON__                       /demo/lib/Pod/Parser.pm
     119 adaptive cutting                        /demo/lib/Pod/Parser.pm
     119 adaptive parse_paragraph                /demo/lib/Pod/Parser.pm
     119 adaptive preprocess_paragraph           /demo/lib/Pod/Text.pm
     120 adaptive output                         /demo/lib/Pod/Text.pm
     126 adaptive top                            /demo/lib/Pod/InputObjects.pm
     127 adaptive input_file                     /demo/lib/Pod/Parser.pm
     127 adaptive parse_text                     /demo/lib/Pod/Parser.pm
     133 spin     BEGIN                          /demo/lib/warnings.pm
     148 adaptive right_delimiter                /demo/lib/Pod/InputObjects.pm
     159 adaptive interpolate                    /demo/lib/Pod/Parser.pm
     162 adaptive bits                           /demo/lib/strict.pm
     167 adaptive BEGIN                          /demo/lib/Pod/Select.pm
     181 adaptive _set_child2parent_links        /demo/lib/Pod/InputObjects.pm
     183 adaptive cmd_name                       /demo/lib/Pod/InputObjects.pm
     183 adaptive nested                         /demo/lib/Pod/InputObjects.pm
     220 adaptive BEGIN                          /demo/lib/Pod/Usage.pm
     239 adaptive children                       /demo/lib/Pod/InputObjects.pm
     275 adaptive BEGIN                          /demo/lib/Pod/Text.pm
     328 adaptive BEGIN                          /demo/lib/Pod/Parser.pm
     352 adaptive DESTROY                        /demo/lib/Pod/InputObjects.pm
     352 adaptive _unset_child2parent_links      /demo/lib/Pod/InputObjects.pm
     437 adaptive preprocess_line                /demo/lib/Pod/Parser.pm
     455 adaptive import                         /demo/lib/vars.pm
     474 adaptive new                            /demo/lib/Pod/InputObjects.pm
     496 adaptive BEGIN                          /demo/lib/vars.pm
     643 adaptive append                         /demo/lib/Pod/InputObjects.pm
     670 adaptive BEGIN                          pod/pod2text
     695 adaptive BEGIN                          /demo/lib/Getopt/Long.pm
    1243 adaptive BEGIN                          /demo/lib/warnings.pm
    2946 spin     PERL                           PERL
   51019 adaptive PERL                           PERL

Categories : Solaris, Tech, Perl


Re: DTrace and Perl

Could you tell me/us how to do this under Solaris 10? Particulary, where does one define the probe? Did you do it from vanilla Perl sources? I would like to somehow add dtrace instrumentation to system Perl.

Re: DTrace and Perl

At least now I have a good excuse to get my OpenSolaris box actually running. :)

Re: DTrace and Perl

Some comments on your comments
  1. I agree with you when you say it's difficult, but the dtrace guys seemed to thing it was do-able, I defer to their superior know-how ;-)
  2. The performance impact will be the same in either case. We need to modify PUSHSUB as the perl interpreter enters subroutines from several different places, and indeed some XSUB modules do the same thing.
  3. Yes, the Makefile does need to be LP32/LP64 aware. We probably also need to modify MakeMaker so that it too uses dtrace to postprocess object files, otherwise perl XSUB modules won't be dtraceable.
  4. Perl doesn't use the C stack for storing arguments to subs, and perl data structures implement polymorphism in C (!) so we'd be into copyin pointer chasing in a big way.

Re: DTrace and Perl

Alan, Do you still have the patches you did for this around? I maintain a bunch of Perl packages/servers that I wanted to profile. I pulled down the latest Nexenta, apt-got the perl deb source, went to patch/rebuild, but I failed somehow merging the descriptions above into cop.h. (I had to guess how it'd look for POPSUB...) Thanks! brad@danga.com

Re: DTrace and Perl

I've managed to reproduce Alan's work and integrate (roughly) into the perl build system. You can find my patch here: http://rich.phekda.org/perl-dtrace/perl-5.8.8-dtrace-20070720.patch. I'm giving a talk next week on Perl and DTrace at Birmingham Perl Mongers here in the UK.