Commit | Line | Data |
---|---|---|
f993ad5b SM |
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 | ||
2b679393 SM |
54 | =item 5.16.0 |
55 | ||
56 | The C<phase-change> probe was added. | |
57 | ||
fe83c362 SM |
58 | =item 5.18.0 |
59 | ||
42b5c62b | 60 | The C<op-entry>, C<loading-file>, and C<loaded-file> probes were added. |
fe83c362 | 61 | |
f993ad5b SM |
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", | |
62b5d8c0 | 77 | copyinstr(arg3), copyinstr(arg0), copyinstr(arg1), arg2); |
f993ad5b SM |
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", | |
62b5d8c0 | 89 | copyinstr(arg3), copyinstr(arg0), copyinstr(arg1), arg2); |
f993ad5b SM |
90 | } |
91 | ||
2b679393 SM |
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 | ||
fe83c362 SM |
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 | ||
32aeab29 SM |
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 | |
97dd44ee | 130 | is read from disk and its contents evaluated. The filename argument |
32aeab29 SM |
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 | ||
f993ad5b SM |
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 | ||
2b679393 SM |
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 | |
f993ad5b | 196 | |
fe83c362 SM |
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 | ||
f993ad5b SM |
205 | =back |
206 | ||
207 | =head1 REFERENCES | |
208 | ||
209 | =over 4 | |
210 | ||
d2a68ca8 | 211 | =item DTrace Dynamic Tracing Guide |
f993ad5b | 212 | |
d2a68ca8 | 213 | L<http://dtrace.org/guide/preface.html> |
f993ad5b SM |
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 | ||
fe83c362 SM |
221 | =head1 SEE ALSO |
222 | ||
223 | =over 4 | |
224 | ||
225 | =item L<Devel::DTrace::Provider> | |
226 | ||
d2a68ca8 RS |
227 | This CPAN module lets you create application-level DTrace probes written in |
228 | Perl. | |
fe83c362 SM |
229 | |
230 | =back | |
231 | ||
f993ad5b SM |
232 | =head1 AUTHORS |
233 | ||
234 | Shawn M Moore C<sartak@gmail.com> | |
235 | ||
236 | =cut |