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

I've been using DProf to profile my application, to see where the bottlenecks are. I run it, and get the following -
> perl -d:DProf app.pl ... output of script here... > dprofpp tmon.out main::ProcessMinorFrames has 1 unstacked calls in outer Exporter::export_to_level has -1 unstacked calls in outer main::ProcessFile has 1 unstacked calls in outer Exporter::export has -1 unstacked calls in outer AutoLoader::AUTOLOAD has -1 unstacked calls in outer Exporter::Heavy::heavy_export_to_level has 1 unstacked calls in outer DynaLoader::dl_findfile has 1 unstacked calls in outer main::CalculateCRCInfo has 1 unstacked calls in outer Exporter::Heavy::heavy_export has 1 unstacked calls in outer main::ProcessDir has 1 unstacked calls in outer Garbled profile is missing some exit time stamps: main::ProcessDir main::ProcessFile main::ProcessMinorFrames main::CalculateCRCInfo Try rerunning dprofpp with -F.
Even running with the -F option, I still get some errors like that, although I do get a table of performance data, as expected. Any thoughts on why I'm getting those errors? I checked in the manpage, and there's nothing about unstacked calls or exit time stamps.

-- Burvil

Replies are listed 'Best First'.
Re: Errors when using DProf to profile
by BrowserUk (Patriarch) on Mar 29, 2006 at 06:35 UTC

    Here is one of the ways that can cause these messages

    junk.pm

    package junk; use strict; use warnings; use Exporter qw[ import ]; our @ISA = 'Exporter'; our @EXPORT_OK = qw[ test test2 ]; sub test{ print 'test' } sub test2{ print 'test2'; goto &test; } 1;

    junk.pl

    #! perl -slw use strict; use junk qw[ test test2 ]; test; test2;

    Profiling output

    C:\test>perl -d:DProf junk.pl test test2 test C:\test>dprofpp tmon.out junk::test has 1 unstacked calls in outer junk::test2 has -1 unstacked calls in outer Total Elapsed Time = 0.014928 Seconds User+System Time = 0.015928 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 0.00 - -0.000 1 - - strict::bits 0.00 - -0.000 1 - - warnings::BEGIN 0.00 - -0.000 1 - - warnings::import 0.00 - -0.000 2 - - junk::test 0.00 - -0.000 2 - - strict::import 0.00 - -0.000 2 - - Exporter::import 0.00 - -0.000 1 - - junk::test2 0.00 - -0.000 3 - - junk::BEGIN 0.00 - -0.000 2 - - main::BEGIN

    The use of the "magic" goto in subroutine test2(), goto &test, is an optimisation that is sometimes usefully used by packages. It's effect is to transfer control from the first subroutine to the second in such a way as to ensure that when the second subroutine returns, control is transferred directly back to the original caller, rather than back through the first subroutine. This can be used to implement a form of the 'tail call optimisation'.

    As dprof tracks and logs entry and exits to subroutines and then tries to match them when calculating the timing information, this one-way transfer of control confuses it's matching process and the warnings you see reflect that.

    Either ignore the warnings, or use one of the line-by-line profilers which time each line, rather than each subroutine as so do not become confused. They are often more useful, though the profiling process is necessarily much slower.


    Examine what is said, not who speaks -- Silence betokens consent -- Love the truth but pardon error.
    Lingua non convalesco, consenesco et abolesco. -- Rule 1 has a caveat! -- Who broke the cabal?
    "Science is about questioning the status quo. Questioning authority".
    In the absence of evidence, opinion is indistinguishable from prejudice.
      OK, thanks. So I guess if a subroutine doesn't explicitly return a value, would that cause dprof to give an error?

      I'll try Devel::SmallProf to see what happens. I just tried dprof, since it was recommended in PBP.

      -- Burvil

        So I guess if a subroutine doesn't explicitly return a value, would that cause dprof to give an error?

        No it shouldn't. Dprof operates at a level that will see the subroutine return regardless of whether it uses an explicit return statement or not.

        The thing about the goto trick is that the subroutine never returns at all, which Dprof rightly warns as being unusual, althought the goto trick is a specially architected feature of Perl. I guess it would be nice if it could detect the goto and so not report it, but I would imagine that detecting it would be quite difficult to do.

        The chances are that you could just ignore the warnings and the results from dprofpp would be perfectly usable.


        Examine what is said, not who speaks -- Silence betokens consent -- Love the truth but pardon error.
        Lingua non convalesco, consenesco et abolesco. -- Rule 1 has a caveat! -- Who broke the cabal?
        "Science is about questioning the status quo. Questioning authority".
        In the absence of evidence, opinion is indistinguishable from prejudice.
Re: Errors when using DProf to profile
by QM (Parson) on Mar 29, 2006 at 02:41 UTC
    I can't help you with DProf, though I would suggest Devel::SmallProf, and use smallprof.pl to digest it.

    D:S has line by line resolution.

    -QM
    --
    Quantum Mechanics: The dreams stuff is made of

      Devel::FastProf is also available, it is more or less a version of Devel::SmallProf written in C/XS and so much faster, though it doesn't work on Windows.
        Yes, D:S is slow. On the other hand, how often does a program need to be profiled? If D:S makes the program run an order of magnitude slower, that shouldn't be a problem for most situations. I can see it being a problem if it's doing some compute-intensive work, and needing months instead of weeks to finish, but then, it wouldn't be written in Perl, would it?

        Curiosity: Is the output of Devel::FastProf the same as Devel::SmallProf? I wonder if my script will work on both?

        <Off Topic Rant>
        Unfortunately, I'm in a mostly Windoze shop. It's only a Windoze shop because it's convenient, not out of some necessity. But I have a few users, and everything has to be portable to *nix too. The *nix stuff is not administered properly, and depending on which workstation my user is on, s/he may only have Perl 4 available, and other crud like that. Weirdly enough, it's easier to standardize on Windoze here, because they'd rather sling money around than administer *nix machines properly.

        So everyone has XP Pro SP2 on a recent laptop. If we really need some compute power or storage, we have to jump through paperwork hoops, and entertain arguments about whose desk it goes on, etc. (It's usually "I don't want it on my desk, I just want access to it".)
        </Off Topic Rant>

        -QM
        --
        Quantum Mechanics: The dreams stuff is made of

Re: Errors when using DProf to profile
by aufflick (Deacon) on Mar 30, 2006 at 12:41 UTC
    There are many different ways that the different profilers can be tripped up. Fortunately they are not fully overlapping sets, so if one profiler doesn't work another might.

    If Devel::DProf doesn't work I would try Devel::Profiler.

    Devel::SmallProf (and Devel::FastProf) are also good, but they are for per-line profiling. So they are very useful for scripts and CGIs where there is little sub or method breakdown.

    There's also Devel::AutoProfiler, but I've never had much luck with that (probably because I've always tried it when every other profiler has failed).