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

I am having a degree of bother with the Time::Hires module, running on Win98; The output of the following snippet looks something like this:

0
0
0
0
{...repeated several hundred times}
0.0500000715255737
0.0500000715255737
0.0500000715255737
0.0500000715255737
{repeated several hundred - about 6-700 - times}
0.110000014305115
0.110000014305115
0.110000014305115
{you begin to get the picture...}
{etc}
4.94000005722046
4.94000005722046
4.94000005722046
4.94000005722046
5

I understand that the module may not have marvellous performance on windows, I was under the impression that this was in the order of milliseconds being possible, but not much better. My issue is the repeating of the same value (despite $t being refreshed on every loop), at approx. 0.06 second intervals, which is quite a bit worse than milliseconds. Is this a problem with my code, or have I just misunderstood the appallingness of Windows? Incidentally, all I want is up to 1/100th of a second, and cross-platformability. Is this too much to ask?
use Time::HiRes qw(time); $thu = "5.00"; $a="0"; $s=time; while ($a=="0"){ $t=time; $f=($t-$s); print "$f\n"; if ($f==$thu){$a="1";} }
Any help much appreciated :-)

Replies are listed 'Best First'.
Re: Time::Hires Granularity (tick size)
by tye (Sage) on Dec 04, 2003 at 07:11 UTC

    Checking, I see that Time::HiRes1 is using GetSystemTimeAsFileTime() under Windows. Based on your results, it appears that this Win32 API call uses the same facility as GetTickCount() and has the same limitations.

    GetTickCount() returns a 4-byte unsigned integer containing the number of milliseconds since the computer was booted (which wraps every 49.7 days). System "ticks" are the basis for scheduling in Win32. GetTickCount() is poorly named because it returns a count of milliseconds not a count of ticks. The duration of one "tick" depends on operating system version.

    For Win98 and prior, the tick size is 60ms. For WinNT/Win2k, it is 10ms (same as for Solaris). For WinXP, it is 15ms. (Based on testing as I haven't found good documentation on these values.)

    So even though GetSystemTimeAsFileTime() returns the time measured in 100-nanosecond intervals since January 1, 1601, it isn't any more accurate than between 10ms and 60ms.

    The easiest way to get more accurate timings on Windows is to call QueryPerformanceFrequency() and QueryPerformanceCounter(). They each fill an 8-byte buffer with a __int64 value. The first fills it with the number of times the performance counter is incremented each second. The second fills it with the current value of this counter.

    The resolution of the performance counter is much higher. One example showed it was 1193180Hz (it may well vary by hardware, I haven't looked into that too much).

    Sorry, I don't have the time at the moment to find a module for you that exposes these APIs to Perl nor to write one using Win32::API nor XS. But it would probably be very cool (and not too difficult) to patch Time::HiRes so that it augemented its use of GetSystemTimeAsFileTime() with performance counter queries so that the resolution would be much, much higher.

    Also note that Perl is compiled with access to GetTickCount() built-in so you can simply use Win32::GetTickCount() whenever you want (you don't even need to "use Win32" for it to work).

                    - tye

    1 Without the capital "R" (like in the node title) it is very similar to Time::Miller, but not as intoxicating.

    Update: You could even have Time::HiRes optionally run a tight loop for around 10ms to 60ms when it is first loaded so that not only would timings of durations be much more accurate within this process, but timings would even be almost as accurate across processes...

      Re: wraps every 49.7 days - Interesting... I use Time::HiRes a lot on Win32, suppose I left a script running long enough, would it start to return incorrect times?

        No. The tick count and GetTickCount() wrap but neither GetSystemTimeAsFileTime() nor Time::HiRes do.

                        - tye
      """GetTickCount() returns a 4-byte unsigned integer containing the number of milliseconds since the computer was booted (which wraps every 49.7 days). """ That's patently ridiculous! What Windows sytem stays up for 49.7 days? :)
Re: Time::Hires Granularity
by BrowserUk (Patriarch) on Dec 04, 2003 at 09:46 UTC

    The limitation is in the implementation of Time::HiRes on Win32. You might find Re: Time::HiRes not that high on windows interesting. It doesn't add much over what tye has already said, but it might cause you to question what it is that you are after in trying for highly accurate timestamps.


    Examine what is said, not who speaks.
    "Efficiency is intelligent laziness." -David Dunham
    "Think for yourself!" - Abigail
    Hooray!
    Wanted!

Re: Time::Hires Granularity
by chromatic (Archbishop) on Dec 04, 2003 at 03:47 UTC

    I just ran this code on my laptop for 170k prints per second. Note that printing takes a bit of time:

    use Time::HiRes 'time'; my $end_secs = 5; my $elapsed = 0; my $start = time(); while ($elapsed < $end_secs) { $elapsed = time() - $start; print "$elapsed\n"; }

    Update: Sorry, I forgot why I was posting. I'm using Linux and slightly different code, both of which may make a difference. If my code runs the same as your code on your machine, it's likely a Windows thing, as tye has already pointed out.

      Thanks for the reply, maybe I was unclear...
      The issue is not the number of prints. As I said I am getting about 700 prints of the same time, and then the next set of lines is time+0.06
      I am confused as to why the routine can loop 700 times without updating the 'time' variable. Is is that the system is only capable of receiving a request for the time information every .06 seconds? I was hoping that the increment would be smaller (1/100th of a second would be fine). Is this a Windows issue, or, less likely, a code problem; if so, are there any sensible workarounds that anyone could suggest.
      Cheers :-)
        As I said I am getting about 700 prints of the same time, and then the next set of lines is time+0.06
        Actually, it should be closer to 0.055.

        Windows' internal click gets updated 18 times a second, or once every 55ms, via a timer interrupt. The API call GetTickCount() exhibits the same behaviour as you describe here. The docs for this API call mention:

        It is limited to the resolution of the system timer.
        So yes, even though I haven't seen any evidence that the two phenomenons are indeed related, their symptoms are so strikingly alike, that I'm quite convinced they share the same origin. So yes, it's a Windows Thing™.

        Update: I don't mean to say it cannot be fixed/patched, only that this is behaviour you'll typically only see in Windows, for this particular case.

      And?
Re: Time::Hires Granularity
by ysth (Canon) on Dec 04, 2003 at 06:04 UTC
    Try taking the print out of the loop. I tried this:
    $ perl -wle'use Time::HiRes "time"; my $start = time; while (10000 > k +eys %t) { ++$t{time()-$start} } print "total time ", time()-$start; use List::U +til "sum" ; print "avg iterations per reported time ", sum(values %t)/keys(%t)' total time 11.0990000963211 avg iterations per reported time 20.3936
    on cygwin/Windows XP Pro.