Interesting issue with (Ke)QueryPerformanceCounter

Hi all.

A customer of mine reported a strange issue, and I tracked the issue down to
wrong values returned by KeQueryPerformanceCounter (or the user counterpart
QueryPerformanceCounter/Frequency).

The MSDN docs clearly state that

KeQueryPerformanceCounter always returns a 64-bit integer that represents
the current value of a monotonically nondecreasing counter. The resolution
of the timer used to accumulate the current count can be obtained by
specifying a pointer value for PerformanceFrequency. The value that is
returned is the number of ticks per second. The count starts accumulating
when the computer is started up.

What I get on some specific customer machine is something that is not “ticks
per second”. Either the frequency is bogus, or the counter itself.

I wrote a small user app to test it:

int _tmain(int argc, _TCHAR* argv)
{
int i;
LARGE_INTEGER freq, counter;
SYSTEMTIME systemTime;

for (i = 0; i < 10; i++)
{
GetSystemTime(&systemTime);

if (QueryPerformanceCounter(&counter) == FALSE ||
QueryPerformanceFrequency(&freq) == FALSE)
{
printf(“Error getting performance counters\n”);
}

printf(“Counter = %I64d Freq = %I64d”, counter.QuadPart, freq.QuadPart);
printf(" system: %02d:%02d:%02d\n",
systemTime.wHour,
systemTime.wMinute,
systemTime.wSecond);

Sleep(1000);
}

return 0;
}

And this is the output on the failing machine:

Counter = 56497408135970 Freq = 3158750000 system: 01:18:57
Counter = 56497818110218 Freq = 3158750000 system: 01:18:58
Counter = 56498206404250 Freq = 3158750000 system: 01:18:59
Counter = 56498715528269 Freq = 3158750000 system: 01:19:00
Counter = 56499113984213 Freq = 3158750000 system: 01:19:01
Counter = 56499489120527 Freq = 3158750000 system: 01:19:02
Counter = 56499867623469 Freq = 3158750000 system: 01:19:03
Counter = 56500252073478 Freq = 3158750000 system: 01:19:04
Counter = 56500713252945 Freq = 3158750000 system: 01:19:05
Counter = 56501096560332 Freq = 3158750000 system: 01:19:06

If you make some computations, the counter seems to say that every iteration
is about 0.12 seconds apart from the previous one, while it should be more
or less 1 second.
The failing machine is running XP SP3 (hal.dll 5.1.2600.5687, ntoskrnl.exe
5.1.2600.5938) on an Intel Core 2 Duo E8500.

Has anyone ever seen this?

Have a nice day
GV

Haven’t seen this.

But you might try starting/stopping the multimedia timer. See if that causes
difference in behavior.

Thomas


From: “Gianluca Varenni”
Sent: Wednesday, September 01, 2010 3:34 PM
To: “Windows System Software Devs Interest List”
Subject: [ntdev] Interesting issue with (Ke)QueryPerformanceCounter

> Hi all.
>
> A customer of mine reported a strange issue, and I tracked the issue down
> to wrong values returned by KeQueryPerformanceCounter (or the user
> counterpart QueryPerformanceCounter/Frequency).
>
> The MSDN docs clearly state that
>
> KeQueryPerformanceCounter always returns a 64-bit integer that represents
> the current value of a monotonically nondecreasing counter. The resolution
> of the timer used to accumulate the current count can be obtained by
> specifying a pointer value for PerformanceFrequency. The value that is
> returned is the number of ticks per second. The count starts accumulating
> when the computer is started up.
>
>
> What I get on some specific customer machine is something that is not
> “ticks per second”. Either the frequency is bogus, or the counter itself.
>
> I wrote a small user app to test it:
>
> int _tmain(int argc, _TCHAR* argv)
> {
> int i;
> LARGE_INTEGER freq, counter;
> SYSTEMTIME systemTime;
>
> for (i = 0; i < 10; i++)
> {
> GetSystemTime(&systemTime);
>
> if (QueryPerformanceCounter(&counter) == FALSE ||
> QueryPerformanceFrequency(&freq) == FALSE)
> {
> printf(“Error getting performance counters\n”);
> }
>
> printf(“Counter = %I64d Freq = %I64d”, counter.QuadPart, freq.QuadPart);
> printf(" system: %02d:%02d:%02d\n",
> systemTime.wHour,
> systemTime.wMinute,
> systemTime.wSecond);
>
> Sleep(1000);
> }
>
> return 0;
> }
>
> And this is the output on the failing machine:
>
> Counter = 56497408135970 Freq = 3158750000 system: 01:18:57
> Counter = 56497818110218 Freq = 3158750000 system: 01:18:58
> Counter = 56498206404250 Freq = 3158750000 system: 01:18:59
> Counter = 56498715528269 Freq = 3158750000 system: 01:19:00
> Counter = 56499113984213 Freq = 3158750000 system: 01:19:01
> Counter = 56499489120527 Freq = 3158750000 system: 01:19:02
> Counter = 56499867623469 Freq = 3158750000 system: 01:19:03
> Counter = 56500252073478 Freq = 3158750000 system: 01:19:04
> Counter = 56500713252945 Freq = 3158750000 system: 01:19:05
> Counter = 56501096560332 Freq = 3158750000 system: 01:19:06
>
> If you make some computations, the counter seems to say that every
> iteration is about 0.12 seconds apart from the previous one, while it
> should be more or less 1 second.
> The failing machine is running XP SP3 (hal.dll 5.1.2600.5687, ntoskrnl.exe
> 5.1.2600.5938) on an Intel Core 2 Duo E8500.
>
> Has anyone ever seen this?
>
>
> Have a nice day
> GV
>
>
>
>
> —
> NTDEV is sponsored by OSR
>
> For our schedule of WDF, WDM, debugging and other seminars visit:
> http://www.osr.com/seminars
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer

