Click here to get back home

Re: Devel::SmallProf claims "return 1" needs much time !?
 Home | NewsGroups | Search | About
Login Password
Register Now!
 comp.lang.perl.misc    Post an article   get this group's latest topics as an RSS feed add this group's latest topics to your My MSN content add this group's latest topics to your My Yahoo content
Subject Author Date
Re: Devel::SmallProf claims "return 1" needs much time !? xhoster 04-30-2008
Posted by xhoster on April 30, 2008, 12:38 pm
Please log in for more thread options
> I'm trying to do some profiling on DBM::Deep. I started with
> Devel::DProf and Devel::Profile but for some subs I had no idea *why*
> they took long, so I tried Devel::SmallProf for additional detail.
> Much of what I see makes sense but results like this puzzle me (these
> are the subs that do the low-level disc read and write):

I often find SmallProf to be unreliable, especially when trying to profile
code portions which are fast on each execution but are executed very often.

>
> count wall tm cpu time line
> 0 0.00000 0.00000 103:sub print_at {
> 314000 0.96161 3.67000 104: my $self = shift;
> 314000 0.88398 3.34000 105: my $loc = shift;
> 0 0.00000 0.00000 106:
> 314000 1.51351 3.89000 107: local ($/,$\);
> 0 0.00000 0.00000 108:
> 314000 1.07561 3.94000 109: my $fh = $self->;
> 314000 4.39820 7.83000 110: if ( defined $loc ) {

This just seems weird. My 3GHz machine does an if defined test 32 times
faster, so unless you have an old computer I would say that this casts
doubt on the entire reliability of the SmallProf output.
...
> 0 0.00000 0.00000 115:
> 314000 6.65324 9.86000 116: return 1;
> 0 0.00000 0.00000 117:}
...
>
> Much of the time is spent in "seek", "print" and "read" -- as expected
> (although I'm surprised it's only tenths of microseconds per call -- I
> suppose disc caches work their wonders...). But even more time is
> spent in the two "return" statements, and I don't know why! I thought
> that maybe they contain the overhead of function calling/returning but
> coudn't verify that in a simple testscript.

Your return is only taking ~50-100% longer than your "if defined". While
both of them are taking absurdly long, that ratio is about what I find in a
simple test script. Is your machine old and slow? Is it perhaps swapping
itself to death during this test, or heavily loaded with other people's
processes?

If you can post the entire harness (provided it is small) you are using to
profile DBM::Deep, I'll play with it a bit.

Xho

--
-------------------- http://NewsReader.Com/ --------------------
The costs of publication of this article were defrayed in part by the
payment of page charges. This article must therefore be hereby marked
advertisement in accordance with 18 U.S.C. Section 1734 solely to indicate
this fact.

Posted by Wolfram Humann on April 30, 2008, 4:06 pm
Please log in for more thread options
 On Apr 30, 6:38=A0pm, xhos...@gmail.com wrote:
>
> This just seems weird. =A0My 3GHz machine does an if defined test 32 times=

> faster, so unless you have an old computer I would say that this casts
> doubt on the entire reliability of the SmallProf output.

I think you got somthing wrong here. The profiler runs on the comiled
and optimized code where several source-lines may have become one. If
you look at the "count"-column, you will see that line 110 includes
the time for seek() in the next line. Im my experience, the shortest-
running lines in a script (e.g. "my $self =3D shift;") will indeed vary
a lot from run to run because of the nulltime-compensation im
SmallProf. The lines we're talking about are fairly stable.

> If you can post the entire harness (provided it is small) you are using to=

> profile DBM::Deep, I'll play with it a bit.

Every script that imports heavily in DBM::Deep will do. Mine looks
like this:

BEGIN
{
        $DB::profile =3D 0;
        %DB::packages =3D ( 'DBM::Deep::Engine' =3D> 1,
'DBM::Deep::Engine::Sector' =3D> 1, 'DBM::Deep::File' =3D> 1 );
}

use strict;
use warnings;
use DBM::Deep;

my $text =3D 'this is always the same dummy text';
my $inner =3D 500;
my $outer =3D 2;
my $profilefile =3D "prof.out";

my $db =3D DBM::Deep->new( "deeptest2.db" );

for my $j (1..$outer)
{
        my $data;

        for my $i (1..$inner)
        {
                my %hash =3D map { +"subkey$_" =3D> $text } (12..30);
                $data-> =3D \%hash;
        }

        $DB::profile =3D 1 if $j =3D=3D $outer;

        my $t =3D time();
        $db->import($data);
        print "Import duration: ", time() - $t, "\n";
}

But I can't say exactly how $inner and $outer were set when I created
the posted profile. Also, I already did some changes in DBM::Deep that
might affect performance.

Wolfram

Posted by xhoster on April 30, 2008, 4:27 pm
Please log in for more thread options
> On Apr 30, 6:38=A0pm, xhos...@gmail.com wrote:
> >
> > This just seems weird. =A0My 3GHz machine does an if defined test 32
> > times=
>
> > faster, so unless you have an old computer I would say that this casts
> > doubt on the entire reliability of the SmallProf output.
>
> I think you got somthing wrong here. The profiler runs on the comiled
> and optimized code where several source-lines may have become one. If
> you look at the "count"-column, you will see that line 110 includes
> the time for seek() in the next line.

While I can't rule that out, I've never seen that done in this setting.
I've seen the condition of an elsif reported as if it were the condition of
the preceding if, but I've never seen that type of conflation happen
between the if condition and if block (except when the block contents are
on the same line as the condition). And I can't reproduce it with test
cases.

I assumed the behavior of the count column was simply because $loc is never
defined in the use-case you used, and therefore line 111 is never executed.
But I could be wrong.

Xho

--
-------------------- http://NewsReader.Com/ --------------------
The costs of publication of this article were defrayed in part by the
payment of page charges. This article must therefore be hereby marked
advertisement in accordance with 18 U.S.C. Section 1734 solely to indicate
this fact.

Posted by Wolfram Humann on April 30, 2008, 4:40 pm
Please log in for more thread options
On Apr 30, 10:27=A0pm, xhos...@gmail.com wrote:
>
> I assumed the behavior of the count column was simply because $loc is neve=
r
> defined in the use-case you used, and therefore line 111 is never executed=
.
> But I could be wrong.

Well, I'm also not *that* sure about my claim, I should better check
that :-)

