Bug #19175 for Devel-Profile: Inclusive times

Tue May 09 19:49:46 2006 mschwern [...] cpan.org - Ticket created

Subject:

Inclusive times

The profile times for Devel::Profile appear to be exclusive times, ie. only the time spend on the code inside that subroutine and not time spent calling other routines. I often find inclusive time, time spent executing a subroutine and all routines called from it, very useful for finding the true cost of calling a routine. It would be very nice if there were a way to get this information from Devel::Profile. To make clear the difference between inclusive and exclusive time... sub foo { sleep 5 } sub bar { foo() } bar() subroutine exclusive time inclusive time foo 5 5 bar 0.001 5.001 PS Devel::Profile is the only profiler which works with the perl installation and code I am currently working with, thank you.

Wed May 10 12:50:49 2006 jaw+pause [...] tcp4me.com - Correspondence added

Subject:	Re: [rt.cpan.org #19175] Inclusive times
Date:	Wed, 10 May 2006 12:49:56 -0400 (EDT)
To:	bug-Devel-Profile [...] rt.cpan.org
From:	jaw [...] cpan.org

| The profile times for Devel::Profile appear to be exclusive times, ie. | only the time spend on the code inside that subroutine and not time | spent calling other routines. I often find inclusive time, time spent | executing a subroutine and all routines called from it, very useful for | finding the true cost of calling a routine. It would be very nice if | there were a way to get this information from Devel::Profile. does it need to be part of Devel::Profile? sitting on my hard drive is Devel::DProfLB (where 'LB' = 'Less Bad'), that produces output in a similar format as Devel::DProf, so you would be able to run 'dprofpp -I' to get what you want. I imagine I'll get it onto CPAN in the near future.

Wed May 10 12:50:50 2006 The RT System itself - Status changed from 'new' to 'open'

Wed May 10 14:17:59 2006 mschwern [...] cpan.org - Correspondence added

On Wed May 10 12:50:49 2006, JAW wrote: Show quoted text

> does it need to be part of Devel::Profile?

Nope, as long as it works. Show quoted text

> sitting on my hard drive is Devel::DProfLB > (where 'LB' = 'Less Bad'), that produces output > in a similar format as Devel::DProf, so you would > be able to run 'dprofpp -I' to get what you want.

That would be much preferred. While the human readable output of Devel::Profile is easy to use its not terribly flexible. Show quoted text

> I imagine I'll get it onto CPAN in the near future.

Any chance I could have a sneak peek if it works? FWIW here's the hack I'm using on Devel::Profile to get inclusive times. It throws pretty much all the other statistics off, but the clock seconds are correct. --- Profile.pm Tue May 9 16:54:33 2006 +++ Profile.pm~ Wed May 5 15:47:34 2004 @@ -155,11 +155,9 @@ my $t = time() - $ti # total time of called sub - ($tacc - $st); # minus time of subs it called $tacc += $t; - for ( $sx, map { $_->[0] } @prof_stack ) { - $prof_times{$_} += $t; - } - $prof_calls{$sx} ++; - $call ++; + $prof_times{$sx} += $t; # We take no note of time + $prof_calls{$sx} ++; # But from its loss + $call ++; # -- Edward Young, Night Thoughts } if( $wa ){

Wed May 10 14:18:47 2006 mschwern [...] cpan.org - Correspondence added

Whoops, reversed the patch. --- Profile.pm~ Wed May 5 15:47:34 2004 +++ Profile.pm Tue May 9 16:54:33 2006 @@ -155,9 +155,11 @@ my $t = time() - $ti # total time of called sub - ($tacc - $st); # minus time of subs it called $tacc += $t; - $prof_times{$sx} += $t; # We take no note of time - $prof_calls{$sx} ++; # But from its loss - $call ++; # -- Edward Young, Night Thoughts + for ( $sx, map { $_->[0] } @prof_stack ) { + $prof_times{$_} += $t; + } + $prof_calls{$sx} ++; + $call ++; } if( $wa ){

Thu May 11 12:11:33 2006 jaw+pause [...] tcp4me.com - Correspondence added

Subject:	Re: [rt.cpan.org #19175] Inclusive times
Date:	Thu, 11 May 2006 12:11:01 -0400 (EDT)
To:	bug-Devel-Profile [...] rt.cpan.org
From:	jaw [...] cpan.org

| > I imagine I'll get it onto CPAN in the near future. | | Any chance I could have a sneak peek if it works? I just uploaded Devel-DProfLB-0.0 to CPAN, it should be visible after some delay. feedback welcome.

Thu May 11 20:28:30 2006 mschwern [...] cpan.org - Correspondence added

On Thu May 11 12:11:33 2006, JAW wrote: Show quoted text

> > | > I imagine I'll get it onto CPAN in the near future. > | > | Any chance I could have a sneak peek if it works? > > > I just uploaded Devel-DProfLB-0.0 to CPAN, > it should be visible after some delay. > > feedback welcome.

Very cursory use shows it to work, though I get a spew of these at the end... print() on closed filehandle DB::PROF at /dp/usr/mgs/work/current/perl_lib//Devel/DProfLB.pm line 210 during global destruction. print() on closed filehandle DB::PROF at /dp/usr/mgs/work/current/perl_lib//Devel/DProfLB.pm line 239 during global destruction. This is with ActiveState's 5.6.1 build 633 on Linux.