DTrace provides powerful tracing abilities, combined with perl's support for user defined trace points gives powerful insight into Perl.
These are the slides from my talk at FOSDEM.
The slides with demos won't make much sense without some notes, so the below are expanded notes.
Slide 2
SystemTap is similar to DTrace and is source compatible through a compatibility layer for the userspace probes Perl provides with its Dtrace support.
Technically it should work on any Linux, but unfortunately the required kernel patch (uprobes) is only in Red Hat based distributions, so without kernel patching you’re limited to RHEL/CentOS and Fedora. Also this doesn’t work out of the box on any version of RHEL as the version of SystemTap provided has an issue in usdt support; needs SystemTap from git.
It’s also worth pointing out the only code that can be shared between DTrace and SystemTap is the probes, which in the case are perl are provided by perl itself -- so your scripts will be different.
Slide 4
First of all you need a version of perl with DTrace support.
Perl natively gained DTrace support in 5.10.1. It needs to be enabled at configure time.
The default system provided Perl doesn’t normally have DTrace probes compiled in (Mac OS X is the only thing I know of that ships with DTrace by default).
DTrace doesn’t break ABI compatibility so it is possible to recompile the system perl without needing to recompile everything.
Slide 6
Although the perl shipped with OSX has DTrace support but doesn’t know about this.
Slide 7
Once you’ve enabled DTrace support, the important thing is the probes – when perl tells DTrace something interesting happened.
You are told when you enter a subroutine and when you return; a basic building block but allows much customisation.
Slide 8
The simplest place to start is a DTrace script that prints the sub that is called:
#!/usr/sbin/dtrace -qs
perl$target:::sub-entry {
printf("-> %s\n", copyinstr(arg0));
}
Save this to a file called demo1.d and chmod +x demo1.d, then grab my example script demo1.pl and run:
sudo ./demo1.d -c "perl demo1.pl"
The output should be:
hi # Output from the script
-> hello # Output from DTrace showing the function that was called
(Note that perl above needs to be the full name of the actual perl binary. On Mac OS X this should be for example perl5.10.0 as /usr/bin/perl actually wraps two different versions of perl.)
Slide 9
A slightly more advanced version of the previous slide, use the files demo1a.d and demo1a.pl.
In a way this is similar to the debugger's support for AutoTrace, e.g.:
PERLDB_OPTS="NonStop=1 AutoTrace=1 frame=2" perl −d program.pl
However the debugger actually prints each line as it executes, whereas the DTrace example prints each function as it is entered.
Using the perl debugger changes the behaviour of Perl in several ways whereas DTrace has minimal impact.
Slide 10
You might have noticed I used “arg0” in the previous example without explaining it. It only looked at the subroutine name, there’s actually a bunch of arguments passed to the probe.
The next demo is perl-trace-all.d and the demo program moose.pl. This literally prints out each function call and where it is located:
sudo ./perl-trace-all.d -c "perl moose.pl"
This produces a huge amount of output, basically everything moose did behind the scenes while compiling your code.
Therefore there's a version of this script (perl-trace.d) that filters out the arguments (note the rather odd calling convention):
sudo ./perl-trace.d -c "perl moose.pl" '"moose.pl"' '"test"'
-> test (accessor test defined at moose.pl:11)
<- test (accessor test defined at moose.pl:11)
-> test (accessor test defined at moose.pl:11)
-> Str (.../Moose/Util/TypeConstraints/OptimizedConstraints.pm:21)
<- Str (.../Moose/Util/TypeConstraints/OptimizedConstraints.pm:21)
<- test (accessor test defined at moose.pl:11)
-> test (accessor test defined at moose.pl:11)
<- test (accessor test defined at moose.pl:11)
This says to filter to everything called from a subroutine or method called test in a file called moose.pl. (This script could be much nicer after 5.14 provides the package name :) ).
Slide 11
Attaching to a process is where the real power of DTrace comes in. Have you ever found a process stuck in a loop and had no idea why?
You could attach with gdb, but that can be risky in production environments (and not all sysadmins are comfortable with using gdb).
Grab demo2.pl, this is an AnyEvent using script. It happens to be an infinite loop.
perl demo2.pl&
sudo ./perl-trace-all.d -p [the pid your shell prints]
You'll see this is stuck in an infinite loop and where. Don't forget to kill %1.
Slide 12
dtruss is Truss implemented in DTrace (truss basically like strace on Linux). I have customised dtruss slightly to notice which Perl function called a system call.
Grab demo3.pl and my custom dtruss.
perl demo3.pl&
dtruss.sh -p [the pid your shell printed]
This will show demo3 is in a loop calling gettimeofday from demo3.pl:foo. Don't forget to kill %1.
gettimeofday(0x7FFF5FBFF670, 0x0, 0x1FA1) = 1296994916 0 [demo3.pl:foo]
gettimeofday(0x7FFF5FBFF670, 0x0, 0x1FA1) = 1296994916 0 [demo3.pl:foo]
(Actually this is a very naïve implementation, XS code and other libraries won’t be reported -- although there’s no reason such a thing couldn’t be done with DTrace.)
Slide 13
This demo showed which function was responsible for malloc, using perl-malloc.d:
sudo ./perl-malloc.d -c "perl moose.pl"
Slide 14
Perl underneath compiles to ops. B::Concise is a useful way to find out the ops a particular piece of code compiles into.
NYTProf works at an op level, so it is much lower level than the current DTrace support, however each op is implemented by a C function, which DTrace can intercept.
Slide 15
For example Perl_pp_match is the op that implements regexp matching. By hooking this combined with the sub-entry and sub-return probes we can time how much time each function spends in regular expression matching.
Grab perl-match.d and re2-bench.pl:
sudo ./perl-match.d -c "perl re2-bench.pl /usr/share/doc/postfix/TLS_README"
[Note this needs re::engine::RE2 installed. The file you match on doesn't really matter, the postfix file just happened to be something around on my system.]
The output of this script needs some explanation, it compares the runtime speeds of RE2 with Perl regular expressions. You'll see below the two different timings are shown. If you uncomment the calls to subname in the script you can get these traces in separate charts.
dtrace: script './perl-match.d' matched 11 probes
Rate re re2
re 35.2/s -- -99%
re2 2439/s 6827% --
dtrace: pid 74334 has exited
[..removed core Perl stuff..]
re2-bench.pl __ANON__
value ------------- Distribution ------------- count
131072 | 0
262144 |@@@@@@@@@@@@@@@@@@@@ 999
524288 | 1
1048576 | 0
2097152 | 0
4194304 | 0
8388608 | 0
16777216 |@@@@@@@@@@@@@@@@@@ 890
33554432 |@ 36
67108864 |@ 30
134217728 | 17
268435456 | 9
536870912 | 11
1073741824 | 6
2147483648 | 1
4294967296 | 0