pod/perldtrace.pod

   1 =head1 NAME
   2
   3 perldtrace - Perl's support for DTrace
   4
   5 =head1 SYNOPSIS
   6
   7     # dtrace -Zn 'perl::sub-entry, perl::sub-return { trace(copyinstr(arg0)) }'
   8     dtrace: description 'perl::sub-entry, perl::sub-return ' matched 10 probes
   9
  10     # perl -E 'sub outer { inner(@_) } sub inner { say shift } outer("hello")'
  11     hello
  12
  13     (dtrace output)
  14     CPU     ID                    FUNCTION:NAME
  15       0  75915       Perl_pp_entersub:sub-entry   BEGIN
  16       0  75915       Perl_pp_entersub:sub-entry   import
  17       0  75922      Perl_pp_leavesub:sub-return   import
  18       0  75922      Perl_pp_leavesub:sub-return   BEGIN
  19       0  75915       Perl_pp_entersub:sub-entry   outer
  20       0  75915       Perl_pp_entersub:sub-entry   inner
  21       0  75922      Perl_pp_leavesub:sub-return   inner
  22       0  75922      Perl_pp_leavesub:sub-return   outer
  23
  24 =head1 DESCRIPTION
  25
  26 DTrace is a framework for comprehensive system- and application-level
  27 tracing. Perl is a DTrace I<provider>, meaning it exposes several
  28 I<probes> for instrumentation. You can use these in conjunction
  29 with kernel-level probes, as well as probes from other providers
  30 such as MySQL, in order to diagnose software defects, or even just
  31 your application's bottlenecks.
  32
  33 Perl must be compiled with the C<-Dusedtrace> option in order to
  34 make use of the provided probes. While DTrace aims to have no
  35 overhead when its instrumentation is not active, Perl's support
  36 itself cannot uphold that guarantee, so it is built without DTrace
  37 probes under most systems. One notable exception is that Mac OS X
  38 ships a F</usr/bin/perl> with DTrace support enabled.
  39
  40 =head1 HISTORY
  41
  42 =over 4
  43
  44 =item 5.10.1
  45
  46 Perl's initial DTrace support was added, providing C<sub-entry> and
  47 C<sub-return> probes.
  48
  49 =item 5.14.0
  50
  51 The C<sub-entry> and C<sub-return> probes gain a fourth argument: the
  52 package name of the function.
  53
  54 =item 5.16.0
  55
  56 The C<phase-change> probe was added.
  57
  58 =item 5.18.0
  59
  60 The C<op-entry>, C<loading-file>, and C<loaded-file> probes were added.
  61
  62 =back
  63
  64 =head1 PROBES
  65
  66 =over 4
  67
  68 =item sub-entry(SUBNAME, FILE, LINE, PACKAGE)
  69
  70 Traces the entry of any subroutine. Note that all of the variables
  71 refer to the subroutine that is being invoked; there is currently
  72 no way to get ahold of any information about the subroutine's
  73 I<caller> from a DTrace action.
  74
  75     :*perl*::sub-entry {
  76         printf("%s::%s entered at %s line %d\n",
  77                copyinstr(arg3), copyinstr(arg0), copyinstr(arg1), arg2);
  78     }
  79
  80 =item sub-return(SUBNAME, FILE, LINE, PACKAGE)
  81
  82 Traces the exit of any subroutine. Note that all of the variables
  83 refer to the subroutine that is returning; there is currently no
  84 way to get ahold of any information about the subroutine's I<caller>
  85 from a DTrace action.
  86
  87     :*perl*::sub-return {
  88         printf("%s::%s returned at %s line %d\n",
  89                copyinstr(arg3), copyinstr(arg0), copyinstr(arg1), arg2);
  90     }
  91
  92 =item phase-change(NEWPHASE, OLDPHASE)
  93
  94 Traces changes to Perl's interpreter state. You can internalize this
  95 as tracing changes to Perl's C<${^GLOBAL_PHASE}> variable, especially
  96 since the values for C<NEWPHASE> and C<OLDPHASE> are the strings that
  97 C<${^GLOBAL_PHASE}> reports.
  98
  99     :*perl*::phase-change {
 100         printf("Phase changed from %s to %s\n",
 101             copyinstr(arg1), copyinstr(arg0));
 102     }
 103
 104 =item op-entry(OPNAME)
 105
 106 Traces the execution of each opcode in the Perl runloop. This probe
 107 is fired before the opcode is executed. When the Perl debugger is
 108 enabled, the DTrace probe is fired I<after> the debugger hooks (but
 109 still before the opcode itself is executed).
 110
 111     :*perl*::op-entry {
 112         printf("About to execute opcode %s\n", copyinstr(arg0));
 113     }
 114
 115 =item loading-file(FILENAME)
 116
 117 Fires when Perl is about to load an individual file, whether from
 118 C<use>, C<require>, or C<do>. This probe fires before the file is
 119 read from disk. The filename argument is converted to local filesystem
 120 paths instead of providing C<Module::Name>-style names.
 121
 122     :*perl*:loading-file {
 123         printf("About to load %s\n", copyinstr(arg0));
 124     }
 125
 126 =item loaded-file(FILENAME)
 127
 128 Fires when Perl has successfully loaded an individual file, whether
 129 from C<use>, C<require>, or C<do>. This probe fires after the file
 130 is read from disk and its contents evaluated. The filename argument
 131 is converted to local filesystem paths instead of providing
 132 C<Module::Name>-style names.
 133
 134     :*perl*:loaded-file {
 135         printf("Successfully loaded %s\n", copyinstr(arg0));
 136     }
 137
 138 =back
 139
 140 =head1 EXAMPLES
 141
 142 =over 4
 143
 144 =item Most frequently called functions
 145
 146     # dtrace -qZn 'sub-entry { @[strjoin(strjoin(copyinstr(arg3),"::"),copyinstr(arg0))] = count() } END {trunc(@, 10)}'
 147
 148     Class::MOP::Attribute::slots                                    400
 149     Try::Tiny::catch                                                411
 150     Try::Tiny::try                                                  411
 151     Class::MOP::Instance::inline_slot_access                        451
 152     Class::MOP::Class::Immutable::Trait:::around                    472
 153     Class::MOP::Mixin::AttributeCore::has_initializer               496
 154     Class::MOP::Method::Wrapped::__ANON__                           544
 155     Class::MOP::Package::_package_stash                             737
 156     Class::MOP::Class::initialize                                  1128
 157     Class::MOP::get_metaclass_by_name                              1204
 158
 159 =item Trace function calls
 160
 161     # dtrace -qFZn 'sub-entry, sub-return { trace(copyinstr(arg0)) }'
 162
 163     0  -> Perl_pp_entersub                        BEGIN
 164     0  <- Perl_pp_leavesub                        BEGIN
 165     0  -> Perl_pp_entersub                        BEGIN
 166     0    -> Perl_pp_entersub                      import
 167     0    <- Perl_pp_leavesub                      import
 168     0  <- Perl_pp_leavesub                        BEGIN
 169     0  -> Perl_pp_entersub                        BEGIN
 170     0    -> Perl_pp_entersub                      dress
 171     0    <- Perl_pp_leavesub                      dress
 172     0    -> Perl_pp_entersub                      dirty
 173     0    <- Perl_pp_leavesub                      dirty
 174     0    -> Perl_pp_entersub                      whiten
 175     0    <- Perl_pp_leavesub                      whiten
 176     0  <- Perl_dounwind                           BEGIN
 177
 178 =item Function calls during interpreter cleanup
 179
 180     # dtrace -Zn 'phase-change /copyinstr(arg0) == "END"/ { self->ending = 1 } sub-entry /self->ending/ { trace(copyinstr(arg0)) }'
 181
 182     CPU     ID                    FUNCTION:NAME
 183       1  77214       Perl_pp_entersub:sub-entry   END
 184       1  77214       Perl_pp_entersub:sub-entry   END
 185       1  77214       Perl_pp_entersub:sub-entry   cleanup
 186       1  77214       Perl_pp_entersub:sub-entry   _force_writable
 187       1  77214       Perl_pp_entersub:sub-entry   _force_writable
 188
 189 =item System calls at compile time
 190
 191     # 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) }'
 192
 193     lseek                                                           310
 194     read                                                            374
 195     stat64                                                         1056
 196
 197 =item Perl functions that execute the most opcodes
 198
 199     # dtrace -qZn 'sub-entry { self->fqn = strjoin(copyinstr(arg3), strjoin("::", copyinstr(arg0))) } op-entry /self->fqn != ""/ { @[self->fqn] = count() } END { trunc(@, 3) }'
 200
 201     warnings::unimport                                             4589
 202     Exporter::Heavy::_rebuild_cache                                5039
 203     Exporter::import                                              14578
 204
 205 =back
 206
 207 =head1 REFERENCES
 208
 209 =over 4
 210
 211 =item DTrace User Guide
 212
 213 L<http://download.oracle.com/docs/cd/E19082-01/819-3620/index.html>
 214
 215 =item DTrace: Dynamic Tracing in Oracle Solaris, Mac OS X and FreeBSD
 216
 217 L<http://www.amazon.com/DTrace-Dynamic-Tracing-Solaris-FreeBSD/dp/0132091518/>
 218
 219 =back
 220
 221 =head1 SEE ALSO
 222
 223 =over 4
 224
 225 =item L<Devel::DTrace::Provider>
 226
 227 This CPAN module lets you create application-level DTrace probes written in Perl.
 228
 229 =back
 230
 231 =head1 AUTHORS
 232
 233 Shawn M Moore C<sartak@gmail.com>
 234
 235 =cut