Wolfram

Posted by xhoster on April 30, 2008, 5:52 pm
Please log in for more thread options
>
> Every script that imports heavily in DBM::Deep will do. Mine looks
> like this:
>
> BEGIN
> {
> $DB::profile = 0;
> %DB::packages = ( 'DBM::Deep::Engine' => 1,
> 'DBM::Deep::Engine::Sector' => 1, 'DBM::Deep::File' => 1 );
> }

I'm not sure, but I think that by restricting your packages that way, all
the time spent in a non-monitored package will get attributed to the
most recently executed statement which is in one of the monitored packages.
That statement is likely to be a "return".

I tried profiling your program, but the profiled code looked nothing like
yours. I realized I have an old DBM::Deep. I installed the current
version in a test directory, and holy cow is it slow compared to the old
version. If it ever finishes, I'll see what the profile looks like.

It looks like DBM::Deep is trying to change from a module to tie hashes to
disk with as little differences as possible (behvior-wise) from a regular
Perl hash; and instead turn into a full-fledged ACID database. I think
that that is unfortunate. Perhaps a code fork is in order.

Xho

--
-------------------- http://NewsReader.Com/ --------------------
The costs of publication of this article were defrayed in part by the
payment of page charges. This article must therefore be hereby marked
advertisement in accordance with 18 U.S.C. Section 1734 solely to indicate
this fact.

Similar ThreadsPosted
Devel::StackTrace November 16, 2006, 10:35 am
Devel::Cover How to get a more indepth report January 10, 2007, 7:19 pm
Profiling Perl with better granularity than Devel::DProf October 8, 2007, 5:22 pm
GMT time to local time, according to timezone and summer/winter time. May 15, 2005, 10:45 pm
Calculating time of employee session from the log date/time stampusing perl May 24, 2005, 5:55 pm
How do I convert TIME into Cookie and last-modified-time format? October 1, 2004, 3:05 pm
Compare UNIX file time with time in a variable November 23, 2006, 2:39 pm
How to send a query to the browser from time to time? July 20, 2005, 9:35 am
Time::Format with two $time strings February 23, 2005, 4:56 pm
Perl time and Mysql time September 26, 2005, 7:47 pm

Our other projects:

Art Dolls, Fairies and Mermaids - Sunnyfaces.net

Roy's Linux, Programming and Search Engines messages

1-Script XML SitemapXML Sitemap