Why QueryperformanceCounter timed different from wall clock?

Question

Hi I am using QueryperformanceCounter to time a block of code in Delphi. For some reason, the Millisecond number I got by using QueryPerformanceCounter is quite different from my wall clock time by using a stopwatch. For example The stopwatch give me about 33 seconds, which seems right if not accuracy, but using QueryPerofomanceCounter will give me a number like 500 Milliseconds.

When step though my code, I can see that QueryPerformanceFrequencygives me correct CPU frequency for my CPU, 2.4G for Core2 E6600. So if the tick number is correct, (tick number / Freq) * 1000 should give me correct execution time for the code I am timing, but why not?

I know that for the code I am trying to timing, QeuryPerformanceCounter is probably over-killing as it took seconds rather than MillionSeconds, but I am more interested in understanding the reason for the time difference between wall clock and QueryPerormanceCounter.

My Hardware is E6600 Core2 and OS is Windows 7 X64 if it is relevant.

unit PerformanceTimer;

interface

uses Windows, SysUtils, DateUtils;

type TPerformanceTimer = class
  private
    fFrequency : TLargeInteger;
    fIsRunning: boolean;
    fIsHighResolution: boolean;
    fStartCount, FstopCount : TLargeInteger;
    procedure SetTickStamp(var lInt : TLargeInteger) ;
    function GetElapsedTicks: TLargeInteger;
    function GetElapsedMiliseconds: TLargeInteger;
  public
    constructor Create(const startOnCreate : boolean = false) ;
    procedure Start;
    procedure Stop;
    property IsHighResolution : boolean read fIsHighResolution;
    property ElapsedTicks : TLargeInteger read GetElapsedTicks;
    property ElapsedMiliseconds : TLargeInteger read GetElapsedMiliseconds;
    property IsRunning : boolean read fIsRunning;
end;

implementation

constructor TPerformanceTimer.Create(const startOnCreate : boolean = false) ;
begin
  inherited Create;

  fIsRunning := false;

  fIsHighResolution := QueryPerformanceFrequency(fFrequency) ;
  if NOT fIsHighResolution then
    fFrequency := MSecsPerSec;

  if startOnCreate then
    Start;
end;

function TPerformanceTimer.GetElapsedTicks: TLargeInteger;
begin
  result := fStopCount - fStartCount;
end;

procedure TPerformanceTimer.SetTickStamp(var lInt : TLargeInteger) ;
begin
  if fIsHighResolution then
    QueryPerformanceCounter(lInt)
  else
    lInt := MilliSecondOf(Now) ;
end;

function TPerformanceTimer.GetElapsedMiliseconds: TLargeInteger;
begin
  result := (MSecsPerSec * (fStopCount - fStartCount)) div fFrequency;
end;

procedure TPerformanceTimer.Start;
begin
  SetTickStamp(fStartCount) ;
  fIsRunning := true;
end;

procedure TPerformanceTimer.Stop;
begin
  SetTickStamp(fStopCount) ;
  fIsRunning := false;
end;

end.

Answer 1

This code just works for me, maybe you can try it:

  var
    ifrequency, icount1, icount2: Int64;
    fmsec: Double;
  begin
    QueryPerformanceFrequency(ifrequency);
    QueryPerformanceCounter(icount1);
    Sleep(500);
    QueryPerformanceCounter(icount2);
    fmsec := 1000 * ((icount2 - icount1) / ifrequency);
  end;

fmsec is about 499.6 or something like that.

Note: Don't rely on Now or TickCount for small numbers: they have an interval of about 10ms (depending on Windows version)! So duration of "sleep(10)" can give 0ms if you use Now and DateUtils.MillisecondsBetween

Note 2: Don't rely on QueryPerformanceCounter for long durations, because it's time can slowly go away during a day (about 1ms diff per minute)

Answer 2

If your hardware supports dynamic frequency scaling, it implies that QueryPerformanceFrequency cannot return a static value continuously describing a dynamically changing one. Whenever something computationally aggressive starts, the adapting CPU speed will prevent exact measurements.

At least, it was experienced with my notebook - as it changed to the higher clock rate, QueryPerformanceCounter based measurements were messed up.

So, regardless of the higher accuracy offered, I still use GetTickCount most of the time for such purposes (but DateTime based measurements are also OK, as mentioned before, except if time zone switches may occur), with some "warm-up" code piece that starts eating up the CPU power so the CPU speed is at its (constant) maximum as the relevant code piece starts executing.

Answer 3

You should post a code snippet demonstrating the problem...but I would assume an error on your part:

Milliseconds := 1000 * ((StopCount - StartCount) / Frequency);

If you are comparing to a stop watch, you can likely take the easier route and just capture the TDateTime before and after (by using Now()) and then use the DateUtils MilliSecondSpan() method to calculate difference:

var
  MyStartDate:TDateTime;
  MyStopDate:TDateTime;
  MyTiming:Double;
begin
  MyStartDate := Now();
  DoSomethingYouWantTimed();
  MyStopDate := Now();
  MyTiming := MilliSecondSpan(MyStopDate, MyStartDate);
  DoSomethingWithTiming(MyTiming);
