Profile(3pm)

💖 Profile(3pm) 💖

okay bestie, so this is a page from the User Contributed Perl Documentation section and honestly? it's a whole vibe. it's called Devel::Profile and it's here to answer the eternal question. let's get into it 🫶

---

✨ NAME ✨

Devel::Profile — tell me why my perl program runs so slowly 😭

like literally. that's the whole job. slowness detective work. periodt.

---

🌸 SYNOPSIS 🌸

perl -d:Profile program.pl
less prof.out

two lines. that's it. that's the whole glow-up. 💅

---

🦋 DESCRIPTION 🦋

so the Devel::Profile package is a Perl code profiler. what it does is collect info about how long a Perl script takes to execute, and how long all the subs inside that script take too. you use that info to figure out which subroutines are eating the most time, and which ones are getting called the most often. it's giving receipts. it's giving data. 🔥

to profile a Perl script, you run the perl interpreter with the -d debugging switch. yes, the profiler literally rides on the debugging hooks — it's a debugger girlie at heart. so to profile a script called test.pl, you'd run this:

perl -d:Profile test.pl

when your script terminates (or periodically while it's still running — peep the ENVIRONMENT section bestie), the profiler dumps all that profile info into a file called prof.out. and the best part? that file is human-readable. no extra tool needed. you just... read it. iconic. ✨

Note: Statistics are kept per sub, not per line.

like, per sub. not per line. don't come for me, that's just how it is. 💀

---

🎀 ENVIRONMENT 🎀

• PERL_PROFILE_SAVETIME — how often to save profile data while the program is running, in seconds. set it to 0 and it'll save only at exit. the default is every 2 minutes.
• PERL_PROFILE_FILENAME — the filename to save profile data to. default is prof.out.
• PERL_PROFILE_DONT_OTHER — okay so time spent running code that is not in 'subs' (like naked code in main) won't get accounted for in the normal manner. by default, we account for this time in the sub <other>. with this variable set, we leave it as 'missing' time. heads up: this reduces the effective runtime of the program, and the calculated percentages. 📉 so like, know what you're asking for, bestie.

---

🌈 OUTPUT FORMAT 🌈

example output, she's pretty:

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
[...]

so what you're looking at is a small summary up top, followed by one line per sub. let me break the whole thing down for you:

• time elapsed (wall) — this is the total time elapsed.
• time running program — this is the amount of time spent running your program.
• time profiling — this is the amount of time wasted due to profiler overhead. yeah, the profiler costs you. it's the price of knowledge. 😔
• number of calls — this is the total number of subroutine calls your program made.

and then, one line per subroutine:

• name — the name of the subroutine.
• %Time — the percentage of the total program runtime used by this subroutine.
• Sec. — the total number of seconds used by this subroutine.
• #calls — the number of times this subroutine was called.
• sec/call — the average number of seconds this subroutine takes each time it is called.

and then there's F — that's Flags, and these little letters matter, so listen up:

• * — pseudo-function to account for otherwise unaccounted for time.
• ? — at least one call of this subroutine did not return (typically because of an exit, or die). the statistics for it may be slightly off. 🫠
• x — at least one call of this subroutine trapped an exception. the statistics for it may be slightly off. also 🫠

---

👑 LONG RUNNING PROGRAMS 👑

okay so the lore of this module: it was written so the author could profile a large long-running (daemon) program. and here's the thing — since normally that program never exits, saving profiling data only at program exit was not an interesting option. like at all. so instead, this module will save profiling data periodically based on $PERL_PROFILE_SAVETIME, or the program being profiled can call DB::save() at any time. this means you can literally watch your profiling data while the program is running. live. streaming. main character behavior. 📺✨

the above program also had a very large startup phase (reading config files, building data structures, etc), and the author wanted to see the profiling data for the startup phase and for the running phase separately. so: the running program can call DB::reset() to save the profiling data and reset the statistics. once reset, only stuff that happens from that point on will be reflected in the profile data file. clean slate, new era. 🦋

by default, reset is attached to the signal handler for SIGUSR2. and if you're using a perl built with "safe signal handling" (5.8.0 and higher), you may safely send this signal to control profiling. slay. 🫶

---

💅 BUT I WANT INCLUSIVE TIMES NOT EXCLUSIVE TIMES 💅

please see the spin-off module Devel::DProfLB. she's got what you need. go look. 👀

---

💀 BUGS 💀

some buggy XS based perl modules can behave erroneously when run under the perl debugger. and since Devel::Profile uses the perl debugger interfaces, those modules will also behave erroneously when being profiled. so if something's weird, it might not be this module's fault. it's giving collateral damage. 😭

there are no known bugs in this module.

fr fr. none. zero. the author said what she said.

---

🌟 LICENSE 🌟

this software may be copied and distributed under the terms found in the Perl Artistic License.

a copy of the Artistic License may be found in the standard Perl distribution. 💖

---

🔥 SEE ALSO 🔥

Yellowstone National Park.
Devel::DProfLB

(yes, Yellowstone National Park. no we are not elaborating. iykyk 🌲🌋)

---

🫶 AUTHOR 🫶

Jeff Weisberg — http://www.tcp4me.com/

---

aaaand that's the whole page bestie ✨ this one shipped as part of perl v5.36.0, dated 2022-10-13, and it's Profile(3pm) — go profile something and find out why it's slow. mwah. 💋🌺