Beefy Boxes and Bandwidth Generously Provided by pair Networks
P is for Practical
 
PerlMonks  

In search of a bug in Time::HiRes on Windows.

by BrowserUk (Patriarch)
on Jun 15, 2005 at 02:55 UTC ( [id://466763]=perlquestion: print w/replies, xml ) Need Help??

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

Could a few of you with windows machines and Time::HiRes installed (it comes with AS distributions) run the following snippet and post your results.

If you only get 1 or 2 lines of output, please increase the value 10 to 100 or 1000 or whatever it takes to get 10 or so values printed. Thanks.

#! perl -slw use strict; use Time::HiRes qw[ time ]; print $Time::HiRes::VERSION; my( $t, $t2 ) = time; $t2 = time - $t and $t += $t2 and print $t for 1 .. 10;

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".
The "good enough" maybe good enough for the now, and perfection maybe unobtainable, but that should not preclude us from striving for perfection, when time, circumstance or desire allow.

Replies are listed 'Best First'.
Re: In search of a bug in Time::HiRes on Windows.
by PodMaster (Abbot) on Jun 15, 2005 at 03:07 UTC
    C:\>perl5.6.1 time.hires.bug.466763.pl 1.68 1118804774.18816 1118804774.18823 1118804774.18829 1118804774.18834 1118804774.1884 1118804774.18851 1118804774.18857 1118804774.18866 1118804774.18872 1118804774.18877 C:\>perl5.6.2 time.hires.bug.466763.pl 1.68 1118804778.18835 1118804778.18842 1118804778.18847 1118804778.18853 1118804778.18859 1118804778.18864 1118804778.1887 1118804778.18876 1118804778.18881 1118804778.18887 C:\>perl5.8.4 time.hires.bug.466763.pl 1.68 1118804785.78195 1118804785.78199 1118804785.78203 1118804785.78207 1118804785.7821 1118804785.78214 1118804785.78217 1118804785.7822 1118804785.78224 1118804785.78227 C:\>perl5.8.6d time.hires.bug.466763.pl 1.65 1118804791.4676 1118804791.46766 1118804791.4677 1118804791.46774 1118804791.46778 1118804791.46782 1118804791.46786 1118804791.4679 1118804791.46794 1118804791.46798

    MJD says "you can't just make shit up and expect the computer to know what you mean, retardo!"
    I run a Win32 PPM repository for perl 5.6.x and 5.8.x -- I take requests (README).
    ** The third rule of perl club is a statement of fact: pod is sexy.

Re: In search of a bug in Time::HiRes on Windows.
by eyepopslikeamosquito (Archbishop) on Jun 15, 2005 at 03:04 UTC

    With standard perl 5.8.6 built from sources:

    1.65 1118804504.10359 1118804504.10371 1118804504.10383 1118804504.10393 1118804504.10403 1118804504.10416 1118804504.10425 1118804504.10435 1118804504.10446 1118804504.10456

Re: In search of a bug in Time::HiRes on Windows.
by kiat (Vicar) on Jun 15, 2005 at 03:15 UTC
    With Perl version v5.8.6:

    1.65 1118805186.85975 1118805186.85976 1118805186.85976 1118805186.85977 1118805186.85978 1118805186.85978 1118805186.85979 1118805186.85979 1118805186.8598 1118805186.8598

      That's strange? The snippet I posted should only produce unique values, not duplicates.

      Did you modify it to produce these results?


      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".
      The "good enough" maybe good enough for the now, and perfection maybe unobtainable, but that should not preclude us from striving for perfection, when time, circumstance or desire allow.
        No, I ran your code as-is. Here's more:

        perl time_bug.pl > time_bug.txt 1.65 1118806411.5004 1118806411.50041 1118806411.50041 1118806411.50042 1118806411.50043 1118806411.50043 1118806411.50044 1118806411.50044 1118806411.50045 1118806411.50045
        Update:

        When I ran (output to the screen)

        perl time_bug.pl
        i.e. without "> time_bug.txt", there're no duplicates.
Re: In search of a bug in Time::HiRes on Windows.
by jbrugger (Parson) on Jun 15, 2005 at 05:04 UTC
    got:
    U:\>perl --version
    
    This is perl, v5.8.6 built for cygwin-thread-multi-64int
    
    Copyright 1987-2004, Larry Wall
    
    Perl may be copied only under the terms of either the Artistic License or the
    GNU General Public License, which may be found in the Perl 5 source kit.
    
    Complete documentation for Perl, including FAQ lists, should be found on
    this system using `man perl' or `perldoc perl'.  If you have access to the
    Internet, point your browser at http://www.perl.org/, the Perl Home Page.
    
    U:\>perl test.pl
    1.65
    1118811736.68118
    1118811736.68156
    1118811736.68186
    1118811736.68224
    1118811736.68257
    1118811736.68288
    1118811736.68318
    1118811736.68357
    1118811736.68387
    1118811736.68417
    
    "We all agree on the necessity of compromise. We just can't agree on when it's necessary to compromise." - Larry Wall.
Re: In search of a bug in Time::HiRes on Windows.
by K_M_McMahon (Hermit) on Jun 15, 2005 at 03:33 UTC
    Results
    1.65 1118806227.5142 1118806227.51421 1118806227.51422 1118806227.51422 1118806227.51423 1118806227.51424 1118806227.51424 1118806227.51425 1118806227.51426 1118806227.51427

    Perl Version
    This is perl, v5.8.6 built for MSWin32-x86-multi-thread (with 3 registered patches, see perl -V for more detail) Copyright 1987-2004, Larry Wall Binary build 811 provided by ActiveState Corp. http://www.ActiveState. +com ActiveState is a division of Sophos. Built Dec 13 2004 09:52:01 Perl may be copied only under the terms of either the Artistic License + or the GNU General Public License, which may be found in the Perl 5 source ki +t. Complete documentation for Perl, including FAQ lists, should be found +on this system using `man perl' or `perldoc perl'. If you have access to + the Internet, point your browser at http://www.perl.org/, the Perl Home Pa +ge.
    Perl Version (More Detail)


    -Kevin
    my $a='62696c6c77667269656e6440676d61696c2e636f6d'; while ($a=~m/(^.{2})/s) {print unpack('A',pack('H*',"$1"));$a=~s/^.{2}//s;}
Re: In search of a bug in Time::HiRes on Windows.
by ikegami (Patriarch) on Jun 15, 2005 at 05:45 UTC
    (n = 10,000) >perl !.pl 1.2 1118813755.17075 1118813755.18637 (n = 100,000) >perl !.pl 1.2 1118813761.18637 1118813761.202 1118813761.21762 1118813761.23325 1118813761.24887 1118813761.2645 >perl -v This is perl, v5.8.0 built for MSWin32-x86-multi-thread (with 1 registered patch, see perl -V for more detail) Binary build 806 provided by ActiveState Corp. http://www.ActiveState. +com Built 00:45:44 Mar 31 2003 ...

    I had to use ppm to install Time::HiRes for 5.6.1. I had to reduce the loop to 10, down from 100,000:

    (n=10) >perl !.pl 1.63 1118814102.57754 1118814102.57761 1118814102.57767 1118814102.57773 1118814102.57793 1118814102.57799 1118814102.57805 1118814102.57812 1118814102.57818 1118814102.57824 >perl -v This is perl, v5.6.1 built for MSWin32-x86-multi-thread (with 1 registered patch, see perl -V for more detail) Copyright 1987-2001, Larry Wall Binary build 635 provided by ActiveState Corp. http://www.ActiveState. +com Built 15:34:21 Feb 4 2003 ...

    It seems 5.6.1's Time::HiRes has a much better resolution than 5.8.0's. Is that the bug for which you are searching? My 5.8.0 results seem different from everyone else's results.

      Warning: Long & complicated story! (With a request at the end)

      It seems 5.6.1 has a much better resolution than 5.8.0. Is that the bug for which you are searching?

      It's not quite that simple. Time::HiRes v1.2 is a very old version I think which could explain your results. Later versions (circa. >= 1.53 ) have code which uses a high resolution performance counter to enhance the low resolution of the GetSystemTimeAsFileTime() api.

      However, under some circumstances, the use of the high res timer doesn't seems to work correctly. For example:

      On my system, doing it this way the resolution is around 70/80 uSeconds:

      P:\test>perl -MTime::HiRes=time -wle"print time for 1 .. 10" 1118814859.12534 1118814859.12551 1118814859.12558 1118814859.12566 1118814859.12573 1118814859.1258 1118814859.12587 1118814859.12594 1118814859.12602 1118814859.12609

      but in the debugger, it suddenly becomes 31.25 milliseconds:

      P:\test>perl -MTime::HiRes=time -de1 perldb: Must not source insecure rcfile ./perldb.ini. You or the superuser must be the owner, and it must not be writable by anyone but its owner. Loading DB routines from perl5db.pl version 1.25 Editor support available. Enter h or `h h' for help, or `perldoc perldebug' for more help. main::(-e:1): 1 DB<1> print time . $/ for 1 .. 20;; 1118815107.6875 1118815107.6875 1118815107.6875 1118815107.6875 1118815107.6875 1118815107.6875 1118815107.6875 1118815107.6875 1118815107.6875 1118815107.6875 1118815107.6875 1118815107.6875 1118815107.71875 1118815107.71875 1118815107.71875 1118815107.71875 1118815107.71875 1118815107.71875 1118815107.71875 1118815107.73438 DB<2>

      which is strange enough, but it gets stranger. I saw spurperl's comment in Re^2: Microseconds in Per regarding Time::HiRes resolution on Win32 and it reminded me of a similar effect I pursued a while ago after reading Unique filenames with Time::HiRes which lead to Re^4: Perl -de1 weirdness..

      I was on a different machine/version of the OS back then, and when I tried to trackdown the problem, I couldn't reproduce it outside the debugger. Whilst I did raise a mention on p5p, a bug in a timer that only occurs inside the debugger isn't really critical.

      However, and this is where it gets really strange, the other day when I read spurperl's comment, I ran the above test, and I was getting the 31.25 millsecond resolution outside of the debugger! Last night I decided to try and track it down again, and I ran some code using Win32::API to access the performance counter directly. Twiddled around a bit and then tried the test above again, and suddenly, the I was getting the 70/80 microsecond resolution outside of the debugger. I didn't install anything new.

      Puzzled, I eventually tried rebooting to see what if any difference that made and it made none at all. I now have the high resolution timer outside of the debugger and nothing I have tried reverts me to the low res situation outside of the debugger.

      Great you might say, but this is where I was on my old machine. I had the low-res timer always. Played with calling the performance counter, suddenly got the high res results and could find no way to revert outside of the debugger!

      My feeling is that Windows is caching some state somewhere and that the calls inside Time::HiRes.xs are not triggering the enablement of the performance counter on their own. But once the performance counter has been enabled, Time::HiRes is able to use it from that point on. How/why that would be so I cannot imagine at this stage.

      So, what I need is someone who has Time::HiRes v 1.53 or greater that is getting low-res results. I am not sure whether the Perl version is relevant or not yet. PodMaster showed that high resolution results are possible on every build.

      If I can find someone with T::H >1.53 getting low-res results, then I will ask then to run the piece of Win32::API code that appeared to make the difference on my machine and see if it has the same enabling effect for them.

      Is there any chance of you upgrading to T::H > 1.53 in your 5.8.x install?

      If you cannot find a PPM, I could always email you the files from here.


      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".
      The "good enough" maybe good enough for the now, and perfection maybe unobtainable, but that should not preclude us from striving for perfection, when time, circumstance or desire allow.
Re: In search of a bug in Time::HiRes on Windows.
by GrandFather (Saint) on Jun 15, 2005 at 03:43 UTC

    AS distribution. Version: 5.008006

    1.65 1118806618.62947 1118806618.62948 1118806618.62948 1118806618.62949 1118806618.6295 1118806618.6295 1118806618.62951 1118806618.62951 1118806618.62952 1118806618.62952

    Perl is Huffman encoded by design.
Re: In search of a bug in Time::HiRes on Windows.
by fglock (Vicar) on Jun 15, 2005 at 05:23 UTC

    This is all I get (Windows NT, perl 5.8.0):

    1.2

      Could you please re-run having set the loop upper bound to 10,000?


      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".
      The "good enough" maybe good enough for the now, and perfection maybe unobtainable, but that should not preclude us from striving for perfection, when time, circumstance or desire allow.

        with 1..10000 I get:

        1.2 1118892950.89816 1118892950.90818
Re: In search of a bug in Time::HiRes on Windows.
by NateTut (Deacon) on Jun 15, 2005 at 16:44 UTC
    perl Time-HiRes-Test.pl 1.55 1118852932.57546 1118852932.57558 1118852932.57561 1118852932.57624 1118852932.57633 1118852932.59201 1118852932.59212 1118852932.59215 1118852932.59252 1118852932.59257 C:\My Documents\Clients\Dem\pl>perl -v This is perl, v5.8.3 built for MSWin32-x86-multi-thread (with 8 registered patches, see perl -V for more detail) Copyright 1987-2003, Larry Wall Binary build 809 provided by ActiveState Corp. http://www.ActiveState. +com ActiveState is a division of Sophos. Built Feb 3 2004 00:28:51


    If it matters: 733 MHz, Windows ME
Re: In search of a bug in Time::HiRes on Windows.
by spurperl (Priest) on Jun 17, 2005 at 05:59 UTC
    This is perl, v5.8.4 built for MSWin32-x86-multi-thread
    (with 3 registered patches, see perl -V for more detail)
    
    Copyright 1987-2004, Larry Wall
    
    Binary build 810 provided by ActiveState Corp. http://www.ActiveState.com
    ActiveState is a division of Sophos.
    Built Jun  1 2004 11:52:21
    
    Perl may be copied only under the terms of either the Artistic License or the
    GNU General Public License, which may be found in the Perl 5 source kit.
    
    Complete documentation for Perl, including FAQ lists, should be found on
    this system using `man perl' or `perldoc perl'.  If you have access to the
    Internet, point your browser at http://www.perl.com/, the Perl Home Page.
    

    The results are:

    1.59
    1118987794.35973
    1118987794.35978
    1118987794.3598
    1118987794.35981
    1118987794.35983
    1118987794.35985
    1118987794.35987
    1118987794.35989
    1118987794.35991
    1118987794.35992
    

      That has fixed your problem?

      Could you try the loop within the debugger and see what results you get?


      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".
      The "good enough" maybe good enough for the now, and perfection maybe unobtainable, but that should not preclude us from striving for perfection, when time, circumstance or desire allow.
        It looks like the problem went away, yes. Unfortunately, I don't remember how to reproduce the original problem. If I run into it again I'll let you know.

        In the debugger I get:

          DB<2> print time  . $/ for 1 .. 20;;
        1118999589.19879
        1118999589.2088
        1118999589.2088
        1118999589.21882
        1118999589.21882
        1118999589.22883
        1118999589.23884
        1118999589.23884
        1118999589.24886
        1118999589.24886
        1118999589.25887
        1118999589.26889
        1118999589.26889
        1118999589.2789
        1118999589.2789
        1118999589.28892
        1118999589.29893
        1118999589.30894
        1118999589.30894
        1118999589.31896
        

Log In?
Username:
Password:

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

How do I use this?Last hourOther CB clients
Other Users?
Others exploiting the Monastery: (5)
As of 2024-03-19 08:40 GMT
Sections?
Information?
Find Nodes?
Leftovers?
    Voting Booth?

    No recent polls found