NAME

perldtrace - Perl's support for DTrace

SYNOPSIS

 # dtrace -Zn 'perl::sub-entry, perl::sub-return {trace(copyinstr(arg0))}'
 dtrace: description 'perl::sub-entry, perl::sub-return ' matched 10 probes

 # perl -E 'sub outer { inner(@_) } sub inner { say shift } outer("hello")'
 hello

 (dtrace output)
 CPU     ID                    FUNCTION:NAME
   0  75915       Perl_pp_entersub:sub-entry   BEGIN
   0  75915       Perl_pp_entersub:sub-entry   import
   0  75922      Perl_pp_leavesub:sub-return   import
   0  75922      Perl_pp_leavesub:sub-return   BEGIN
   0  75915       Perl_pp_entersub:sub-entry   outer
   0  75915       Perl_pp_entersub:sub-entry   inner
   0  75922      Perl_pp_leavesub:sub-return   inner
   0  75922      Perl_pp_leavesub:sub-return   outer

DESCRIPTION

DTrace is a framework for comprehensive system- and application-level tracing. Perl is a DTrace provider, meaning it exposes several probes for instrumentation. You can use these in conjunction with kernel-level probes, as well as probes from other providers such as MySQL, in order to diagnose software defects, or even just your application's bottlenecks, from user-land calls, to binaries, up into kernel calls.

Perl needs to be compiled with the -Dusedtrace option in order to make use of the provided probes. While DTrace aims to have no overhead when its instrumentation is not active, Perl's support itself cannot uphold that guarantee, so it is built without DTrace probes under most systems. One notable exception is that Mac OS X builds with -Dusedtrace by default, and ships a /usr/bin/perl with DTrace support enabled.

Currently DTrace is known to be ported to Solaris, Mac OS X, FreeBSD, DragonFLY BSD, NetBSD, and on linux there is a unstable port via a dtrace4linux at https://crtags.blogspot.de/, but see https://github.com/agentzh/perl-systemtap-toolkit instead.

On most systems you need to run it as root: sudo dtrace, and beware that probes are global. Prefer to use pid-specific probes, beginning with perl$target:::.

HISTORY

5.10.1

Perl's initial DTrace support was added, providing sub-entry and sub-return probes.

5.14.0

The sub-entry and sub-return probes gain a fourth argument: the package name of the function.

5.16.0

The phase-change probe was added.

5.18.0

The op-entry, loading-file, and loaded-file probes were added.

5.25.3c

loading-file, loaded-file renamed to load-entry, load-return. Added glob-entry, glob-return, hash-entry, hash-return probes. Added more examples.

PROBES

sub-entry(SUBNAME, FILE, LINE, PACKAGE)

Traces the entry of any subroutine. Note that all of the variables refer to the subroutine that is being invoked; there is currently no way to get ahold of any information about the subroutine's caller from a DTrace action.

 perl$target:::sub-entry {
     printf("%s::%s entered at %s line %d\n",
           copyinstr(arg3), copyinstr(arg0), copyinstr(arg1), arg2);
 }
sub-return(SUBNAME, FILE, LINE, PACKAGE)

Traces the exit of any subroutine. Note that all of the variables refer to the subroutine that is returning; there is currently no way to get ahold of any information about the subroutine's caller from a DTrace action.

 perl$target:::sub-return {
     printf("%s::%s returned at %s line %d\n",
           copyinstr(arg3), copyinstr(arg0), copyinstr(arg1), arg2);
 }
phase-change(NEWPHASE, OLDPHASE)

Traces changes to Perl's interpreter state. You can internalize this as tracing changes to Perl's ${^GLOBAL_PHASE} variable, especially since the values for NEWPHASE and OLDPHASE are the strings that ${^GLOBAL_PHASE} reports.

 perl$target:::phase-change {
     printf("Phase changed from %s to %s\n",
         copyinstr(arg1), copyinstr(arg0));
 }
op-entry(OPNAME)

Traces the execution of each opcode in the Perl runloop. This probe is fired before the opcode is executed. When the Perl debugger is enabled, the DTrace probe is fired after the debugger hooks (but still before the opcode itself is executed).

 perl$target:::op-entry {
     printf("About to execute opcode %s\n", copyinstr(arg0));
 }
load-entry(FILENAME)

