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

As a rule, I'm blissfully ignorant of technical details surrounding windows implementations of perl, but now there's something I need to know, and I'm hoping there's a monk out there who has experience with certain details...

I have a perl script using Time::HiRes (in particular its "time" function) to write a log file of elapsed times (in fractional seconds) for key strokes, and this is being done while an audio recording process is going on. (Each key stroke brings up a new phrase on the display, and a person reads the phrase aloud.)

So, each keyboard input event relates to (immediately precedes) a spoken utterance in the audio file, and the plan is that the time stamps in the log file will match up with audio time offsets, so that the key-stroke times will identify the locations of the utterances in the recording.

The problem is that the values returned by Time::HiRes on this windows/cygwin setup appear to be moving along faster than "real" elapsed time, as marked by the audio data. For example:

Since the keyboard clicks are audible in the audio, and the log file includes the text for each phrase being displayed, I can tell that the log file times and audio locations match pretty well at the beginning of a session, but for an utterance that occurs at 300.0 sec from the start of the audio file, the corresponding log file time stamp shows 302.5 (roughly) -- that is, Time::HiRes is gaining about half a second for every minute of elapsed time.

The man page for the module contains this little gem:

... in Win32 (and derived platforms like Cygwin and MinGW) the Time::HiRes::time() may temporarily drift off from the system clock (and the original time()) by up to 0.5 seconds. Time::HiRes will notice this eventually and recalibrate.

Has anyone been bothered by this "feature"? Can anyone elaborate on what sort of behavior I should expect (e.g. sudden/unpredictable "re-alignments" in the middle of a session log file, or a consistent pattern of resets at specific intervals)? Is there a sensible solution or workaround for getting accurate timing data?

  • Comment on Time::HiRes (un)reliability in Windows/Cygwin ??

Replies are listed 'Best First'.
Re: Time::HiRes (un)reliability in Windows/Cygwin ??
by BrowserUk (Patriarch) on Jul 25, 2007 at 21:10 UTC

    See also Re: Time::HiRes not that high on windows, Time::Hires Granularity and In search of a bug in Time::HiRes on Windows..

    PC clocks do drift. That's why we have NTP protocols to correct them.

    On Win32, Time::HiRes uses two different system apis to produce its wallclock timings.

    1. GetSystemTimeAsFileTime() which is the system clock time. Rather low resolution, but relatively accurate over the long term. Especially if NTP is set up to correct for silicon drift.
    2. QueryPerformanceCounter/QueryPerformanceFrequency which combine to produce very high resolution.

      But, the faster a clock (bistable) runs, the faster any slight variations in the frequency due to chip temperature, voltage variations etc. are magnified into noticable values over the long term.

    Time::HiRes uses the high resolution performance timer to generate hi-res timings, but as it can drift over long periods (more than a few seconds; several 100 million ticks), it compares it against the lower resolution, but more stable System clock time, and if it has drifted by more than 0.5 seconds (an arbitrary choice of constant used with HiRes.xs), then it corrects it according to the system clock.

    The problem is, the checking and resetting only occurs when you call the GetTimeOfDay() api or one of it's aliases like time(). If you do not call the timer for extended periods, then the timer drift will not be corrected and so you may get larger than 0.5 second of drift.

    A simplistic solution to ensure the drift is corrected as early as possible is to set a thread running in the background of your app that simply calls one of the apis at regular intervals

    use threads; async{ my $x == time() while Win32::Sleep 0.25; };

    If you want to ensure less than 0.5 seconds of drift, re-build Time::HiRes having adjusted the following constant to a suitable value:

    #define MAX_PERF_COUNTER_SKEW Const64(5000000) /* 0.5 seconds */

    You would still need to ensure that one of the apis gets called regularly as above to ensure the correction takes place in a timely (sic) manner. Adjust the sleep accordingly.

    It's also worth considering whether it is the Time::HiRes time that is drifting, or the mutimedia timer that doesn't correct for drift?

    I'm not sure how other OSs compensate for silicon drift?


    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.
Re: Time::HiRes (un)reliability in Windows/Cygwin ??
by ikegami (Patriarch) on Jul 25, 2007 at 21:01 UTC

    The way I read the (uncut) man page quote leads me to believe the mentioned drift only occurs when "adjusting the system clock (either manually or by services like ntp)".

    At I ran the following code:

    perl -le"use Time::HiRes qw( time ); print time while <>

    I pressed enter at 4:39:00, 4:44:00 and 4:56:00.

    1185395940.27216 1185396239.78586 1185396960.49883

    Time 1 and Time 2:
    Clock time difference: 300 seconds
    HiRes time difference: 299.5137 seconds
    Drift: 0.09726 HiRes second per Clock minute

    Time 1 and Time 3:
    Clock time difference: 1020 seconds
    HiRes time difference: 1020.22667 seconds
    Drift: 0.01333 HiRes second per Clock minute

    You mentioned a drift of 0.5 HiRes second per Clock minute. I am simply not seeing that. The error is surely due to the variance in my response time.

    By the way, old versions of Time::HiRes (< 1.53) had notorisouly bad resolution on Windows. Are you using something recent?

      Thanks for the info -- esp. about the version issue (I'll need to check into that, but the machine is not close to my desk).

      I also tried a one-liner test similar to what you showed, and I got results similar to yours -- that is, I was not able to replicate the problem when I tried the simplest possible means to demonstrate it.

      Naturally, the overall situation is more complicated -- the script that is writing the log file is actually a Perl/Tk app (so that the phrase to be read aloud is presented in a nice big font), and so far I'm just assuming that the sampling rate of the audio file is "accurate" (supposed to be 16 kHz, though I'm not sure if this is done via downsampling from something like 44.1). Uncertainty abounds...

        so far I'm just assuming that the sampling rate of the audio file is "accurate"

        It might be worth verifying that. What audio recording hardware are you using? In fact, there are some particularly bad soundcards out there, like this one, for example, which could approximately account for the drift you're observing... Most cards are significantly better, though (by orders of magnitude), so this may not necessarily be the problem in your case. But how would you know, unless you've actually measured it...?

        A relatively easy way to check would be to record the ticking of a reasonably accurate clock (with an analog display), and then verify that the peaks of the recorded waveform stay in sync with what the audio software reports based on the assumed sample rate. (Even cheap quartz wrist watches typically have of drift of less than one second per day, so that should be a sufficiently precise time reference for the purpose at hand...)

        Incidentally, when I was working in psycholinguistic/ERP research, we were using similar experimental setups, to present stimuli, and such... And from those experiences I can confirm that sample rate inaccuracy can in fact become a problem in special cases like the one you're describing.  That was more than a decade ago, though. Hardware might actually have improved since then — or maybe not...