end;

Answer 4

I use an NTP server to sync the PC clock periodically, the PC clock over a large amount of time to adjust the QueryPerformanceCounter "tick" time, and the calibrated QueryPerformanceCounter time for precise time measurements. On a good server where the clock drift is low it means that I have accuracy over time periods to much less than a millisecond and the clock times of all my machines synchronised to within a millsecond or two. Some of the relevant code is attached below:

function NowInternal: TDateTime;
const
  // maximum time in seconds between synchronising the high-resolution clock
  MAX_SYNC_TIME = 10;
var
  lPerformanceCount: Int64;
  lResult: TDateTime;
  lDateTimeSynchronised: Boolean;
begin
  // check that the the high-resolution performance counter frequency has been
  // initialised
  fDateTimeCritSect.Enter;
  try
    if (fPerformanceFrequency < 0) and
       not QueryPerformanceFrequency(fPerformanceFrequency) then
      fPerformanceFrequency := 0;

    if fPerformanceFrequency > 0 then begin
      // get the return value from the the high-resolution performance counter
      if (fWindowsStartTime <> CSI_NULL_DATE_TIME) and
         QueryPerformanceCounter(lPerformanceCount) then
        lResult := fWindowsStartTime +
                   lPerformanceCount / fPerformanceFrequency / SecsPerDay
      else
        lResult := CSI_NULL_DATE_TIME;

      if (MilliSecondsBetween(lResult, Now) >= MAX_CLOCK_DIFF) or
         (SecondsBetween(Now, fLastSyncTime) >= MAX_SYNC_TIME) then begin
        // resynchronise the high-resolution clock due to clock differences or
        // at least every 10 seconds
        lDateTimeSynchronised := SyncDateTime;

        // get the return value from the the high-resolution performance counter
        if (fWindowsStartTime <> CSI_NULL_DATE_TIME) and
           QueryPerformanceCounter(lPerformanceCount) then
          lResult := fWindowsStartTime +
                     lPerformanceCount / fPerformanceFrequency / SecsPerDay;

      end else
        lDateTimeSynchronised := False;

      if MilliSecondsBetween(lResult, Now) >= (MAX_CLOCK_DIFF * 2) then
        // default the return value to the standard low-resolution value if
        // anything has gone wrong
        Result := Now
      else
        Result := lResult;

    end else begin
      lDateTimeSynchronised := False;

      // default the return value to the standard low-resolution value because
      // we cannot use the high-resolution clock
      Result := Now;
    end;
  finally
    fDateTimeCritSect.Leave;
  end;

  if lDateTimeSynchronised then
    CsiGlobals.AddLogMsg('High-resolution clock synchronised', CSI_LC_CLOCK);
end;

function SyncDateTime: Boolean;
var
  lPriorityClass: Cardinal;
  lThreadPriority: Integer;
  lInitTime: TDateTime;
  lNextTime: TDateTime;
  lPerformanceCount: Int64;
  lHighResCurrentTime: TDateTime;
  lLowResCurrentTime: TDateTime;
begin
  // synchronise the high-resolution date/time structure (boost the thread
  // priority as high as possible during synchronisation)
  lPriorityClass := CsiGetProcessPriorityClass;
  lThreadPriority := CsiGetCurrentThreadPriority;
  try
    CsiSetProcessPriorityClass(REALTIME_PRIORITY_CLASS);
    CsiSetCurrentThreadPriority(THREAD_PRIORITY_TIME_CRITICAL);

    // loop until the low-resolution date/time value changes (this will load the
    // CPU, but only for a maximum of around 15 milliseconds)
    lInitTime := Now;
    lNextTime := Now;
    while lNextTime = lInitTime do
      lNextTime := Now;

    // adjust the high-resolution performance counter frequency for clock drift
    if (fWindowsStartTime <> CSI_NULL_DATE_TIME) and
       QueryPerformanceCounter(lPerformanceCount) then begin
      lHighResCurrentTime := fWindowsStartTime +
                             lPerformanceCount / fPerformanceFrequency /
                             SecsPerDay;
      lLowResCurrentTime := Now;
      if MilliSecondsBetween(lHighResCurrentTime, lLowResCurrentTime) <
         (MAX_CLOCK_DIFF * 2) then
        fPerformanceFrequency := Round((1 +
                                       (lHighResCurrentTime -
                                        lLowResCurrentTime) /
                                       (lLowResCurrentTime - fLastSyncTime)) *
                                       fPerformanceFrequency);
    end;

    // save the Windows start time by extrapolating the high-resolution
    // performance counter value back to zero
    if QueryPerformanceCounter(lPerformanceCount) then begin
      fWindowsStartTime := lNextTime -
                           lPerformanceCount / fPerformanceFrequency /
                           SecsPerDay;
      fLastSyncTime := Now;
      Result := True;

    end else
      Result := False;
  finally
    CsiSetCurrentThreadPriority(lThreadPriority);
    CsiSetProcessPriorityClass(lPriorityClass);
  end;
end;