http://qs321.pair.com?node_id=216518

dbush has asked for the wisdom of the Perl Monks concerning the following question:

I am currently doing some performance tuning and have a question regarding the output of Dprofpp. I am seeing that the majority of time (40% or more) is being taken up with many thousands of calls to main::BEGIN.

The typical output that I'm getting looks like this:

> dprofpp
Total Elapsed Time = -51.0824 Seconds
  User+System Time = 310.7123 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 44.8   139.2 114.05 843865   0.0000 0.0000  main::BEGIN
 31.3   97.53 97.452  36407   0.0027 0.0027  DBI::st::execute
 22.4   69.62 183.55      4   17.405 45.889  main::ScanBuffer
Snip...

[download]

I had a super search and a look on CPAN. I found the following useful:

  • The CPAN documentation at Devel::DProf
  • Wierd dprofpp results. by dreadpiratepeter
  • The followup by dug seems to indicate that Dprof may be lying but... is it?
  • With Why is perl spending so much time in the BEGIN section? by erabus I thought I had cracked it but... I'm not sure that really answers it. I do not have a BEGIN {} block in my script.

    • One further thing that might be useful are the modules that I'm using:

    use strict;
use DBI qw(:sql_types); 
use Data::Dumper;

    [download]

    ... I mention this as I think the BEGIN block is called by AUTOLOADER when use-ing modules but I'm afraid that I'm not very clear on the details. One thought that I had was that Dprof was counting the BEGIN blocks in the imported modules but not labelling them correctly in the output. Plausible or not?

    Regards,
    Dom.

    Replies are listed 'Best First'.
    Re: Dprof and main::BEGIN
    by broquaint (Abbot) on Nov 29, 2002 at 14:25 UTC
      I am seeing that the majority of time (40% or more) is being taken up with many thousands of calls to main::BEGIN.
      The answer can be found in a recent p5p post by Tim Bunce
      A BEGIN block gets a CV, executes, the CV is freed and another sub is created with the same CV address. The result is that Devel::DProf (for example) will report BEGIN blocks being called many times when in fact it's a different sub. Very frustrating.
      The initial p5p thread starts here.
      HTH

      _________
      broquaint

    		[reply]

        broquaint many thanks for your response.

        From the sounds of things, this effect is unavoidable. Just to clarify my understanding, is a CV an internal data structure? I seem to remember reading something in perlman:perlguts about two letter typedefs before I was scared away.

        Regards,
        Dom.

    		[reply]
          Just to clarify my understanding, is a CV an internal data structure?
          A CV is an internal representation of a subroutine (see. Code Value). It's a typedef of a struct cv which has a pointer to a XPVCV which is a typedef for a struct xpvcv which can be found in cv.h in the perl source code. Simple as that ;)
          HTH

          _________
          broquaint

    		[reply]
          CV is short for Code Value, and is one of perl's internal data types. (It's a sub-class of SV, the Scalar Value, if you can think of purely C code as subclassing anything :)
    		[reply]

    Back to Seekers of Perl Wisdom