Devel::DProfPP - Parse C<Devel::DProf> output


Devel-DProfPP documentation Contained in the Devel-DProfPP distribution.

Index


Code Index:

NAME

Top

Devel::DProfPP - Parse Devel::DProf output

SYNOPSIS

Top

  use Devel::DProfPP;
  my $pp = Devel::DProfPP->new;

  Devel::DProfPP->new(
        file    => "../tmon.out",
        enter   => sub { my ($self, $sub_name)  = shift;
                         my $frame = ($self->stack)[-1];
                         print "\t" x $frame->height, $frame->sub_name;
                       }
  )->parse;

DESCRIPTION

Top

This module takes the output file from Devel::DProf (typically tmon.out) and parses it. By hooking subroutines onto the enter and leave events, you can produce useful reports from the profiling data.

METHODS

Top

new

    new(
        file    => $file,
        enter   => \&entersub_code,
        leave   => \&leavesub_code
    );

Creates a new parser object. All parameters are optional. See below for more information about what the enter and leave hooks can do.

parse

This parses the profiler output, running the enter and leave hooks, and gathering information about subroutine timings.

stack

During the parsing run, $pp-gtstack will return a list of Devel::DProfPP::Frame objects. (See below) These can be examined for the profile timings.

This returns a hash of the header information, whose keys are:

hz

The number of clock cycles per second; the times are measured in cycles and then converted into seconds later.

XS_VERSION

The version of the XS for the profiler.

over_utime
over_stime
over_rtime

The tested overhead of profiling, in user, system and real times. These are in cycles.

over_tests

The number of samples that generated the above overhead; this is usually 2000. So divide over_utime by over_tests and you'll find the user time overhead required to enter a subroutine. Take this off each subroutine enter and leave event, and you'll have the "real" user time of a subroutine call. Devel::DProfPP doesn't do this for you.

rrun_utime
rrun_stime
rrun_rtime

The user, system and real times (in cycles) for the whole program run.

HOOKS

Top

The enter and leave hooks are called every time a subroutine is, predictable, entered or left. In each case, the parser and name of the subroutine are passed in as parameters to the hook, and everything else can be accessed through the parser object and the stack.

FRAME OBJECTS

Top

The following methods are available on a Devel::DProfPP::Frame object:

times

inc_times

cum_times

These return the current execution time for a stack frame individually, for the stack frame and all of its descendants, and for all instances of this code.

These times are given in seconds, but DO NOT include compensation for subroutine enter/leave overheads. If you want to compensate for these, subtract the appropriate overhead value from $pp->header.

height

The height of this stack frame - 1 for the first subroutine call on the stack, 2 for the second, and so on.

sub_name

The fully qualified name of this subroutine.

BUGS

Top

Understanding how dprofpp's overhead compensation code works is Not Easy and has meant that I haven't tried to apply overhead compensation in this module. All the data's there if you want to do it yourself. The numbers produced by Devel::DProf are pseudorandom anyway, so this omission should't make any real difference.

AUTHOR

Top

Simon Cozens is the original author. Currently maintained by Steve Peters, steve@fisharerojo.org

LICENSE

Top

You may distribute this module under the same terms as Perl itself.


Devel-DProfPP documentation Contained in the Devel-DProfPP distribution.
package Devel::DProfPP;
use 5.006;
use strict;
use warnings;
use Carp;
our $VERSION = '1.3';
use constant DUMMY => sub {};
my $magic = "fOrTyTwO";

sub new {
    my $class = shift;
    my %args = @_;
    open my $fh, ($args{file} ||= "tmon.out") 
        or croak "Can't open $args{file}: $!";
    bless {
        fh    => $fh,
        enter => ($args{enter} || DUMMY),
        leave => ($args{leave} || DUMMY),
        stack => [],
        syms  => {},
        cum_times => {}
    }, $class;
}

sub parse {
    my $self = shift;
    $self->_parse_header;
    $self->_parse_body;
}