Fires when Perl is about to load an individual file, whether from use, require, or do. This probe fires before the file is read from disk. The filename argument is converted to local filesystem paths instead of providing Module::Name-style names.

 perl$target:::load-entry {
     printf("About to load %s\n", copyinstr(arg0));
 }
load-return(FILENAME)

Fires when Perl has successfully loaded an individual file, whether from use, require, or do. This probe fires after the file is read from disk and its contents evaluated. The filename argument is converted to local filesystem paths instead of providing Module::Name-style names.

 perl$target:::load-return {
     printf("Successfully loaded %s\n", copyinstr(arg0));
 }
glob-entry(MODE, NAME)

Fires when Perl is performing a glob lookup.

  MODE 0: gv_init
       1: gv_add (empty name)
       2: gv_fetch
       3: gv_fetchmeth

 perl$target:::glob-entry {
     printf("glob lookup mode %d: %s\n", arg0, copyinstr(arg1));
 }
glob-return(MODE, NAME)

Fires when Perl finished a glob lookup. For MODE see "glob-entry(MODE, NAME)".

 perl$target:::glob-return {
   printf("glob lookup mode: %d: %s done\n", arg0, copyinstr(arg1));
 }
hash-entry(MODE, KEY)

Fires when Perl is performing an internal hash-table lookup.

  MODE 0: hv_fetch
       1: hv_store
       2: hv_exists
       3: hv_delete

 perl$target:::hash-entry {
     printf("hash lookup mode %d {%s}\n", arg0, copyinstr(arg1));
 }

Example to print the sum of operations by type:

  $ sudo dtrace -qn "hash-entry{@[arg0]=count()}" -c"perl script.pl"
hash-return(MODE, KEY)

Fires when Perl finished an internal hash-table lookup. For MODE see "hash-entry(MODE, KEY)".

 perl$target:::hash-return {
   printf("hash lookup mode %d {%s} done\n", arg0, copyinstr(arg1));
 }

EXAMPLES

Most frequently called functions
 # dtrace -qZn 'sub-entry { @[strjoin(strjoin(copyinstr(arg3),"::"),
                  copyinstr(arg0))] = count() } END {trunc(@, 10)}'

 Class::MOP::Attribute::slots                                    400
 Try::Tiny::catch                                                411
 Try::Tiny::try                                                  411
 Class::MOP::Instance::inline_slot_access                        451
 Class::MOP::Class::Immutable::Trait:::around                    472
 Class::MOP::Mixin::AttributeCore::has_initializer               496
 Class::MOP::Method::Wrapped::__ANON__                           544
 Class::MOP::Package::_package_stash                             737
 Class::MOP::Class::initialize                                  1128
 Class::MOP::get_metaclass_by_name                              1204
Trace function calls
 # dtrace -qFZn 'sub-entry, sub-return { trace(copyinstr(arg0)) }'

 0  -> Perl_pp_entersub                        BEGIN
 0  <- Perl_pp_leavesub                        BEGIN
 0  -> Perl_pp_entersub                        BEGIN
 0    -> Perl_pp_entersub                      import
 0    <- Perl_pp_leavesub                      import
 0  <- Perl_pp_leavesub                        BEGIN
 0  -> Perl_pp_entersub                        BEGIN
 0    -> Perl_pp_entersub                      dress
 0    <- Perl_pp_leavesub                      dress
 0    -> Perl_pp_entersub                      dirty
 0    <- Perl_pp_leavesub                      dirty
 0    -> Perl_pp_entersub                      whiten
 0    <- Perl_pp_leavesub                      whiten
 0  <- Perl_dounwind                           BEGIN

See Porting/subs.d for a similar example.

Function calls during interpreter cleanup
 # dtrace -Zn 'phase-change /copyinstr(arg0) == "END"/ { self->ending = 1 }
               sub-entry /self->ending/ { trace(copyinstr(arg0)) }'

 CPU     ID                    FUNCTION:NAME
   1  77214       Perl_pp_entersub:sub-entry   END
   1  77214       Perl_pp_entersub:sub-entry   END
   1  77214       Perl_pp_entersub:sub-entry   cleanup
   1  77214       Perl_pp_entersub:sub-entry   _force_writable
   1  77214       Perl_pp_entersub:sub-entry   _force_writable
System calls at compile time
 # dtrace -qZn 'phase-change
     /copyinstr(arg0) == "START"/ { self->interesting = 1 }
     phase-change /copyinstr(arg0) == "RUN"/ { self->interesting = 0 }
     syscall::: /self->interesting/ { @[probefunc] = count() }
     END { trunc(@, 3) }'

 lseek                                                           310
 read                                                            374
 stat64                                                         1056
