perldtrace - Perl's support for DTrace
# 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 outerDTrace 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, system-level probes (such as libc) as well as probes from other providers on the user-level such as MySQL, Perl, Python, 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, macOS, FreeBSD, DragonFLY BSD, NetBSD and Oracle Linux. The similar Linux systemtap instrumentations are not widely used, are more insecure than DTrace and don't work across kernel, system, userland. See https://github.com/agentzh/perl-systemtap-toolkit.
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:::.
Perl's initial DTrace support was added, providing sub-entry and sub-return probes.
The sub-entry and sub-return probes gain a fourth argument: the package name of the function.
The phase-change probe was added.
The op-entry, loading-file, and loaded-file probes were added.
loading-file, loaded-file renamed to load-entry, load-return. Added glob-entry, glob-return, hash-entry, hash-return probes. Added more examples.
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);
}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);
}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));
}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));
}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));
}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));
}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));
}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));
}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"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));
} # 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 # 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 BEGINSee Porting/subs.d for a similar example.
# 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 # 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 # 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 # 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 10073See Porting/op.d for a bigger example, with count() and quantize().
sudo dtrace -s Porting/op.d -c'./miniperl -Ilib -E0'
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 # FETCHTime 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 # DELETESee mydtrace.h for the modes.
# 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 # FETCHMETHtime 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 | 0sum of glob calls:
3 3 # FETCHMETH
1 108 # ADD
2 241 # FETCH
0 300 # INIThttp://www.amazon.com/DTrace-Dynamic-Tracing-Solaris-FreeBSD/dp/0132091518/
This CPAN module lets you create application-level DTrace probes written in Perl.
Shawn M Moore sartak@gmail.com, Reini Urban rurban@cpan.org