sub _parse_header {
    my $self = shift;
    my ($hz, $XS_VERSION, $over_utime, $over_stime, $over_rtime);
    my ($over_tests, $rrun_utime, $rrun_stime, $rrun_rtime, $total_marks);
    my $fh = $self->{fh};
    my $head = <$fh>;
    if(!defined $head || $head !~ /$magic/) {
        croak "This isn't really DProf output";
    }

    while (<$fh>) {
        last if /^PART2/;
        eval;
    }
    no strict 'refs';
    $self->{header} = {
        hz => $hz,
        XS_VERSION => $XS_VERSION,
        over_utime => $over_utime, over_stime => $over_stime,
        over_rtime => $over_rtime,
        over_tests => $over_tests,
        rrun_utime => $rrun_utime, rrun_stime => $rrun_stime,
        rrun_rtime => $rrun_rtime,
        total_marks => $total_marks,
    };
}

sub _parse_body {
    my $self = shift;
    my $fh = $self->{fh};

    while (<$fh>) {
        chomp;
        /^\@ ([\da-f]+) (\d+) (\d+)/ && do { $self->_add_times($1,$2,$3);     next;};
        /^\& ([\da-f]+) (\S+) (\S+)/ && do { $self->_introduce_sub($1,$2,$3); next;};
        /^\+ ([\da-f]+)/             && do { $self->_enter($1);               next;};
        /^\- ([\da-f]+)/             && do { $self->_leave($1);               next;};
        /^\+ & (\S+)/           && do { $self->_enter_named($1);         next;};
        /^\- & (\S+)/           && do { $self->_leave_named($1);         next;};
        /^\* ([\da-f]+)/             && do { $self->_goto($1);                next;};
        /^\/ ([\da-f]+)/             && do { $self->_die($1);                 next;};
        die "Didn't expect to see <$_> at this stage of play";
    }
}

sub _add_times {
    my ($self, @times) = @_;
    if (@{$self->{stack}} == 0) {
        # There's an interesting buglet in Devel::DProf/dprofpp that it
        # doesn't actually cater for timing the entire program. So
        # neither do we.
        return
    }
    $self->{stack}[-1]{times}[$_] += $times[$_] for 0..2;
    $self->{cum_times}{$self->{stack}[-1]{sub_name}}[$_] += $times[$_] for 0..2;
    for my $frame (@{$self->{stack}}) {
        $frame->{inc_times}[$_] += $times[$_] for 0..2;
    }
}

sub _introduce_sub {
    my ($self, $num, $pack, $sym) = @_;
    $self->{syms}{$num} = $pack."::".$sym;
}

sub stack { @{$_[0]->{stack}} }

sub header { $_[0]->{header} }

sub _enter { 
    my ($self, $num) = @_;
    my $name = $self->{syms}{$num};
    die "Entering unknown subroutine $num" unless $name;
    $self->_enter_named($name);
}
sub _leave {
    my ($self, $num) = @_;
    my $name = $self->{syms}{$num};
    die "Leaving unknown subroutine $num" unless $name;
    $self->_leave_named($name);
}

sub _goto { 
    my ($self, $num) = @_;
    pop @{$self->{stack}};
    $self->_enter($num);
}
sub _die { goto &_leave }

sub _enter_named {
    my ($self, $sub) = @_;
    my $frame = Devel::DProfPP::Frame->new(
        parent => $self,
        sub_name => $sub,
        times => [0,0,0],
        inc_times => [0,0,0],
        height => ($#{$self->{stack}} + 1)
    );
    push @{$self->{stack}}, $frame;
    $self->{enter}->($self, $sub);
}

sub _leave_named {
    my ($self, $sub) = @_;
    $self->{leave}->($self, $sub);
    pop @{$self->{stack}};
}

1;

package Devel::DProfPP::Frame;

sub new       { 
    my $class = shift;
    bless {@_}, $class;
}

sub times     { map { $_/($_[0]->{parent}{header}{hz})} @{$_[0]->{times}} }
sub inc_times { map { $_/($_[0]->{parent}{header}{hz})} @{$_[0]->{inc_times}} }
sub cum_times {
    my $self = shift;
    map { $_/($self->{parent}{header}{hz}) } 
    @{$self->{parent}{cum_times}{$self->{sub_name}} ||= [0,0,0]};
}
sub height     { $_[0]->{height} }
sub sub_name  { $_[0]->{sub_name} }


1;