Beefy Boxes and Bandwidth Generously Provided by pair Networks
"be consistent"
 
PerlMonks  

localtime/strftime not behaving as expected

by sdetweil (Sexton)
on Feb 22, 2013 at 00:19 UTC ( #1020023=perlquestion: print w/replies, xml ) Need Help??
sdetweil has asked for the wisdom of the Perl Monks concerning the following question:

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

Replies are listed 'Best First'.
Re: localtime/strftime not behaving as expected
by ww (Archbishop) on Feb 22, 2013 at 02:38 UTC
    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).


    If you didn't program your executable by toggling in binary, it wasn't really programming!

      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.
Re: localtime/strftime not behaving as expected
by Discipulus (Monsignor) on Feb 22, 2013 at 10:10 UTC
    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*
    there are no rules, there are no thumbs..
Re: localtime/strftime not behaving as expected
by Anonymous Monk on Feb 22, 2013 at 00:49 UTC

    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

      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
      
Re: localtime/strftime not behaving as expected
by karlgoethebier (Monsignor) on Feb 22, 2013 at 08:10 UTC

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

    «The Crux of the Biscuit is the Apostrophe»

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

        «The Crux of the Biscuit is the Apostrophe»

Log In?
Username:
Password:

What's my password?
Create A New User
Node Status?
node history
Node Type: perlquestion [id://1020023]
Approved by ww
help
Chatterbox?
and the web crawler heard nothing...

How do I use this? | Other CB clients
Other Users?
Others meditating upon the Monastery: (5)
As of 2018-10-15 23:18 GMT
Sections?
Information?
Find Nodes?
Leftovers?
    Voting Booth?
    When I need money for a bigger acquisition, I usually ...














    Results (82 votes). Check out past polls.

    Notices?