DTrace and Perl
After reading Bryan's DTrace and PHP and DTrace and PHP, demonstrated blog entries, I thought I'd better have a crack at doing the same for Perl - after all, anything PHP can do, Perl can do better - right? ;-)
I posted a question on the perl5-porters list about the best way of doing this for Perl, and Dave Mitchell kindly stepped up to help - many thanks to Dave, and he should take most of the credit for figuring out how best to do this.
The PHP DTrace probes instrument the function entry and return points within a PHP script so I thought I'd do the same for Perl. After some to-and-fro-ing with Dave it became apparent that the easiest way was to add DTrace probes to the PUSHSUB and POPSUB macros. As the names suggest, these are called each time a Perl subroutine is entered and exited. This doesn't get all of the potential entry points, for example eval and require but it's a good start, at least for the purposes of prototyping. The first step is to define the DTrace probes that we will be using:
provider perl {
probe sub__entry(char*, char*, int);
probe sub__return(char*, char*, int);
};
The arguments are the sub name, the filename and line number. Here's the changes that are required to cop.h for the PUSHSUB case:
DTRACE_PROBE3(perl, sub__entry, GvENAME(CvGV(cv)), \
CopFILE((COP*)CvSTART(cv)), CopLINE((COP*)CvSTART(cv)));
The fiddly bits are the dereferencing of the current cv to extract the sub name, file name and line number. The next bit is to hack Makefile to call dtrace to postprocess the object files before building libperl.so. This builds an extra object file which we then need to include in the file list used to build libperl.so:
$(LIBPERL): $& perl$(OBJ_EXT) $(obj) $(LIBPERLEXPORT)
dtrace -G -s dtrace.d -o dtrace.o $(obj) miniperlmain.o perl.o
$(LD) -o $@ $(SHRPLDFLAGS) perl$(OBJ_EXT) $(obj) dtrace.o $(libs)
Job done. There are a couple of caveats however - firstly, adding the probes has a worst-case performance hit of about 5% even when they aren't enabled. The hit depends on what you are doing in your script - the worst case is for a script that does nothing but call an empty sub. The DTrace probes themselves are NOP'd out when they are inactive, but the code used to calculate the sub name, file name and line number and put them on the stack is still executed even when DTrace is inactive. I've discussed this with the DTrace crew and a way to minimise the overhead is to use a DTrace translator - a shim that sits between the application and the DTrace script and gives a stable view of application data strucures. This would take a pointer to the current cv and do the various dereferencing ops to get the sub name, file name and line number only when the probe was actually active rather than all the time, as in the prototype. This is a good idea not just because of the performance improvement, but also because it means that we can provide a stable API that will be immune to changes in the perl interpreter.
The second caveat is that at the moment some tests in the perl test suite fail with the DTrace macros inserted. Most of these happen because the object files that go into some of the extensions aren't postprocessed with DTrace, so if the extension uses the modified PUSHSUB and POPSUB macros it will fail. Two solutions spring to mind - either modify MakeMaker so that module objects are postprocessed with DTrace, or conditionally add the DTrace probes only when compiling libperl. Overall, I think I prefer the second option, at least as a first pass option.
Anyway, without further ado I present a simple example of it in use. The following D script aggregates page faults by the sub that generated them. Page faults that are caused by the perl interpreter when it isn't actually executing perl code (e.g. during startup) are aggregated under PERL
#pragma D option quiet
BEGIN
{
self->sub = "PERL";
self->file = "PERL";
}
perl$target:::sub-entry
{
self->sub = copyinstr(arg0);
self->file = copyinstr(arg1);
}
perl$target:::sub-return
{
self->sub = "PERL";
self->file = "PERL";
}
vminfo:::maj_fault,
vminfo:::zfod,
vminfo:::as_fault
/self->sub != 0/
{
@pf[self->sub, self->file] = count();
}
END
{
printa("%@8d %-20s %s\n", @pf);
}
And here is the output when run on pod2text perl.pod:
1 import /demo/lib/Exporter.pm
1 import /demo/lib/strict.pm
1 import /demo/lib/warnings/register.pm
1 output /demo/lib/Pod/Text.pm
2 GetOptions /demo/lib/Getopt/Long.pm
2 bits /demo/lib/strict.pm
2 interpolate /demo/lib/Pod/Parser.pm
2 seq_c /demo/lib/Pod/Text.pm
2 wrap /demo/lib/Pod/Text.pm
4 as_heavy /demo/lib/Exporter.pm
6 verbatim /demo/lib/Pod/Text.pm
8 BEGIN /demo/lib/Pod/Select.pm
8 BEGIN /demo/lib/Pod/Usage.pm
10 BEGIN /demo/lib/Pod/Text.pm
11 import /demo/lib/vars.pm
13 BEGIN /demo/lib/Pod/Parser.pm
18 BEGIN /demo/lib/vars.pm
25 BEGIN pod/pod2text
28 BEGIN /demo/lib/Getopt/Long.pm
51 BEGIN /demo/lib/warnings.pm
1580 PERL PERL
Of course that's just a really simplistic sample, the full power of DTrace can be used to find out exactly what your perl script is doing sub-by-sub, whether it be in libperl, libc or the kernel itself. Here's an example which shows which perl subs result in kernel locks being taken, the output is for the same pod2text perl.pod command. If you want to know what all the scary numbers mean, the DTrace lockstat provider documentation explains all.
1 adaptive BEGIN /demo/lib/Symbol.pm
1 adaptive ConfigDefaults /demo/lib/Getopt/Long.pm
1 adaptive DESTROY /demo/lib/Config.pm
1 adaptive FindOption /demo/lib/Getopt/Long.pm
1 adaptive MAIN pod/pod2text
1 adaptive TIEHASH /demo/lib/Config.pm
1 adaptive _pop_input_stream /demo/lib/Pod/Parser.pm
1 adaptive _push_input_stream /demo/lib/Pod/Parser.pm
1 adaptive begin_input /demo/lib/Pod/Parser.pm
1 adaptive begin_pod /demo/lib/Pod/Parser.pm
1 adaptive cmd_back /demo/lib/Pod/Text.pm
1 adaptive cmd_over /demo/lib/Pod/Text.pm
1 adaptive config /demo/lib/Getopt/Long.pm
1 adaptive end_input /demo/lib/Pod/Parser.pm
1 adaptive end_pod /demo/lib/Pod/Parser.pm
1 adaptive export /demo/lib/Exporter.pm
1 adaptive import /demo/lib/Config.pm
1 adaptive import /demo/lib/Getopt/Long.pm
1 adaptive initialize /demo/lib/Pod/Parser.pm
1 adaptive initialize /demo/lib/Pod/Text.pm
1 adaptive new /demo/lib/Pod/Parser.pm
1 adaptive parse_from_file /demo/lib/Pod/Parser.pm
1 adaptive parse_from_filehandle /demo/lib/Pod/Parser.pm
1 adaptive was_cutting /demo/lib/Pod/InputObjects.pm
2 adaptive BEGIN /demo/lib/Config.pm
2 adaptive BEGIN /demo/lib/Exporter/Heavy.pm
2 adaptive BEGIN /demo/lib/File/Spec.pm
2 adaptive Configure /demo/lib/Getopt/Long.pm
2 adaptive gensym /demo/lib/Symbol.pm
2 spin import /demo/lib/vars.pm
2 spin interpolate /demo/lib/Pod/Parser.pm
2 spin seq_c /demo/lib/Pod/Text.pm
2 spin verbatim /demo/lib/Pod/Text.pm
3 adaptive BEGIN /demo/lib/File/Spec/Unix.pm
3 adaptive BEGIN /demo/lib/Pod/InputObjects.pm
3 adaptive BEGIN /demo/lib/Pod/ParseLink.pm
3 spin __ANON__ /demo/lib/Pod/Parser.pm
3 spin input_file /demo/lib/Pod/Parser.pm
3 spin parse_text /demo/lib/Pod/Parser.pm
3 spin preprocess_line /demo/lib/Pod/Parser.pm
3 spin wrap /demo/lib/Pod/Text.pm
4 adaptive BEGIN /demo/lib/constant.pm
4 adaptive mkMask /demo/lib/warnings/register.pm
4 adaptive unimport /demo/lib/strict.pm
6 spin new /demo/lib/Pod/InputObjects.pm
7 adaptive cmd_head2 /demo/lib/Pod/Text.pm
8 adaptive seq_f /demo/lib/Pod/Text.pm
9 adaptive import /demo/lib/constant.pm
9 spin as_heavy /demo/lib/Exporter.pm
11 adaptive cmd_head1 /demo/lib/Pod/Text.pm
12 adaptive ParseOptionSpec /demo/lib/Getopt/Long.pm
12 adaptive cmd_item /demo/lib/Pod/Text.pm
12 adaptive item /demo/lib/Pod/Text.pm
12 spin BEGIN /demo/lib/Pod/Select.pm
15 adaptive seq_i /demo/lib/Pod/Text.pm
18 adaptive heading /demo/lib/Pod/Text.pm
18 adaptive import /demo/lib/warnings/register.pm
18 spin BEGIN /demo/lib/Pod/Usage.pm
26 spin BEGIN /demo/lib/Pod/Text.pm
32 adaptive command /demo/lib/Pod/Text.pm
33 adaptive GetOptions /demo/lib/Getopt/Long.pm
34 adaptive seq_c /demo/lib/Pod/Text.pm
35 adaptive left_delimiter /demo/lib/Pod/InputObjects.pm
38 adaptive seq_b /demo/lib/Pod/Text.pm
39 adaptive _infer_text /demo/lib/Pod/ParseLink.pm
39 adaptive _parse_section /demo/lib/Pod/ParseLink.pm
39 adaptive file_line /demo/lib/Pod/InputObjects.pm
39 adaptive parselink /demo/lib/Pod/ParseLink.pm
39 adaptive seq_l /demo/lib/Pod/Text.pm
42 spin BEGIN /demo/lib/Getopt/Long.pm
42 spin BEGIN /demo/lib/Pod/Parser.pm
42 spin BEGIN pod/pod2text
57 adaptive reformat /demo/lib/Pod/Text.pm
57 adaptive textblock /demo/lib/Pod/Text.pm
92 adaptive wrap /demo/lib/Pod/Text.pm
96 spin BEGIN /demo/lib/vars.pm
99 adaptive import /demo/lib/Exporter.pm
99 adaptive verbatim /demo/lib/Pod/Text.pm
100 adaptive import /demo/lib/strict.pm
104 adaptive output_handle /demo/lib/Pod/Parser.pm
111 adaptive as_heavy /demo/lib/Exporter.pm
113 adaptive interior_sequence /demo/lib/Pod/Text.pm
113 adaptive parse_tree /demo/lib/Pod/InputObjects.pm
114 adaptive __ANON__ /demo/lib/Pod/Parser.pm
119 adaptive cutting /demo/lib/Pod/Parser.pm
119 adaptive parse_paragraph /demo/lib/Pod/Parser.pm
119 adaptive preprocess_paragraph /demo/lib/Pod/Text.pm
120 adaptive output /demo/lib/Pod/Text.pm
126 adaptive top /demo/lib/Pod/InputObjects.pm
127 adaptive input_file /demo/lib/Pod/Parser.pm
127 adaptive parse_text /demo/lib/Pod/Parser.pm
133 spin BEGIN /demo/lib/warnings.pm
148 adaptive right_delimiter /demo/lib/Pod/InputObjects.pm
159 adaptive interpolate /demo/lib/Pod/Parser.pm
162 adaptive bits /demo/lib/strict.pm
167 adaptive BEGIN /demo/lib/Pod/Select.pm
181 adaptive _set_child2parent_links /demo/lib/Pod/InputObjects.pm
183 adaptive cmd_name /demo/lib/Pod/InputObjects.pm
183 adaptive nested /demo/lib/Pod/InputObjects.pm
220 adaptive BEGIN /demo/lib/Pod/Usage.pm
239 adaptive children /demo/lib/Pod/InputObjects.pm
275 adaptive BEGIN /demo/lib/Pod/Text.pm
328 adaptive BEGIN /demo/lib/Pod/Parser.pm
352 adaptive DESTROY /demo/lib/Pod/InputObjects.pm
352 adaptive _unset_child2parent_links /demo/lib/Pod/InputObjects.pm
437 adaptive preprocess_line /demo/lib/Pod/Parser.pm
455 adaptive import /demo/lib/vars.pm
474 adaptive new /demo/lib/Pod/InputObjects.pm
496 adaptive BEGIN /demo/lib/vars.pm
643 adaptive append /demo/lib/Pod/InputObjects.pm
670 adaptive BEGIN pod/pod2text
695 adaptive BEGIN /demo/lib/Getopt/Long.pm
1243 adaptive BEGIN /demo/lib/warnings.pm
2946 spin PERL PERL
51019 adaptive PERL PERL
Re: DTrace and Perl
- I agree with you when you say it's difficult, but the dtrace guys seemed to thing it was do-able, I defer to their superior know-how ;-)
- The performance impact will be the same in either case. We need to modify PUSHSUB as the perl interpreter enters subroutines from several different places, and indeed some XSUB modules do the same thing.
- Yes, the Makefile does need to be LP32/LP64 aware. We probably also need to modify MakeMaker so that it too uses dtrace to postprocess object files, otherwise perl XSUB modules won't be dtraceable.
- Perl doesn't use the C stack for storing arguments to subs, and perl data structures implement polymorphism in C (!) so we'd be into copyin pointer chasing in a big way.