> Has anyone ever seen this?

We had a discussion with Michal around a week ago about something similar. Basically, you can sleep less than the amount of time you have specified under some circumstances. You can check "Some doubts about KeStallExecutionProcessor and KeDelayExecutionThread’ thread (http://www.osronline.com/showThread.cfm?link=187626) for more info…

Anton Bassov

One thing is sleeping less than exactly one second, one other thing is
reporting numbers that are almost 10 times off.

The test runs for about 10 seconds. The difference between the first and the
last sample is around 9 seconds (remember that I print the result of
GetSystemTime). QueryPerformanceCounter reports that the time difference is
1.17 seconds.

GV


From:
Sent: Wednesday, September 01, 2010 1:17 PM
To: “Windows System Software Devs Interest List”
Subject: RE:[ntdev] Interesting issue with (Ke)QueryPerformanceCounter

>> Has anyone ever seen this?
>
> We had a discussion with Michal around a week ago about something similar.
> Basically, you can sleep less than the amount of time you have specified
> under some circumstances. You can check "Some doubts about
> KeStallExecutionProcessor and KeDelayExecutionThread’ thread
> (http://www.osronline.com/showThread.cfm?link=187626) for more info…
>
>
> Anton Bassov
>
> —
> NTDEV is sponsored by OSR
>
> For our schedule of WDF, WDM, debugging and other seminars visit:
> http://www.osr.com/seminars
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer

Yeah, yeah… it’s not even remotely related to what we talked about a couple of weeks back…

You posted user-mode code, though, which makes my head hurt.

Have you tried this in kernel mode?? Thankfully, in kernel-mode KeQueryPerformanceCounter both returns the value *and* the frequency… which makes life a lot easier.

Peter
OSR

Is this some kind of virtual machine? Or do they have anything that tampers with whatever timer QueryPerformanceCounter uses? (run this test again in safe mode, or boot a WinPE CD).
If none of above, then… that machine is only 99% compatible with Windows. It happens.

Regards,
–pa

Is this running in a VM?

mm

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Gianluca Varenni
Sent: Wednesday, September 01, 2010 4:27 PM
To: Windows System Software Devs Interest List
Subject: Re: RE:[ntdev] Interesting issue with (Ke)QueryPerformanceCounter

One thing is sleeping less than exactly one second, one other thing is
reporting numbers that are almost 10 times off.

The test runs for about 10 seconds. The difference between the first and the
last sample is around 9 seconds (remember that I print the result of
GetSystemTime). QueryPerformanceCounter reports that the time difference is
1.17 seconds.

GV


From:
Sent: Wednesday, September 01, 2010 1:17 PM
To: “Windows System Software Devs Interest List”
Subject: RE:[ntdev] Interesting issue with (Ke)QueryPerformanceCounter

>> Has anyone ever seen this?
>
> We had a discussion with Michal around a week ago about something similar.

> Basically, you can sleep less than the amount of time you have specified
> under some circumstances. You can check "Some doubts about
> KeStallExecutionProcessor and KeDelayExecutionThread’ thread
> (http://www.osronline.com/showThread.cfm?link=187626) for more info…
>
>
> Anton Bassov
>
> —
> NTDEV is sponsored by OSR
>
> For our schedule of WDF, WDM, debugging and other seminars visit:
> http://www.osr.com/seminars
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer


NTDEV is sponsored by OSR

For our schedule of WDF, WDM, debugging and other seminars visit:
http://www.osr.com/seminars

To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer


From:
Sent: Wednesday, September 01, 2010 1:39 PM
To: “Windows System Software Devs Interest List”
Subject: RE:[ntdev] Interesting issue with (Ke)QueryPerformanceCounter

> Yeah, yeah… it’s not even remotely related to what we talked about a
> couple of weeks back…
>
> You posted user-mode code, though, which makes my head hurt.
>
> Have you tried this in kernel mode?? Thankfully, in kernel-mode
> KeQueryPerformanceCounter both returns the value and the frequency…
> which makes life a lot easier.

The problem was originally detected with KeQueryPerformanceCounter (where it
was used to timestamp packets). Even in that case, the frequency was always
the same, but the counter was off in the same exact way.

Unfortunately writing a similar test application in kernel mode is a bit
more complicated. The customer having the issue is not a direct customer. We
sell the library and driver to our customer, and he builds the application
for the end customer (having the issue). So I have no whatsoever access to
the failing machine. I can just ask my customer to check his customer’s
machine (or run some test apps on it). Having said that, I have a similar
trace, where I was printing the values returned by KeQuerySystemTime and
KeQueryPerformance counter (where the iterations are not 1second apart, I
was printing them for every packet received by my protocol driver) and it
was showing bogus performance counters as well. The frequency was always the
same, it was not changing.

I’m checking with the customer if they are actually running from within a VM
(and they forgot to tell me).

Have a nice day
GV

>
> Peter
> OSR
>
>
> —
> NTDEV is sponsored by OSR
>
> For our schedule of WDF, WDM, debugging and other seminars visit:
> http://www.osr.com/seminars
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer

Just checked with the customer. Nope. It’s an HP 8000 Elite.

Have a nice day
GV


From: “M. M. O’Brien”
Sent: Wednesday, September 01, 2010 1:49 PM
To: “Windows System Software Devs Interest List”
Subject: RE: RE:[ntdev] Interesting issue with (Ke)QueryPerformanceCounter

> Is this running in a VM?
>
>
> mm
>
> -----Original Message-----
> From: xxxxx@lists.osr.com
> [mailto:xxxxx@lists.osr.com] On Behalf Of Gianluca Varenni
> Sent: Wednesday, September 01, 2010 4:27 PM
> To: Windows System Software Devs Interest List
> Subject: Re: RE:[ntdev] Interesting issue with (Ke)QueryPerformanceCounter
>
> One thing is sleeping less than exactly one second, one other thing is
> reporting numbers that are almost 10 times off.
>
> The test runs for about 10 seconds. The difference between the first and
> the
> last sample is around 9 seconds (remember that I print the result of
> GetSystemTime). QueryPerformanceCounter reports that the time difference
> is
> 1.17 seconds.
>
> GV
>
>
> --------------------------------------------------
> From:
> Sent: Wednesday, September 01, 2010 1:17 PM
> To: “Windows System Software Devs Interest List”
> Subject: RE:[ntdev] Interesting issue with (Ke)QueryPerformanceCounter
>
>>> Has anyone ever seen this?
>>
>> We had a discussion with Michal around a week ago about something
>> similar.
>
>> Basically, you can sleep less than the amount of time you have specified
>> under some circumstances. You can check "Some doubts about
>> KeStallExecutionProcessor and KeDelayExecutionThread’ thread
>> (http://www.osronline.com/showThread.cfm?link=187626) for more info…
>>
>>
>> Anton Bassov
>>
>> —
>> NTDEV is sponsored by OSR
>>
>> For our schedule of WDF, WDM, debugging and other seminars visit:
>> http://www.osr.com/seminars
>>
>> To unsubscribe, visit the List Server section of OSR Online at
>> http://www.osronline.com/page.cfm?name=ListServer
>
>
> —
> NTDEV is sponsored by OSR
>
> For our schedule of WDF, WDM, debugging and other seminars visit:
> http://www.osr.com/seminars
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
>
>
> —
> NTDEV is sponsored by OSR
>
> For our schedule of WDF, WDM, debugging and other seminars visit:
> http://www.osr.com/seminars
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer

Bummer

On Sep 1, 2010 5:16 PM, “Gianluca Varenni”
wrote:
> Just checked with the customer. Nope. It’s an HP 8000 Elite.
>
> Have a nice day
> GV
>
> --------------------------------------------------
> From: “M. M. O’Brien”
> Sent: Wednesday, September 01, 2010 1:49 PM
> To: “Windows System Software Devs Interest List”
> Subject: RE: RE:[ntdev] Interesting issue with (Ke)QueryPerformanceCounter
>
>> Is this running in a VM?
>>
>>
>> mm
>>
>> -----Original Message-----
>> From: xxxxx@lists.osr.com
>> [mailto:xxxxx@lists.osr.com] On Behalf Of Gianluca Varenni
>> Sent: Wednesday, September 01, 2010 4:27 PM
>> To: Windows System Software Devs Interest List
>> Subject: Re: RE:[ntdev] Interesting issue with
(Ke)QueryPerformanceCounter
>>
>> One thing is sleeping less than exactly one second, one other thing is
>> reporting numbers that are almost 10 times off.
>>
>> The test runs for about 10 seconds. The difference between the first and
>> the
>> last sample is around 9 seconds (remember that I print the result of
>> GetSystemTime). QueryPerformanceCounter reports that the time difference
>> is
>> 1.17 seconds.
>>
>> GV
>>
>>
>> --------------------------------------------------
>> From:
>> Sent: Wednesday, September 01, 2010 1:17 PM
>> To: “Windows System Software Devs Interest List”
>> Subject: RE:[ntdev] Interesting issue with (Ke)QueryPerformanceCounter
>>
>>>> Has anyone ever seen this?
>>>
>>> We had a discussion with Michal around a week ago about something
>>> similar.
>>
>>> Basically, you can sleep less than the amount of time you have specified
>>> under some circumstances. You can check "Some doubts about
>>> KeStallExecutionProcessor and KeDelayExecutionThread’ thread
>>> (http://www.osronline.com/showThread.cfm?link=187626) for more info…
>>>
>>>
>>> Anton Bassov
>>>
>>> —
>>> NTDEV is sponsored by OSR
>>>
>>> For our schedule of WDF, WDM, debugging and other seminars visit:
>>> http://www.osr.com/seminars
>>>
>>> To unsubscribe, visit the List Server section of OSR Online at
>>> http://www.osronline.com/page.cfm?name=ListServer
>>
>>
>> —
>> NTDEV is sponsored by OSR
>>
>> For our schedule of WDF, WDM, debugging and other seminars visit:
>> http://www.osr.com/seminars
>>
>> To unsubscribe, visit the List Server section of OSR Online at
>> http://www.osronline.com/page.cfm?name=ListServer
>>
>>
>> —
>> NTDEV is sponsored by OSR
>>
>> For our schedule of WDF, WDM, debugging and other seminars visit:
>> http://www.osr.com/seminars
>>
>> To unsubscribe, visit the List Server section of OSR Online at
>> http://www.osronline.com/page.cfm?name=ListServer
>
>
> —
> NTDEV is sponsored by OSR
>
> For our schedule of WDF, WDM, debugging and other seminars visit:
> http://www.osr.com/seminars
>
> To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer

Gianluca Varenni wrote:

A customer of mine reported a strange issue, and I tracked the issue down to
wrong values returned by KeQueryPerformanceCounter (or the user counterpart
QueryPerformanceCounter/Frequency).

What I get on some specific customer machine is something that is not “ticks
per second”. Either the frequency is bogus, or the counter itself.

If you make some computations, the counter seems to say that every iteration
is about 0.12 seconds apart from the previous one, while it should be more
or less 1 second.
The failing machine is running XP SP3 (hal.dll 5.1.2600.5687, ntoskrnl.exe
5.1.2600.5938) on an Intel Core 2 Duo E8500.

Has anyone ever seen this?

QPC is, in this case, directly reading the processor’s cycle counter.
The processor is running at 3.1 GHz. If the machine is not doing very
much, it’s possible for the cycle frequency to change because of power
management. I have not seen differences quite this dramatic, but it
would be interesting to change your program to do __readtsc() during
each loop and see if the results are identical to QPC.


Tim Roberts, xxxxx@probo.com
Providenza & Boekelheide, Inc.

Hello,

I can’t offer an explanation either, but have you already tried running
‘bcdedit /set useplatformclock yes’ (or setting /USEPMTIMER in boot.ini),
the standard workaround for QPC-related problems?

On Wed, 01 Sep 2010 22:34:23 +0300, Gianluca Varenni
wrote:
> Hi all.
>
> A customer of mine reported a strange issue, and I tracked the issue
> down to wrong values returned by KeQueryPerformanceCounter (or the user
> counterpart QueryPerformanceCounter/Frequency).
>
> The MSDN docs clearly state that
>
> KeQueryPerformanceCounter always returns a 64-bit integer that
> represents the current value of a monotonically nondecreasing counter.
> The resolution of the timer used to accumulate the current count can be
> obtained by specifying a pointer value for PerformanceFrequency. The
> value that is returned is the number of ticks per second. The count
> starts accumulating when the computer is started up.
>
>
> What I get on some specific customer machine is something that is not
> “ticks per second”. Either the frequency is bogus, or the counter itself.
>
> I wrote a small user app to test it:
>
> int _tmain(int argc, _TCHAR* argv)
> {
> int i;
> LARGE_INTEGER freq, counter;
> SYSTEMTIME systemTime;
>
> for (i = 0; i < 10; i++)
> {
> GetSystemTime(&systemTime);
>
> if (QueryPerformanceCounter(&counter) == FALSE ||
> QueryPerformanceFrequency(&freq) == FALSE)
> {
> printf(“Error getting performance counters\n”);
> }
>
> printf(“Counter = %I64d Freq = %I64d”, counter.QuadPart,
> freq.QuadPart);
> printf(" system: %02d:%02d:%02d\n",
> systemTime.wHour,
> systemTime.wMinute,
> systemTime.wSecond);
>
> Sleep(1000);
> }
>
> return 0;
> }
>
> And this is the output on the failing machine:
>
> Counter = 56497408135970 Freq = 3158750000 system: 01:18:57
> Counter = 56497818110218 Freq = 3158750000 system: 01:18:58
> Counter = 56498206404250 Freq = 3158750000 system: 01:18:59
> Counter = 56498715528269 Freq = 3158750000 system: 01:19:00
> Counter = 56499113984213 Freq = 3158750000 system: 01:19:01
> Counter = 56499489120527 Freq = 3158750000 system: 01:19:02
> Counter = 56499867623469 Freq = 3158750000 system: 01:19:03
> Counter = 56500252073478 Freq = 3158750000 system: 01:19:04
> Counter = 56500713252945 Freq = 3158750000 system: 01:19:05
> Counter = 56501096560332 Freq = 3158750000 system: 01:19:06
>
> If you make some computations, the counter seems to say that every
> iteration is about 0.12 seconds apart from the previous one, while it
> should be more or less 1 second.
> The failing machine is running XP SP3 (hal.dll 5.1.2600.5687,
> ntoskrnl.exe 5.1.2600.5938) on an Intel Core 2 Duo E8500.
>
> Has anyone ever seen this?
>
>
> Have a nice day
> GV

I suggest you instead of sleep() run a tight loop waiting for the time to jump to the next second and see if the performance counter will behave better.

In other words, the PerfCount may run with the claimed speed only when you’re actually doing something. If the processor is idle, then power management may kick in

Newer AMD and Intel processors, including the Core 2 family, update the
TSC at a constant rate, so CPU throttling cannot be the culprit here.

(Sorry for mentioning BCDEdit in the first place. I had originally missed
that the machine is running Windows XP.)

On Thu, 02 Sep 2010 05:41:09 +0300, wrote:
> I suggest you instead of sleep() run a tight loop waiting for the time
> to jump to the next second and see if the performance counter will
> behave better.
>
> In other words, the PerfCount may run with the claimed speed only when
> you’re actually doing something. If the processor is idle, then power
> management may kick in

I think the problem is that QPC is broken on Windows XP and Vista. The CPU
guides clearly state that RDTSC is not a serializing instruction and is
subject to out of order execution among other things and the various
implementations on Windows don’t do that. (On Win7 RDTSC is no longer used
possibly depending on available hardware features).

On XP SP3:
hal!KeQueryPerformanceCounter:
806ebb94 8bff mov edi,edi
806ebb96 55 push ebp
806ebb97 8bec mov ebp,esp
806ebb99 5d pop ebp
806ebb9a ff2548156f80 jmp dword ptr [hal!HalpHeapStart+0xc
(806f1548)]
0: kd> t
hal!HalpAcpiTimerQueryPerfCount:
806e4c78 a0dcd06e80 mov al,byte ptr [hal!HalpUse8254 (806ed0dc)]
806e4c78 a0dcd06e80 mov al,byte ptr [hal!HalpUse8254 (806ed0dc)]
806e4c7d 0ac0 or al,al
806e4c7f 752d jne hal!HalpAcpiTimerQueryPerfCount+0x36
(806e4cae)
806e4c81 8b4c2404 mov ecx,dword ptr [esp+4]
806e4c85 0bc9 or ecx,ecx
806e4c87 7412 je hal!HalpAcpiTimerQueryPerfCount+0x23
(806e4c9b)
806e4c89 64a1a4000000 mov eax,dword ptr fs:[000000A4h]
806e4c8f 648b15a8000000 mov edx,dword ptr fs:[0A8h]
806e4c96 8901 mov dword ptr [ecx],eax
806e4c98 895104 mov dword ptr [ecx+4],edx
806e4c9b 0f31 rdtsc
806e4c9d 640305ac000000 add eax,dword ptr fs:[0ACh]
806e4ca4 641315b0000000 adc edx,dword ptr fs:[0B0h]
806e4cab c20400 ret 4

There is no serializing instruction here making RDTSC subject to out of
order execution among other things.

What I would try is issue a CPUID serializing instruction before calling QPC
(__CPUID is included in intrin.h) and see if that solves the problem.

You can read more about the difficulties getting RDTSC right in this
article:
http://www.ccsl.carleton.ca/~jamuir/rdtscpm1.pdf

but you can read about these as well in the latest intel and AMD manuals.

//Daniel

“Gianluca Varenni” wrote in message
news:xxxxx@ntdev…
> Hi all.
>
> A customer of mine reported a strange issue, and I tracked the issue down
> to wrong values returned by KeQueryPerformanceCounter (or the user
> counterpart QueryPerformanceCounter/Frequency).
>
> The MSDN docs clearly state that
>
> KeQueryPerformanceCounter always returns a 64-bit integer that represents
> the current value of a monotonically nondecreasing counter. The resolution
> of the timer used to accumulate the current count can be obtained by
> specifying a pointer value for PerformanceFrequency. The value that is
> returned is the number of ticks per second. The count starts accumulating
> when the computer is started up.
>
>
> What I get on some specific customer machine is something that is not
> “ticks per second”. Either the frequency is bogus, or the counter itself.
>
> I wrote a small user app to test it:
>
> int _tmain(int argc, _TCHAR* argv)
> {
> int i;
> LARGE_INTEGER freq, counter;
> SYSTEMTIME systemTime;
>
> for (i = 0; i < 10; i++)
> {
> GetSystemTime(&systemTime);
>
> if (QueryPerformanceCounter(&counter) == FALSE ||
> QueryPerformanceFrequency(&freq) == FALSE)
> {
> printf(“Error getting performance counters\n”);
> }
>
> printf(“Counter = %I64d Freq = %I64d”, counter.QuadPart, freq.QuadPart);
> printf(" system: %02d:%02d:%02d\n",
> systemTime.wHour,
> systemTime.wMinute,
> systemTime.wSecond);
>
> Sleep(1000);
> }
>
> return 0;
> }
>
> And this is the output on the failing machine:
>
> Counter = 56497408135970 Freq = 3158750000 system: 01:18:57
> Counter = 56497818110218 Freq = 3158750000 system: 01:18:58
> Counter = 56498206404250 Freq = 3158750000 system: 01:18:59
> Counter = 56498715528269 Freq = 3158750000 system: 01:19:00
> Counter = 56499113984213 Freq = 3158750000 system: 01:19:01
> Counter = 56499489120527 Freq = 3158750000 system: 01:19:02
> Counter = 56499867623469 Freq = 3158750000 system: 01:19:03
> Counter = 56500252073478 Freq = 3158750000 system: 01:19:04
> Counter = 56500713252945 Freq = 3158750000 system: 01:19:05
> Counter = 56501096560332 Freq = 3158750000 system: 01:19:06
>
> If you make some computations, the counter seems to say that every
> iteration is about 0.12 seconds apart from the previous one, while it
> should be more or less 1 second.
> The failing machine is running XP SP3 (hal.dll 5.1.2600.5687, ntoskrnl.exe
> 5.1.2600.5938) on an Intel Core 2 Duo E8500.
>
> Has anyone ever seen this?
>
>
> Have a nice day
> GV
>
>
>
>

The mention of /USEPMTIMER got me looking and lead me to this KB article (http://support.microsoft.com/kb/895980) which describes “Programs that use the QueryPerformanceCounter function may perform poorly in Windows Server 2000, in Windows Server 2003, and in Windows XP”. It sounds exactly like what you’re describing.

However, that particular issue is only for AMD CPUs, and according to this (http://h10010.www1.hp.com/wwpc/sg/en/sm/WF06a/12454-12454-64287-3328898-3328898-4065889.html) the HP Elite 8000 uses Intel CPUs.

But I think that the solution is still worth trying: update to the latest hardware/cpu drivers from Intel.

Athough it doesn’t explain the behavior of regular intervals of about 100ms
for the sake of sanity I would also make sure you are running always on the
same CPU by using SetThreadAffinityMask because each core has its own time
stamp counter and they can be out of sync. Also disable variable speed
features such as Intel Speedstep in the BIOS and read the rest of the
recommendations in this article:
http://msdn.microsoft.com/en-us/library/ee417693(VS.85).aspx

//Daniel

wrote in message news:xxxxx@ntdev…
> I think the problem is that QPC is broken on Windows XP and Vista. The CPU
> guides clearly state that RDTSC is not a serializing instruction and is
> subject to out of order execution among other things and the various
> implementations on Windows don’t do that. (On Win7 RDTSC is no longer used
> possibly depending on available hardware features).
>
> On XP SP3:
> hal!KeQueryPerformanceCounter:
> 806ebb94 8bff mov edi,edi
> 806ebb96 55 push ebp
> 806ebb97 8bec mov ebp,esp
> 806ebb99 5d pop ebp
> 806ebb9a ff2548156f80 jmp dword ptr [hal!HalpHeapStart+0xc
> (806f1548)]
> 0: kd> t
> hal!HalpAcpiTimerQueryPerfCount:
> 806e4c78 a0dcd06e80 mov al,byte ptr [hal!HalpUse8254 (806ed0dc)]
> 806e4c78 a0dcd06e80 mov al,byte ptr [hal!HalpUse8254 (806ed0dc)]
> 806e4c7d 0ac0 or al,al
> 806e4c7f 752d jne hal!HalpAcpiTimerQueryPerfCount+0x36
> (806e4cae)
> 806e4c81 8b4c2404 mov ecx,dword ptr [esp+4]
> 806e4c85 0bc9 or ecx,ecx
> 806e4c87 7412 je hal!HalpAcpiTimerQueryPerfCount+0x23
> (806e4c9b)
> 806e4c89 64a1a4000000 mov eax,dword ptr fs:[000000A4h]
> 806e4c8f 648b15a8000000 mov edx,dword ptr fs:[0A8h]
> 806e4c96 8901 mov dword ptr [ecx],eax
> 806e4c98 895104 mov dword ptr [ecx+4],edx
> 806e4c9b 0f31 rdtsc
> 806e4c9d 640305ac000000 add eax,dword ptr fs:[0ACh]
> 806e4ca4 641315b0000000 adc edx,dword ptr fs:[0B0h]
> 806e4cab c20400 ret 4
>
> There is no serializing instruction here making RDTSC subject to out of
> order execution among other things.
>
> What I would try is issue a CPUID serializing instruction before calling
> QPC (__CPUID is included in intrin.h) and see if that solves the problem.
>
> You can read more about the difficulties getting RDTSC right in this
> article:
> http://www.ccsl.carleton.ca/~jamuir/rdtscpm1.pdf
>
> but you can read about these as well in the latest intel and AMD manuals.
>
> //Daniel
>
>
>
>
> “Gianluca Varenni” wrote in message
> news:xxxxx@ntdev…
>> Hi all.
>>
>> A customer of mine reported a strange issue, and I tracked the issue down
>> to wrong values returned by KeQueryPerformanceCounter (or the user
>> counterpart QueryPerformanceCounter/Frequency).
>>
>> The MSDN docs clearly state that
>>
>> KeQueryPerformanceCounter always returns a 64-bit integer that represents
>> the current value of a monotonically nondecreasing counter. The
>> resolution of the timer used to accumulate the current count can be
>> obtained by specifying a pointer value for PerformanceFrequency. The
>> value that is returned is the number of ticks per second. The count
>> starts accumulating when the computer is started up.
>>
>>
>> What I get on some specific customer machine is something that is not
>> “ticks per second”. Either the frequency is bogus, or the counter itself.
>>
>> I wrote a small user app to test it:
>>
>> int _tmain(int argc, _TCHAR* argv)
>> {
>> int i;
>> LARGE_INTEGER freq, counter;
>> SYSTEMTIME systemTime;
>>
>> for (i = 0; i < 10; i++)
>> {
>> GetSystemTime(&systemTime);
>>
>> if (QueryPerformanceCounter(&counter) == FALSE ||
>> QueryPerformanceFrequency(&freq) == FALSE)
>> {
>> printf(“Error getting performance counters\n”);
>> }
>>
>> printf(“Counter = %I64d Freq = %I64d”, counter.QuadPart, freq.QuadPart);
>> printf(" system: %02d:%02d:%02d\n",
>> systemTime.wHour,
>> systemTime.wMinute,
>> systemTime.wSecond);
>>
>> Sleep(1000);
>> }
>>
>> return 0;
>> }
>>
>> And this is the output on the failing machine:
>>
>> Counter = 56497408135970 Freq = 3158750000 system: 01:18:57
>> Counter = 56497818110218 Freq = 3158750000 system: 01:18:58
>> Counter = 56498206404250 Freq = 3158750000 system: 01:18:59
>> Counter = 56498715528269 Freq = 3158750000 system: 01:19:00
>> Counter = 56499113984213 Freq = 3158750000 system: 01:19:01
>> Counter = 56499489120527 Freq = 3158750000 system: 01:19:02
>> Counter = 56499867623469 Freq = 3158750000 system: 01:19:03
>> Counter = 56500252073478 Freq = 3158750000 system: 01:19:04
>> Counter = 56500713252945 Freq = 3158750000 system: 01:19:05
>> Counter = 56501096560332 Freq = 3158750000 system: 01:19:06
>>
>> If you make some computations, the counter seems to say that every
>> iteration is about 0.12 seconds apart from the previous one, while it
>> should be more or less 1 second.
>> The failing machine is running XP SP3 (hal.dll 5.1.2600.5687,
>> ntoskrnl.exe 5.1.2600.5938) on an Intel Core 2 Duo E8500.
>>
>> Has anyone ever seen this?
>>
>>
>> Have a nice day
>> GV
>>
>>
>>
>>
>

Sorry for following up to myself again but what I forgot about is that QPC
has its own implementation in usermode which boils down to
ntdll.RtlQueryPerformanceCounter. Nonethelesss it suffers from the same
problems as the kernel implementations, no instruction which flushes the
pipeline, so unreliable.

//Daniel

wrote in message news:xxxxx@ntdev…
> Athough it doesn’t explain the behavior of regular intervals of about
> 100ms for the sake of sanity I would also make sure you are running always
> on the same CPU by using SetThreadAffinityMask because each core has its
> own time stamp counter and they can be out of sync. Also disable variable
> speed features such as Intel Speedstep in the BIOS and read the rest of
> the recommendations in this article:
> http://msdn.microsoft.com/en-us/library/ee417693(VS.85).aspx
>
> //Daniel
>
>
> wrote in message news:xxxxx@ntdev…
>> I think the problem is that QPC is broken on Windows XP and Vista. The
>> CPU guides clearly state that RDTSC is not a serializing instruction and
>> is subject to out of order execution among other things and the various
>> implementations on Windows don’t do that. (On Win7 RDTSC is no longer
>> used possibly depending on available hardware features).
>>
>> On XP SP3:
>> hal!KeQueryPerformanceCounter:
>> 806ebb94 8bff mov edi,edi
>> 806ebb96 55 push ebp
>> 806ebb97 8bec mov ebp,esp
>> 806ebb99 5d pop ebp
>> 806ebb9a ff2548156f80 jmp dword ptr [hal!HalpHeapStart+0xc
>> (806f1548)]
>> 0: kd> t
>> hal!HalpAcpiTimerQueryPerfCount:
>> 806e4c78 a0dcd06e80 mov al,byte ptr [hal!HalpUse8254 (806ed0dc)]
>> 806e4c78 a0dcd06e80 mov al,byte ptr [hal!HalpUse8254 (806ed0dc)]
>> 806e4c7d 0ac0 or al,al
>> 806e4c7f 752d jne hal!HalpAcpiTimerQueryPerfCount+0x36
>> (806e4cae)
>> 806e4c81 8b4c2404 mov ecx,dword ptr [esp+4]
>> 806e4c85 0bc9 or ecx,ecx
>> 806e4c87 7412 je hal!HalpAcpiTimerQueryPerfCount+0x23
>> (806e4c9b)
>> 806e4c89 64a1a4000000 mov eax,dword ptr fs:[000000A4h]
>> 806e4c8f 648b15a8000000 mov edx,dword ptr fs:[0A8h]
>> 806e4c96 8901 mov dword ptr [ecx],eax
>> 806e4c98 895104 mov dword ptr [ecx+4],edx
>> 806e4c9b 0f31 rdtsc
>> 806e4c9d 640305ac000000 add eax,dword ptr fs:[0ACh]
>> 806e4ca4 641315b0000000 adc edx,dword ptr fs:[0B0h]
>> 806e4cab c20400 ret 4
>>
>> There is no serializing instruction here making RDTSC subject to out of
>> order execution among other things.
>>
>> What I would try is issue a CPUID serializing instruction before calling
>> QPC (__CPUID is included in intrin.h) and see if that solves the problem.
>>
>> You can read more about the difficulties getting RDTSC right in this
>> article:
>> http://www.ccsl.carleton.ca/~jamuir/rdtscpm1.pdf
>>
>> but you can read about these as well in the latest intel and AMD manuals.
>>
>> //Daniel
>>
>>
>>
>>
>> “Gianluca Varenni” wrote in message
>> news:xxxxx@ntdev…
>>> Hi all.
>>>
>>> A customer of mine reported a strange issue, and I tracked the issue
>>> down to wrong values returned by KeQueryPerformanceCounter (or the user
>>> counterpart QueryPerformanceCounter/Frequency).
>>>
>>> The MSDN docs clearly state that
>>>
>>> KeQueryPerformanceCounter always returns a 64-bit integer that
>>> represents the current value of a monotonically nondecreasing counter.
>>> The resolution of the timer used to accumulate the current count can be
>>> obtained by specifying a pointer value for PerformanceFrequency. The
>>> value that is returned is the number of ticks per second. The count
>>> starts accumulating when the computer is started up.
>>>
>>>
>>> What I get on some specific customer machine is something that is not
>>> “ticks per second”. Either the frequency is bogus, or the counter
>>> itself.
>>>
>>> I wrote a small user app to test it:
>>>
>>> int _tmain(int argc, _TCHAR* argv)
>>> {
>>> int i;
>>> LARGE_INTEGER freq, counter;
>>> SYSTEMTIME systemTime;
>>>
>>> for (i = 0; i < 10; i++)
>>> {
>>> GetSystemTime(&systemTime);
>>>
>>> if (QueryPerformanceCounter(&counter) == FALSE ||
>>> QueryPerformanceFrequency(&freq) == FALSE)
>>> {
>>> printf(“Error getting performance counters\n”);
>>> }
>>>
>>> printf(“Counter = %I64d Freq = %I64d”, counter.QuadPart, freq.QuadPart);
>>> printf(" system: %02d:%02d:%02d\n",
>>> systemTime.wHour,
>>> systemTime.wMinute,
>>> systemTime.wSecond);
>>>
>>> Sleep(1000);
>>> }
>>>
>>> return 0;
>>> }
>>>
>>> And this is the output on the failing machine:
>>>
>>> Counter = 56497408135970 Freq = 3158750000 system: 01:18:57
>>> Counter = 56497818110218 Freq = 3158750000 system: 01:18:58
>>> Counter = 56498206404250 Freq = 3158750000 system: 01:18:59
>>> Counter = 56498715528269 Freq = 3158750000 system: 01:19:00
>>> Counter = 56499113984213 Freq = 3158750000 system: 01:19:01
>>> Counter = 56499489120527 Freq = 3158750000 system: 01:19:02
>>> Counter = 56499867623469 Freq = 3158750000 system: 01:19:03
>>> Counter = 56500252073478 Freq = 3158750000 system: 01:19:04
>>> Counter = 56500713252945 Freq = 3158750000 system: 01:19:05
>>> Counter = 56501096560332 Freq = 3158750000 system: 01:19:06
>>>
>>> If you make some computations, the counter seems to say that every
>>> iteration is about 0.12 seconds apart from the previous one, while it
>>> should be more or less 1 second.
>>> The failing machine is running XP SP3 (hal.dll 5.1.2600.5687,
>>> ntoskrnl.exe 5.1.2600.5938) on an Intel Core 2 Duo E8500.
>>>
>>> Has anyone ever seen this?
>>>
>>>
>>> Have a nice day
>>> GV
>>>
>>>
>>>
>>>
>>
>


From:
Sent: Wednesday, September 01, 2010 7:41 PM
To: “Windows System Software Devs Interest List”
Subject: RE:[ntdev] Interesting issue with (Ke)QueryPerformanceCounter

> I suggest you instead of sleep() run a tight loop waiting for the time to
> jump to the next second and see if the performance counter will behave
> better.

That would prove that it’s a power management issue. It still doesn’t solve
the problem of QueryPerformanceCounter returning bogus numbers :frowning:

Have a nice day
GV

>
> In other words, the PerfCount may run with the claimed speed only when
> you’re actually doing something. If the processor is idle, then power
> management may kick in
>
> —
> NTDEV is sponsored by OSR
>
> For our schedule of WDF, WDM, debugging and other seminars visit:
> http://www.osr.com/seminars
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer

You’re right… that IS a known bug. But Gianluca is reporting here isn’t that the time being returned is ragged, highly variable, or off “a little”… he’s reporting that it’s off by almost A FACTOR OF MAGNITUDE.

I’m having trouble believing out of order execution, or reading the TSC on two different processors which are not kept in sync, could be to blame for THAT level of error. Or, do you have a scenario in mind that would explain this.

This finding is really some pretty scary stuff, at least in my mind.

Peter
OSR