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

Greetings,

I am in need of accurate time measurement down to 0.1ms - Generally Time::HiRes does seem to do pretty well, but (using the below code) sometimes gets spikes of 15.625ms.

In reading the module notes, it says Do not expect usleep() to be exact down to one microsecond which I'm perfectly fine with, that makes sense. but these spikes, 15.625ms (most commonly), are way above 50-100 microseconds... which was the kind of precision I was expecting/hoping for.

Questions:
Is my code actually measuring the accuracy of Time::HiRes or are these spikes due to something else?
If the code is fine, how might I be able to better determine what the current time is with accuracy down to 0.1ms? (To clarify, I don't specifically need to sleep for an exact amount of time, I need a means of calculating what the current time is down to 0.1ms accuracy at certain events.)

Incidentally, on my last test, only 63 samples out of 20,000 were unexpected, which is ok, but I'd like to do better than that if possible...

Thanks in advance

Update:
I'm using ActivePerl 5.8.8 and 5.10.1
use strict;
use warnings;

use Time::HiRes ;

my $secs_old = 1;     
my $usecs_old = 0.000001;
my $sleep_amt = 1;

for (1..100_000){
    my ($secs_new, $usecs_new) = Time::HiRes::gettimeofday();
    
    my $secs_diff = $secs_new - $secs_old - $sleep_amt;
    my $usecs_diff = $usecs_new - $usecs_old;
    
    $usecs_diff = $usecs_diff / 1000;
    
    print "[$secs_diff] [$usecs_diff]\n";
    
    $secs_old = $secs_new;
    $usecs_old = $usecs_new;
    
    #Time::HiRes::usleep(1_000_000);    #I found usleep tends to have 
+even less accurate results than the builtin sleep function...
    sleep $sleep_amt;
}

__END__

[0] [0]
[0] [15.625]
[0] [0]
....
[0] [0]
[0] [15.625]
[0] [0]
[0] [0]
[0] [0]
[0] [0]
[0] [265.625]
[0] [0]
[0] [0]
...
etc

[download]

Replies are listed 'Best First'.
Re: Unexpected Timing spikes using Time::HiRes
by stefbv (Priest) on Jan 19, 2010 at 07:47 UTC

    Processes with higher priority interfere with Perl processes so the spikes are normal.

    I don't think you can reliably measure time with that precision unless you use a Real-time operating system.

[reply]
Re: Unexpected Timing spikes using Time::HiRes
by BrowserUk (Patriarch) on Jan 19, 2010 at 11:37 UTC

    Try running your program using 

    start /realtime yourscript.pl

    [download]

    And see if that makes things any better.

    Examine what is said, not who speaks -- Silence betokens consent -- Love the truth but pardon error.
    "Science is about questioning the status quo. Questioning authority".
    In the absence of evidence, opinion is indistinguishable from prejudice.
[reply]
[d/l]
      indeed, that does seem to make a difference, only 11 out of 19,000 samples were unexpected using realtime priority on the perl.exe process running the script.

      Interestingly however, the smallest 'error' was still 15.625ms... it didn't shrink it, only reduced the occurrance of it.
      anyhow, thanks for the pointer - looks like i might have to just live with it. Cheers
[reply]

        My guess is that you are running this on an XP or 200x system?

        Examine what is said, not who speaks -- Silence betokens consent -- Love the truth but pardon error.
        "Science is about questioning the status quo. Questioning authority".
        In the absence of evidence, opinion is indistinguishable from prejudice.
[reply]
Re: Unexpected Timing spikes using Time::HiRes
by hossman (Prior) on Jan 19, 2010 at 08:03 UTC

    Have you considered checking hte return value of usleep (or sleep) to see how many actual seconds the method slept for, and then compare that with the delta from Time::HiRes::gettimeofday

    I suspect that Time::HiRes::gettimeofday is in fact returning the accurate time for your system at the moment you call it, but you are seeing the larger then expected deltas because other things are happening on your system (besides the sleep) in between your calls -- Perl garbage collection, other processes on the same machine, etc....

    My first suggestion was to try something like... 

     time perl -MTime::HiRes -le 'print ((Time::HiRes::gettimeofday())[1])
+ for (1..500)'

    [download]

    ...where you sanity check the numbers printed out looking for any really odd jumps, and Compare the "real" time reported by your system with the delta between the first/last times printed so see if they concur.

    But the compilation/interpreter startup is significant enough to provide missleading info at such a small level of granularity.

[reply]
[d/l]
[select]
Re: Unexpected Timing spikes using Time::HiRes
by jethro (Monsignor) on Jan 19, 2010 at 09:41 UTC

    Did you try your process with different nice-values (i.e. using "nice --adjustment=-20 perl <yourscript>" as root) ? If you change the priority of the process significantly and the number of occurrences of the spikes changes, the problem is that other processes sometimes get in your way. If it doesn't change it might be perl itself as someone else here already suggested.

    Note that there is also a realtime priority setting on linux for processes. RT is a higher priority than the highest normal priority setting (which is -20). You can see it with top, or with "ps -eo pid,tid,rtprio,ni,pri". Look at the third column which is '-' for most processes but on my system two processes have a 99 in that column.

[reply]
Re: Unexpected Timing spikes using Time::HiRes
by ikegami (Patriarch) on Jan 21, 2010 at 00:59 UTC
    What's your Time::HiRes version? It should be ≥1.53
[reply]

Back to Seekers of Perl Wisdom