Tag: solaris

Blead Perl DTrace probes

I’ve ported my additional DTrace probes to blead perl, adding the following probes

  • new-sv and del-sv to track Perl allocations,
  • main-enter and main-exit to show what part of Perl’s execution phase we’re in
  • load-module-entry and load-module-return to instrument use, require, do.

I’ve also started to document the probes at http://wikis.sun.com/display/DTrace/perl+Provider
To use the patch,

  1. get bleadperl:
    1. rsync -avz –exclude .svn/ –delete rsync://ftp.linux.activestate.com/perl-current/ bleadperl
  2. apply the patch:
  3. cd bleadperl ; patch ../bleadperl.diff
  4. run configure with dtrace enabled:
    1. ./Configure -de -Dusedevel -Dinc_version_list=none -Dprefix=/usr/local/bleadperl/ -Dldflags=-Dman3ext=3pm -Duseithreads -Duseshrplib -Uversiononly -Dusedtrace -Doptimize=-g
  5. make
  6. make test
  7. make install
  8. run./perl.d (also found at http://distributedinformation.com/DTrace/ ) and then run whatever Perl code you want to instrument.

Examining ‘use’ and ‘require’ with Perl Dtrace

Given the following functionally similar Perl modules, I was curious what the internal Perl differences in execution were.

To recap – (from PerlDoc)

  • Perl use – Imports some semantics into the current package from the named module – It is exactly equivalent to 
        BEGIN { require Module; Module->import( LIST ); }
  • Perl require – demands that a library file be included if it hasn’t already been included. There is pseudocode there to suggest that a previously required module (successful or not) would just return the previous result

So given a set of modules that don’t define an import() function, one would expect that there would be little difference.

use Module require Module

main.pl

use Module1;
use Module2;
use Module1; # add multiple use's to attempt to simulate having many use statements throughout many modules
use Module1;
use Module1;
use Module1;
use Module1;
use Module1;

BEGIN {
print "::BEGIN\n";
}

Module1::printit();

Module1.pm

package Module1;

BEGIN {
my $test = ”;

print “Module1::BEGIN\n";
}
sub printit {
print "Module1::printit\n";

}
1;

Module2.pm

package Module2;
use Module1;

BEGIN {
print “Module2::BEGIN\n”;
}

sub printit {
print “Module2::printit\n”;
}

1;

main.pl

require Module1;
require MyOtherBegin;
require Module1;
require Module1;
require Module1;
require Module1;
require Module1;
require Module1;

BEGIN {
print "::BEGIN\n";
}

MyBegin::printit();

Module1.pm

package Module1;

BEGIN {
my $test = ”;

print “Module1::BEGIN\n";
}

sub printit {
print “Module1::printit\n";

}
1;

Module2.pm

package Module2;
require Module1;

BEGIN {
print “Module2::BEGIN\n”;
}

sub printit {
print “Module2::printit\n”;
}

1;

program output


bash-3.00$ /usr/local/bin/perl main.pl
Module1::BEGIN
Module2::BEGIN
::BEGIN
Module1::printit

program output


bash-3.00$ /usr/local/bin/perl main.pl
::BEGIN
Module1::BEGIN
Module2::BEGIN
Module1::printit

dtrace output


== perl ==========================================================
perl*::perl_alloc:main-enter
perl*::perl_alloc:main-exit, (0/0) (73 uS)
perl*::perl_construct:main-enter
perl*::perl_construct:main-exit, (12/0) (543 uS)
perl*::perl_parse:main-enter
>> perl*::Perl_utilize:load-module-start (Module1)
>> perl*::Perl_ck_require:load-module-start (Module1)
<< perl*::Perl_ck_require:load-module-end (Module1.pm) (254/2) (3 uS)
--> BEGIN, main.pl
--> BEGIN, Module1.pm
<-- BEGIN, Module1.pm (1/0) (102 uS)
<-- BEGIN, main.pl (60/38) (763 uS)
>> perl*::Perl_utilize:load-module-start (Module2)
>> perl*::Perl_ck_require:load-module-start (Module2)
<< perl*::Perl_ck_require:load-module-end (Module2.pm) (271/16) (2 uS)
--> BEGIN, main.pl
>> perl*::Perl_utilize:load-module-start (Module1)
>> perl*::Perl_ck_require:load-module-start (Module1)
<< perl*::Perl_ck_require:load-module-end (Module1.pm) (31/8) (2 uS)
--> BEGIN, Module2.pm
<-- BEGIN, Module2.pm (0/0) (4 uS)
--> BEGIN, Module2.pm
<-- BEGIN, Module2.pm (1/0) (11 uS)
<-- BEGIN, main.pl (67/47) (399 uS)
>> perl*::Perl_utilize:load-module-start (Module1)
>> perl*::Perl_ck_require:load-module-start (Module1)
<< perl*::Perl_ck_require:load-module-end (Module1.pm) (285/30) (2 uS)
--> BEGIN, main.pl
<-- BEGIN, main.pl (0/0) (3 uS)
>> perl*::Perl_utilize:load-module-start (Module1)
>> perl*::Perl_ck_require:load-module-start (Module1)
<< perl*::Perl_ck_require:load-module-end (Module1.pm) (299/44) (2 uS)
--> BEGIN, main.pl
<-- BEGIN, main.pl (0/0) (3 uS)
>> perl*::Perl_utilize:load-module-start (Module1)
>> perl*::Perl_ck_require:load-module-start (Module1)
<< perl*::Perl_ck_require:load-module-end (Module1.pm) (313/58) (2 uS)
--> BEGIN, main.pl
<-- BEGIN, main.pl (0/0) (3 uS)
>> perl*::Perl_utilize:load-module-start (Module1)
>> perl*::Perl_ck_require:load-module-start (Module1)
<< perl*::Perl_ck_require:load-module-end (Module1.pm) (327/72) (2 uS)
--> BEGIN, main.pl
<-- BEGIN, main.pl (0/0) (3 uS)
>> perl*::Perl_utilize:load-module-start (Module1)
>> perl*::Perl_ck_require:load-module-start (Module1)
<< perl*::Perl_ck_require:load-module-end (Module1.pm) (341/86) (2 uS)
--> BEGIN, main.pl
<-- BEGIN, main.pl (0/0) (3 uS)
>> perl*::Perl_utilize:load-module-start (Module1)
>> perl*::Perl_ck_require:load-module-start (Module1)
<< perl*::Perl_ck_require:load-module-end (Module1.pm) (355/100) (2 uS)
--> BEGIN, main.pl
<-- BEGIN, main.pl (0/0) (3 uS)
--> BEGIN, main.pl
<-- BEGIN, main.pl (1/0) (10 uS)
perl*::perl_parse:main-exit, (373/132) (3464 uS)
perl*::perl_run:main-enter
--> printit, Module1.pm
<-- printit, Module1.pm (0/0) (8 uS)
perl*::perl_run:main-exit, (0/0) (44 uS)
perl*::perl_destruct:main-enter
perl*::perl_destruct:main-exit, (0/5) (20 uS)
total, total (0/0) (4177 uS)Subs returned from:
count totaltime mintime avgtime maxtime allocs deallocs func file
1 8 8 8 8 0 0 printit Module1.pm
1 102 102 102 102 1 0 BEGIN Module1.pm
2 15 4 7 11 1 0 BEGIN Module2.pm
9 1190 3 132 763 128 85 BEGIN main.pl
count totaltime mintime avgtime maxtime allocs deallocs func file

allocations / deallocations (complete program):
(515 / 222) perl

time to run perl: 6389 uS (time on CPU 4177 uS)

dtrace output


== perl ==========================================================
perl*::perl_alloc:main-enter
perl*::perl_alloc:main-exit, (0/0) (71 uS)
perl*::perl_construct:main-enter
perl*::perl_construct:main-exit, (12/0) (583 uS)
perl*::perl_parse:main-enter
>> perl*::Perl_ck_require:load-module-start (Module1)
<< perl*::Perl_ck_require:load-module-end (Module1.pm) (248/2) (3 uS)
>> perl*::Perl_ck_require:load-module-start (Module2)
<< perl*::Perl_ck_require:load-module-end (Module2.pm) (252/2) (2 uS)
>> perl*::Perl_ck_require:load-module-start (Module1)
<< perl*::Perl_ck_require:load-module-end (Module1.pm) (253/2) (1 uS)
>> perl*::Perl_ck_require:load-module-start (Module1)
<< perl*::Perl_ck_require:load-module-end (Module1.pm) (254/2) (2 uS)
>> perl*::Perl_ck_require:load-module-start (Module1)
<< perl*::Perl_ck_require:load-module-end (Module1.pm) (255/2) (1 uS)
>> perl*::Perl_ck_require:load-module-start (Module1)
<< perl*::Perl_ck_require:load-module-end (Module1.pm) (256/2) (1 uS)
>> perl*::Perl_ck_require:load-module-start (Module1)
<< perl*::Perl_ck_require:load-module-end (Module1.pm) (257/2) (2 uS)
>> perl*::Perl_ck_require:load-module-start (Module1)
<< perl*::Perl_ck_require:load-module-end (Module1.pm) (258/2) (1 uS)
--> BEGIN, main.pl
<-- BEGIN, main.pl (1/0) (100 uS)
perl*::perl_parse:main-exit, (285/28) (2319 uS)
perl*::perl_run:main-enter
--> BEGIN, Module1.pm
<-- BEGIN, Module1.pm (1/0) (14 uS)
>> perl*::Perl_ck_require:load-module-start (Module1)
<< perl*::Perl_ck_require:load-module-end (Module1.pm) (69/46) (2 uS)
--> BEGIN, Module2.pm
<-- BEGIN, Module2.pm (1/0) (10 uS)
--> printit, Module1.pm
<-- printit, Module1.pm (0/0) (8 uS)
perl*::perl_run:main-exit, (99/73) (772 uS)
perl*::perl_destruct:main-enter
perl*::perl_destruct:main-exit, (0/13) (36 uS)
total, total (0/0) (3814 uS)Subs returned from:
count totaltime mintime avgtime maxtime allocs deallocs func file
1 8 0 8 8 0 0 printit Module1.pm
1 10 0 10 10 1 0 BEGIN Module2.pm
1 14 0 14 14 1 0 BEGIN Module1.pm
1 100 0 100 100 1 0 BEGIN main.pl
count totaltime mintime avgtime maxtime allocs deallocs func file

allocations / deallocations (complete program):
(399 / 114) perl

time to run perl: 5368 uS (time on CPU 3814 uS)

The (1/0) tuples in braces are counts of allocations and deallocations by the Perl interpreter in in that enter-return pair, and execution times are all using DTrace’s vtimestamp, so are adjusted for time on CPU.

This suggests to me that Perl use and require suffer from the same problems that are encountered when using #include’s inside header files in large scale C and C++, a massive, un-realized parser mess, due to the re-importation of dependencies for the short term convenience of the developer.

While the require output appears better, none the less (looking at the source code for Perl_ck_require) it does more than a nop the second time around (at minimum, its doing a single allocation, and converting the Module name to a File.pm). It is interesting (scary really) that the use case has many more allocations than the require case, but I presume that has to do with the sillyness of importing code into the same namespace several times. That main.pl’s BEGIN is parsed&allocated for 9 times, and Module2:BEGIN is parsed&allocated for twice – is not really what I had in mind.

For those of us working with large scale Perl code (in my case TWiki and Catalyst) it seems that there is not enough clarity, and there are opposing concerns for users that run Perl directly, incurring the parse and allocate steps each time, and those using accelerators such as mod_perl and speedy_cgi, who essentially start at the main-run phase (I think).

Reducing the above examples by removing the use or requires from everywhere except the top level main.pl, still shows an unexpected side effect that the use case has 34 more allocations and 26 deallocations – but… there is less going on. So it is possible, that the inconvenience of needing to manage the Perl module loading at the top level might be worth while, at least until Perl is changed to do what the ‘manual’ implies.

Another interesting side effect of replacing use with require, is that it moves the execution of the BEGIN from the parse phase to the execution phase – again reducing the effectiveness of Perl accelerators, but perhaps more inline with simplistic expectations.

Seems to me its time to move to bleadperl, and see if I can offer a fix.

The above tests are done using the dtrace enabled Perl 5.8.8 that is in my svn repository.

Perl DTrace load-module probe added – see what module is ‘do’, ‘use’ or ‘require’d

With the load-module probe, you can see at what point modules are loaded using ‘do’, ‘use’ or ‘require’.

The following code:

#!/usr/local/bin/perl -w

use strict;

my $initial = "there once was a fish. Its feet were small";
my $post = func($initial);
my $post2 = func($initial);
print "$post\n";

do 'call2.pl';
#eval `cat call2.pl`;
#use CGI::Session;

sub func {
    $_[0] =~ s/there/There/;
    return $_[0];
}

produces the following output:

 == call1.pl ==========================================================
  perl*::perl_alloc:main-enter
  perl*::perl_alloc:main-exit,  (0/0) (56 uS)
  perl*::perl_construct:main-enter
  perl*::perl_construct:main-exit,  (12/0) (624 uS)
  perl*::perl_parse:main-enter
>>>>>>>>>> perl*::Perl_utilize:load-module-start (strict)
>>>>>>>>>> perl*::Perl_ck_require:load-module-start (strict)
<<<<<<<<<< perl*::Perl_ck_require:load-module-end (strict.pm) (3 uS)
>>>>>>>>>> perl*::Perl_ck_require:load-module-start (Carp)
<<<<<<<<<< perl*::Perl_ck_require:load-module-end (Carp.pm) (2 uS)
>>>>>>>>>> perl*::Perl_dofile:load-module-start (call2.pl)
<<<<<<<<<< perl*::Perl_dofile:load-module-end (call2.pl) (3 uS)
  perl*::perl_parse:main-exit,  (299/46) (3069 uS)
  perl*::perl_run:main-enter
>>>>>>>>>> perl*::Perl_utilize:load-module-start (strict)
>>>>>>>>>> perl*::Perl_ck_require:load-module-start (strict)
<<<<<<<<<< perl*::Perl_ck_require:load-module-end (strict.pm) (3 uS)
  perl*::perl_run:main-exit,  (69/45) (533 uS)
  perl*::perl_destruct:main-enter
  perl*::perl_destruct:main-exit,  (0/3) (24 uS)

see my perl5.8 trac for the code -or grab the modified 5.8.8 source from svn

the  perl*::Perl_utilize:load-module-end probe is currently being worked on, and I really would like to see the actual parse component of the load separated out.

A new begining for Perl and DTrace?

I’ve just created a subversion repository with perl 5.8.8, and the accumulated DTrace patches – including the using is-enabled to reduce the performance impact of the Probes when disabled. Byran and I, (and anyone else that would like to help) will be working slowly towards making Perl a first class DTrace citizen over the coming months. Next stop – Perl Guts Illustrated

Of course, we’ll also port it all to Perl 5.10 – the 20th anniversary release 🙂

DTrace, Perl and TWiki – on Solaris

I’ve been promising myself some time to try out DTrace on TWiki’s codebase for over a year. By following Bryan Allen’s
instructions using Richard Dawe’s adaption of Alan Burlison’s work… I now have a Perl 5.8.8 with DTrace probes.

Sounds great, except for one thing…. I now have to learn enough about DTrace to use it 🙂 The patch that Alan and Richard have (or at least their DTrace scripts) seem to require a priori knowledge of the Perl process’ pid… not something thats going to work out for what I want to do.

For a quick test, DTrace -c ./view -s /export/home/sven/src/dtrace/subs-tree.d does show the program flow.

The following is while running some perl scripts – the 2 numbers are their pids.

# dtrace -l | grep -i perl
17803  perl17669        libperl.so                      Perl_pp_sort sub-entry
17804  perl17669        libperl.so                   Perl_pp_dbstate sub-entry
17805  perl17669        libperl.so                  Perl_pp_entersub sub-entry
17806  perl17669        libperl.so                      Perl_pp_last sub-return
17807  perl17669        libperl.so                    Perl_pp_return sub-return
17808  perl17669        libperl.so                     Perl_dounwind sub-return
17809  perl17669        libperl.so                Perl_pp_leavesublv sub-return
17810  perl17669        libperl.so                  Perl_pp_leavesub sub-return
88501  perl17760        libperl.so                      Perl_pp_sort sub-entry
88502  perl17760        libperl.so                   Perl_pp_dbstate sub-entry
88503  perl17760        libperl.so                  Perl_pp_entersub sub-entry
88504  perl17760        libperl.so                      Perl_pp_last sub-return
88505  perl17760        libperl.so                    Perl_pp_return sub-return
88506  perl17760        libperl.so                     Perl_dounwind sub-return
88507  perl17760        libperl.so                Perl_pp_leavesublv sub-return
88508  perl17760        libperl.so                  Perl_pp_leavesub sub-return

so… first ignorant modification – in subs-tree.d, it wants to trace perl$target:::sub-entry – change that to perl*:::sub-entry, and of course, it works exactly as I want – attaches to all subsequent perl process (running my dtrace-perl build) and tells me whats going on. The only caveat being that the DTrace script will only start if there is a Perl process running – the provider is obviously not persistent.

Brilliant!

Should be a fun Christmas holiday adventure – 410 pages of dtrace book, and a myriad of web pages to consume and digest.