Perl functions that execute the most opcodes
 # dtrace -qZn 'sub-entry { self->fqn = strjoin(copyinstr(arg3),
                            strjoin("::", copyinstr(arg0))) }
                op-entry /self->fqn != ""/ { @[self->fqn] = count() }
                END { trunc(@, 3) }'

 warnings::unimport                                             4589
 Exporter::Heavy::_rebuild_cache                                5039
 Exporter::import                                              14578
How much time is spent in an op on average
 # dtrace -qZn "BEGIN{self->prev=0;}
                op-entry { myop = copyinstr(arg0); curtime = timestamp;
                           elapsed = self->prev ? curtime - self->prev : 0;
                           @[myop]=avg(elapsed); self->prev = curtime;}
                END { trunc(@, 15); printf(\"\nTime (avg ns)\n\");
                      printa(\"%10s\t%@8u\n\", @);}"
          -c'./miniperl -Ilib -E0'

                 Time (avg ns)
    pushmark        2149
     sassign        2160
  multideref        2176
       const        2255
    leavesub        2282
       padsv        2460
     aassign        2555
          or        2651
       leave        2984
    iter_ary        3213
   leaveeval        3235
    entersub        3868
       aelem        3884
       enter        3892
   nextstate       10073

See Porting/op.d for a bigger example, with count() and quantize().

sudo dtrace -s Porting/op.d -c'./miniperl -Ilib -E0'

What hash operations dominate

Number of modes:

 # sudo dtrace -n "hash-entry{@[arg0]=count()}" -c"./miniperl -Ilib script.pl"

                3               15  # DELETE
                2               39  # EXISTS
                1              125  # STORE
                0              724  # FETCH

Time spent (on average):

 # sudo dtrace -qn "BEGIN{self->ts=0}hash-entry{self->ts=timestamp}
                    hash-return{@[arg0]=avg(timestamp-self->ts)}"
               -c"./miniperl -Ilib script.pl"

                0             1000  # FETCH
                2             1014  # EXISTS
                1             1111  # STORE
                3             1641  # DELETE

See mydtrace.h for the modes.

glob/gv call statistics
 # sudo dtrace -qn "BEGIN{self->ts=0} glob-entry{self->ts=timestamp}
                    glob-return{ts=timestamp-self->ts;@a[arg0]=avg(ts);
                                @q[arg0]=quantize(ts);@c[arg0]=count()}"
               -c"./miniperl -Ilib autodoc.pl"

average time per mode (ns):

                1             1234  # ADD
                0             1417  # INIT
                2             3055  # FETCH
                3             4150  # FETCHMETH

time spent per mode (ns):

                3 # FETCHMETH
           value  ------------- Distribution ------------- count
            1024 |                                         0
            2048 |@@@@@@@@@@@@@                            1
            4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2
            8192 |                                         0

                1 # ADD
           value  ------------- Distribution ------------- count
             256 |                                         0
             512 |@@@@@@@@@@@@@@@@@@@@@@@@@                67
            1024 |@@@@@@@@@@@                              31
            2048 |@@@                                      8
            4096 |@                                        2
            8192 |                                         0

                0 # INIT
           value  ------------- Distribution ------------- count
             256 |                                         0
             512 |@                                        8
            1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@     273
            2048 |@@                                       16
            4096 |                                         3
            8192 |                                         0

                2 # FETCH
           value  ------------- Distribution ------------- count
            1024 |                                         0
            2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@    224
            4096 |@@                                       13
            8192 |                                         3
           16384 |                                         1
           32768 |                                         0

sum of glob calls:

                3                3  # FETCHMETH
                1              108  # ADD
                2              241  # FETCH
                0              300  # INIT

REFERENCES

DTrace Dynamic Tracing Guide

http://dtrace.org/guide/preface.html

DTrace: Dynamic Tracing in Oracle Solaris, Mac OS X and FreeBSD

http://www.amazon.com/DTrace-Dynamic-Tracing-Solaris-FreeBSD/dp/0132091518/

SEE ALSO

Devel::DTrace::Provider

This CPAN module lets you create application-level DTrace probes written in Perl.

AUTHORS

Shawn M Moore sartak@gmail.com, Reini Urban rurban@cpan.org