localtime/strftime not behaving as expected

[sdetweil]

my application has a performance (elapsed time) problem. so I decided I'd instrument it with prints of localtime, as this topic suggests..

If you have a perl program that seems to be taking too long you can add print statements using localtime before and after a code block or subroutine to time execution:

    print scalar localtime . "\n";
    retrieve_addresses();
    print scalar localtime . "\n";

but, altho the app takes 30 seconds, the timers at the start/stop and along the way show the exact same time..
I actually use it like this

print  "Begin: Debug " . strftime( '%m-%d-%Y %H:%M:%S', localtime() ) 
+. "\n";

and got this

first functional line of application
Begin: Debug 02-21-2013 12:09:54 
last function line of application
Starting window loop 02-21-2013 12:09:54

so, what did I miss? activestate perl 5.10, windows

[ww]

Question answered (more or less) above; now a suggestion:

For a job like this, you probably want to use Devel-NYTProf, Devel::DProf or Devel::Profile (the first tends to be preferred these days).

[sdetweil]

thanks will look at those.. this was the first gross pass.. I might be able to get a second out, but when the OS tool takes 10, there is no way to make that 1.

[Discipulus]

i'll use this...


use Time::HiRes qw(gettimeofday tv_interval);
[..]
my  $t0 = [gettimeofday];
    my $resp = &long_running_funct();
    my $ttaken = tv_interval ($t0, [gettimeofday]);

hth L*

[Anonymous Monk]

so, what did I miss?

A demonstration that demonstrates the problem

$ perl -E " say scalar localtime;  sleep 2; say scalar localtime; "
Thu Feb 21 16:52:56 2013
Thu Feb 21 16:52:58 2013

As you can see, two seconds later is two seconds later, its two seconds later

Maybe you override localtime with another function which caches the value, who knows

[sdetweil]

Thx.. as far as I am aware I do not overlay or alias localtime() anywhere that would cause a cached value I have a statement as the second line of my app

open DEBUG, ">", "debug.txt";
print DEBUG  "Begin: Debug " . strftime( '%m-%d-%Y %H:%M:%S', localtim
+e() ) . "\n";


I have a statement before & after I unzip the help file.
and before/after I load my product reference files (this one I expect to be the trouble area. On windows it uses Find to get the individual lines in my product config files that matter. On my dev system it takes 2.4-2.5 seconds (timed with another language script wrapper)

    my $ok;
    use Archive::Zip;
    my $z = Archive::Zip->new();
    eval { $ok = $z->read($HelpFile); };
    if ( $ok == 0 )
    {
        if ($debug)
        {    
            print DEBUG "Start unzip help  " . strftime( '%m-%d-%Y %H:
+%M:%S', localtime() ) . "\n";
        }
        # unzip the new copy of the scripts into the update folder
        mkdir './help';
        $ok = $z->extractTree( 'help', 'help' );
        if($debug)
        {
            print DEBUG "End   unzip help  " . strftime( '%m-%d-%Y %H:
+%M:%S', localtime() ) . "\n";
        }        
    }
    undef $z;
    unlink($HelpFile);
    if ($debug)
    {
        print DEBUG "Begin: Populating product names." . strftime( '%m
+-%d-%Y %H:%M:%S', localtime() ) ."\n";
    }

    populateProductNames();

    $products = [@products];
    if ($debug)
    {
        print DEBUG "End: Populating product names." . strftime( '%m-%
+d-%Y %H:%M:%S', localtime() ) ."\n";
    }

and I have one just before I put up my wxPerl app window

if ($debug)
{
    use POSIX 'strftime';
    print DEBUG "Starting window loop " . strftime( '%m-%d-%Y %H:%M:%S
+', localtime() ) . "\n";
}
$app->MainLoop;

and I see this

Begin: Debug 02-21-2013 12:09:54
Start unzip help  02-21-2013 12:09:54
End   unzip help  02-21-2013 12:09:54
Begin: Populating product names.02-21-2013 12:09:54
End: Populating product names.02-21-2013 12:09:54
Starting window loop 02-21-2013 12:09:54

[karlgoethebier]

As a supplement, reading this might be helpful. Regards, Karl

[Anonymous Monk]

That talk is marked OUTDATED, try http://www.slideshare.net/Tim.Bunce/develnytprof-v4-at-oscon-201007

[karlgoethebier]

Mmh, points to same slide by Tim Bunce from July 2010. Regards, Karl