1=head1 NAME 2 3perldtrace - 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 26DTrace is a framework for comprehensive system- and application-level 27tracing. Perl is a DTrace I<provider>, meaning it exposes several 28I<probes> for instrumentation. You can use these in conjunction 29with kernel-level probes, as well as probes from other providers 30such as MySQL, in order to diagnose software defects, or even just 31your application's bottlenecks. 32 33Perl must be compiled with the C<-Dusedtrace> option in order to 34make use of the provided probes. While DTrace aims to have no 35overhead when its instrumentation is not active, Perl's support 36itself cannot uphold that guarantee, so it is built without DTrace 37probes under most systems. One notable exception is that Mac OS X 38ships a F</usr/bin/perl> with DTrace support enabled. 39 40=head1 HISTORY 41 42=over 4 43 44=item 5.10.1 45 46Perl's initial DTrace support was added, providing C<sub-entry> and 47C<sub-return> probes. 48 49=item 5.14.0 50 51The C<sub-entry> and C<sub-return> probes gain a fourth argument: the 52package name of the function. 53 54=item 5.16.0 55 56The C<phase-change> probe was added. 57 58=item 5.18.0 59 60The 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 70Traces the entry of any subroutine. Note that all of the variables 71refer to the subroutine that is being invoked; there is currently 72no way to get ahold of any information about the subroutine's 73I<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 82Traces the exit of any subroutine. Note that all of the variables 83refer to the subroutine that is returning; there is currently no 84way to get ahold of any information about the subroutine's I<caller> 85from 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 94Traces changes to Perl's interpreter state. You can internalize this 95as tracing changes to Perl's C<${^GLOBAL_PHASE}> variable, especially 96since the values for C<NEWPHASE> and C<OLDPHASE> are the strings that 97C<${^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 106Traces the execution of each opcode in the Perl runloop. This probe 107is fired before the opcode is executed. When the Perl debugger is 108enabled, the DTrace probe is fired I<after> the debugger hooks (but 109still 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 117Fires when Perl is about to load an individual file, whether from 118C<use>, C<require>, or C<do>. This probe fires before the file is 119read from disk. The filename argument is converted to local filesystem 120paths 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 128Fires when Perl has successfully loaded an individual file, whether 129from C<use>, C<require>, or C<do>. This probe fires after the file 130is read from disk and its contents evaluated. The filename argument 131is converted to local filesystem paths instead of providing 132C<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 Dynamic Tracing Guide 212 213L<http://dtrace.org/guide/preface.html> 214 215=item DTrace: Dynamic Tracing in Oracle Solaris, Mac OS X and FreeBSD 216 217L<https://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 227This CPAN module lets you create application-level DTrace probes written in 228Perl. 229 230=back 231 232=head1 AUTHORS 233 234Shawn M Moore C<sartak@gmail.com> 235 236=cut 237