| 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 |