Devel::DProf - phpMan

Devel::DProf(3pm) Perl Programmers Reference Guide Devel::DProf(3pm)

NAME
Devel::DProf - a Perl code profiler

SYNOPSIS
perl5 -d:DProf test.pl

DESCRIPTION
The Devel::DProf package is a Perl code profiler. This will collect information on
the execution time of a Perl script and of the subs in that script. This informa-
tion can be used to determine which subroutines are using the most time and which
subroutines are being called most often. This information can also be used to cre-
ate an execution graph of the script, showing subroutine relationships.

To profile a Perl script run the perl interpreter with the -d debugging switch.
The profiler uses the debugging hooks. So to profile script test.pl the following
command should be used:

perl5 -d:DProf test.pl

When the script terminates (or when the output buffer is filled) the profiler will
dump the profile information to a file called tmon.out. A tool like dprofpp can be
used to interpret the information which is in that profile. The following command
will print the top 15 subroutines which used the most time:

dprofpp

To print an execution graph of the subroutines in the script use the following com-
mand:

dprofpp -T

Consult dprofpp for other options.

PROFILE FORMAT
The old profile is a text file which looks like this:

#fOrTyTwO
$hz=100;
$XS_VERSION=’DProf 19970606’;
# All values are given in HZ
$rrun_utime=2; $rrun_stime=0; $rrun_rtime=7
PART2
+ 26 28 566822884 DynaLoader::import
- 26 28 566822884 DynaLoader::import
+ 27 28 566822885 main::bar
- 27 28 566822886 main::bar
+ 27 28 566822886 main::baz
+ 27 28 566822887 main::bar
- 27 28 566822888 main::bar
[....]

The first line is the magic number. The second line is the hertz value, or clock
ticks, of the machine where the profile was collected. The third line is the name
and version identifier of the tool which created the profile. The fourth line is a
comment. The fifth line contains three variables holding the user time, system
time, and realtime of the process while it was being profiled. The sixth line
indicates the beginning of the sub entry/exit profile section.

The columns in PART2 are:

sub entry(+)/exit(-) mark
app’s user time at sub entry/exit mark, in ticks
app’s system time at sub entry/exit mark, in ticks
app’s realtime at sub entry/exit mark, in ticks
fully-qualified sub name, when possible

With newer perls another format is used, which may look like this:

#fOrTyTwO
$hz=10000;
$XS_VERSION=’DProf 19971213’;
# All values are given in HZ
$over_utime=5917; $over_stime=0; $over_rtime=5917;
$over_tests=10000;
$rrun_utime=1284; $rrun_stime=0; $rrun_rtime=1284;
$total_marks=6;

PART2
@ 406 0 406
& 2 main bar
+ 2
@ 456 0 456
- 2
@ 1 0 1
& 3 main baz
+ 3
@ 141 0 141
+ 2
@ 141 0 141
- 2
@ 1 0 1
& 4 main foo
+ 4
@ 142 0 142
+ & Devel::DProf::write
@ 5 0 5
- & Devel::DProf::write

(with high value of $ENV{PERL_DPROF_TICKS}).

New "$over_*" values show the measured overhead of making $over_tests calls to the
profiler These values are used by the profiler to subtract the overhead from the
runtimes.

The lines starting with "@" mark time passed from the previous "@" line. The lines
starting with "&" introduce new subroutine id and show the package and the subrou-
tine name of this id. Lines starting with "+", "-" and "*" mark entering and exit
of subroutines by ids, and "goto &subr".

The old-style "+"- and "-"-lines are used to mark the overhead related to writing
to profiler-output file.

AUTOLOAD
When Devel::DProf finds a call to an &AUTOLOAD subroutine it looks at the $AUTOLOAD
variable to find the real name of the sub being called. See "Autoloading" in perl-
sub.

ENVIRONMENT
"PERL_DPROF_BUFFER" sets size of output buffer in words. Defaults to 2**14.

"PERL_DPROF_TICKS" sets number of ticks per second on some systems where a replace-
ment for times() is used. Defaults to the value of "HZ" macro.

"PERL_DPROF_OUT_FILE_NAME" sets the name of the output file. If not set, defaults
to tmon.out.

BUGS
Builtin functions cannot be measured by Devel::DProf.

With a newer Perl DProf relies on the fact that the numeric slot of $DB::sub con-
tains an address of a subroutine. Excessive manipulation of this variable may
overwrite this slot, as in

$DB::sub = ’current_sub’;
...
$addr = $DB::sub + 0;

will set this numeric slot to numeric value of the string "current_sub", i.e., to
0. This will cause a segfault on the exit from this subroutine. Note that the
first assignment above does not change the numeric slot (it will mark it as
invalid, but will not write over it).

Another problem is that if a subroutine exits using goto(LABEL), last(LABEL) or
next(LABEL) then perl may crash or Devel::DProf will die with the error:

panic: Devel::DProf inconsistent subroutine return

For example, this code will break under Devel::DProf:

sub foo {
last FOO;
}
FOO: {
foo();
}

A pattern like this is used by Test::More’s skip() function, for example. See
perldiag for more details.

Mail bug reports and feature requests to the perl5-porters mailing list at
<perl5-porters AT perl.org>.