.\" Automatically generated by Pod::Man 4.14 (Pod::Simple 3.42) .\" .\" Standard preamble: .\" ======================================================================== .de Sp \" Vertical space (when we can't use .PP) .if t .sp .5v .if n .sp .. .de Vb \" Begin verbatim text .ft CW .nf .ne \\$1 .. .de Ve \" End verbatim text .ft R .fi .. .\" Set up some character translations and predefined strings. \*(-- will .\" give an unbreakable dash, \*(PI will give pi, \*(L" will give a left .\" double quote, and \*(R" will give a right double quote. \*(C+ will .\" give a nicer C++. Capital omega is used to do unbreakable dashes and .\" therefore won't be available. \*(C` and \*(C' expand to `' in nroff, .\" nothing in troff, for use with C<>. .tr \(*W- .ds C+ C\v'-.1v'\h'-1p'\s-2+\h'-1p'+\s0\v'.1v'\h'-1p' .ie n \{\ . ds -- \(*W- . ds PI pi . if (\n(.H=4u)&(1m=24u) .ds -- \(*W\h'-12u'\(*W\h'-12u'-\" diablo 10 pitch . if (\n(.H=4u)&(1m=20u) .ds -- \(*W\h'-12u'\(*W\h'-8u'-\" diablo 12 pitch . ds L" "" . ds R" "" . ds C` "" . ds C' "" 'br\} .el\{\ . ds -- \|\(em\| . ds PI \(*p . ds L" `` . ds R" '' . ds C` . ds C' 'br\} .\" .\" Escape single quotes in literal strings from groff's Unicode transform. .ie \n(.g .ds Aq \(aq .el .ds Aq ' .\" .\" If the F register is >0, we'll generate index entries on stderr for .\" titles (.TH), headers (.SH), subsections (.SS), items (.Ip), and index .\" entries marked with X<> in POD. Of course, you'll have to process the .\" output yourself in some meaningful fashion. .\" .\" Avoid warning from groff about undefined register 'F'. .de IX .. .nr rF 0 .if \n(.g .if rF .nr rF 1 .if (\n(rF:(\n(.g==0)) \{\ . if \nF \{\ . de IX . tm Index:\\$1\t\\n%\t"\\$2" .. . if !\nF==2 \{\ . nr % 0 . nr F 2 . \} . \} .\} .rr rF .\" ======================================================================== .\" .IX Title "Profile 3pm" .TH Profile 3pm "2022-10-13" "perl v5.34.0" "User Contributed Perl Documentation" .\" For nroff, turn off justification. Always turn off hyphenation; it makes .\" way too many mistakes in technical documents. .if n .ad l .nh .SH "NAME" Devel::Profile \- tell me why my perl program runs so slowly .SH "SYNOPSIS" .IX Header "SYNOPSIS" .Vb 2 \& perl \-d:Profile program.pl \& less prof.out .Ve .SH "DESCRIPTION" .IX Header "DESCRIPTION" The Devel::Profile 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 information can be used to determine which subroutines are using the most time and which subroutines are being called most often. .PP 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: .PP .Vb 1 \& perl \-d:Profile test.pl .Ve .PP When the script terminates (or periodicly while running, see \s-1ENVIRONMENT\s0) the profiler will dump the profile information to a file called \fIprof.out\fR. This file is human-readable, no additional tool is required to read it. .PP Note: Statistics are kept per sub, not per line. .SH "ENVIRONMENT" .IX Header "ENVIRONMENT" .ie n .IP """PERL_PROFILE_SAVETIME""" 4 .el .IP "\f(CWPERL_PROFILE_SAVETIME\fR" 4 .IX Item "PERL_PROFILE_SAVETIME" How often to save profile data while running, in seconds, 0 to save only at exit. The default is every 2 minutes. .ie n .IP """PERL_PROFILE_FILENAME""" 4 .el .IP "\f(CWPERL_PROFILE_FILENAME\fR" 4 .IX Item "PERL_PROFILE_FILENAME" Filename to save profile data to, default is \fIprof.out\fR .ie n .IP """PERL_PROFILE_DONT_OTHER""" 4 .el .IP "\f(CWPERL_PROFILE_DONT_OTHER\fR" 4 .IX Item "PERL_PROFILE_DONT_OTHER" Time spent running code not in 'subs' (such as naked code in main) won\e't get accounted for in the normal manner. By default, we account for this time in the sub ''. With this variable set, we leave it as 'missing' time. This reduces the effective runtime of the program, and the calculated percentages. .SH "OUTPUT FORMAT" .IX Header "OUTPUT FORMAT" example output: .PP .Vb 4 \& time elapsed (wall): 86.8212 \& time running program: 65.7657 (75.75%) \& time profiling (est.): 21.0556 (24.25%) \& number of calls: 647248 \& \& %Time Sec. #calls sec/call F name \& 31.74 20.8770 2306 0.009053 Configable::init_from_config \& 20.09 13.2116 144638 0.000091 Configable::init_field_from_config \& 17.49 11.5043 297997 0.000039 Configable::has_attr \& 8.22 5.4028 312 0.017317 MonEl::recycle \& 7.54 4.9570 64239 0.000077 Configable::inherit \& 5.02 3.3042 101289 0.000033 MonEl::unique \& [...] .Ve .PP This is a small summary, followed by one line per sub. .IP "time elapsed (wall)" 4 .IX Item "time elapsed (wall)" This is the total time elapsed. .IP "time running program" 4 .IX Item "time running program" This is the amount of time spent running your program. .IP "time profiling" 4 .IX Item "time profiling" This is the amount of time wasted due to profiler overhead. .IP "number of calls" 4 .IX Item "number of calls" This is the total number of subroutine calls your program made. .PP Followed by one line per subroutine. .IP "name" 4 .IX Item "name" The name of the subroutine. .ie n .IP "%Time" 4 .el .IP "\f(CW%Time\fR" 4 .IX Item "%Time" The percentage of the total program runtime used by this subroutine. .IP "Sec." 4 .IX Item "Sec." The total number of seconds used by this subroutine. .IP "#calls" 4 .IX Item "#calls" The number of times this subroutine was called. .IP "sec/call" 4 .IX Item "sec/call" The average number of seconds this subroutines takes each time it is called. .IP "F" 4 .IX Item "F" Flags. .RS 4 .ie n .IP """*""" 4 .el .IP "\f(CW*\fR" 4 .IX Item "*" pseudo-function to account for otherwise unacounted for time. .ie n .IP """?""" 4 .el .IP "\f(CW?\fR" 4 .IX Item "?" At least one call of this subroutine did not return (typically because of an \f(CW\*(C`exit\*(C'\fR, or \f(CW\*(C`die\*(C'\fR). The statistics for it may be slightly off. .ie n .IP """x""" 4 .el .IP "\f(CWx\fR" 4 .IX Item "x" At least one call of this subroutine trapped an exception. The statistics for it may be slightly off. .RE .RS 4 .RE .SH "LONG RUNNING PROGRAMS" .IX Header "LONG RUNNING PROGRAMS" This module was written so that the author could profile a large long-running (daemon) program. Since normally, this program never exited, saving profiling data only at program exit was not an interesting option. This module will save profiling data periodically based on \f(CW$PERL_PROFILE_SAVETIME\fR, or the program being profiled can call \f(CW\*(C`DB::save()\*(C'\fR at any time. This allows you to watch your profiling data while the program is running. .PP The above program also had a very large startup phase (reading config files, building data structures, etc), the author wanted to see profiling data for the startup phase, and for the running phase separately. The running program can call \f(CW\*(C`DB::reset()\*(C'\fR to save the profiling data and reset the statistics. Once reset, only \*(L"stuff\*(R" that happens from that point on will be reflected in the profile data file. .PP By default, reset is attached to the signal handler for \f(CW\*(C`SIGUSR2\*(C'\fR. Using a perl built with \*(L"safe signal handling\*(R" (5.8.0 and higher), you may safely send this signal to control profiling. .SH "BUT I WANT INCLUSIVE TIMES NOT EXCLUSIVE TIMES" .IX Header "BUT I WANT INCLUSIVE TIMES NOT EXCLUSIVE TIMES" Please see the spin-off module Devel::DProfLB. .SH "BUGS" .IX Header "BUGS" Some buggy \s-1XS\s0 based perl modules can behave erroneously when run under the perl debugger. Since Devel::Profile uses the perl debugger interfaces, these modules will also behave erroneously when being profiled. .PP There are no known bugs in this module. .SH "LICENSE" .IX Header "LICENSE" This software may be copied and distributed under the terms found in the Perl \*(L"Artistic License\*(R". .PP A copy of the \*(L"Artistic License\*(R" may be found in the standard Perl distribution. .SH "SEE ALSO" .IX Header "SEE ALSO" .Vb 2 \& Yellowstone National Park. \& Devel::DProfLB .Ve .SH "AUTHOR" .IX Header "AUTHOR" Jeff Weisberg \- http://www.tcp4me.com/