What could be explaining a 10 ms DPC latency?

I have a DPC that is scheduled to be invoked by a timer every 20 ms.

That DPC is responsible for simply fetching an IRP from a cancel-safe-
queue, do an operation that takes **less than a microsecond**, then
completing the IRP.

Using high-resolution measurements (WPP etc.) the time it takes from
the moment the IRP is placed into the cancel-safe-queue until it is
completed is consistently 30 ms - for each and every IRP.

My simple arithmetics suggests that since CPU use at the time of
measurements shows less than 5%, that pend-to-complete time should
actually be around 20 ms, not 30 ms. At the moment, I can't think of
anything that would preempt the system in such a consistent manner
that would *always* add 10 ms latency to invoking that DPC.

Obviously I am wrong. Otherwise I wouldn't have received such results.

What could be my mistake? What could be explaining that consistent 10
ms latency?

Thanks,
Don

0dbell
Sun Mar 30 07:56:19 CDT 2008

On Mar 30, 2:46 am, 0db...@gmail.com wrote:
> I have a DPC that is scheduled to be invoked by a timer every 20 ms.
>
> That DPC is responsible for simply fetching an IRP from a cancel-safe-
> queue, do an operation that takes **less than a microsecond**, then
> completing the IRP.
>
> Using high-resolution measurements (WPP etc.) the time it takes from
> the moment the IRP is placed into the cancel-safe-queue until it is
> completed is consistently 30 ms - for each and every IRP.
>
> My simple arithmetics suggests that since CPU use at the time of
> measurements shows less than 5%, that pend-to-complete time should
> actually be around 20 ms, not 30 ms. At the moment, I can't think of
> anything that would preempt the system in such a consistent manner
> that would *always* add 10 ms latency to invoking that DPC.
>
> Obviously I am wrong. Otherwise I wouldn't have received such results.
>
> What could be my mistake? What could be explaining that consistent 10
> ms latency?
>

OK, I got some more measurements and discovered that this has nothing
to do with the IRPs. That is, if I track this timer-based DPC only
**without any IRPs pending whatsoever*, I still get this DPC fired
every 30ms instead of 20ms.

Why?

What could be explaining such gross rounding up? I understand if the
system cannot honor an 19.5 ms request and providing 19-21 ms jitter,
for example. But 30 ms instead of 20 ms ??? This is a 50% deviation...

Any explanation?

> Thanks,
> Don

Alexander
Sun Mar 30 09:16:33 CDT 2008

The timer granularity is about 15 ms. You can only get it fired at 15, 30,
45, etc.

<0dbell@gmail.com> wrote in message
news:2798fb4c-a8fb-4096-a4f0-c5ccdbc23326@b1g2000hsg.googlegroups.com...
> On Mar 30, 2:46 am, 0db...@gmail.com wrote:
>> I have a DPC that is scheduled to be invoked by a timer every 20 ms.
>>
>> That DPC is responsible for simply fetching an IRP from a cancel-safe-
>> queue, do an operation that takes **less than a microsecond**, then
>> completing the IRP.
>>
>> Using high-resolution measurements (WPP etc.) the time it takes from
>> the moment the IRP is placed into the cancel-safe-queue until it is
>> completed is consistently 30 ms - for each and every IRP.
>>
>> My simple arithmetics suggests that since CPU use at the time of
>> measurements shows less than 5%, that pend-to-complete time should
>> actually be around 20 ms, not 30 ms. At the moment, I can't think of
>> anything that would preempt the system in such a consistent manner
>> that would *always* add 10 ms latency to invoking that DPC.
>>
>> Obviously I am wrong. Otherwise I wouldn't have received such results.
>>
>> What could be my mistake? What could be explaining that consistent 10
>> ms latency?
>>
>
> OK, I got some more measurements and discovered that this has nothing
> to do with the IRPs. That is, if I track this timer-based DPC only
> **without any IRPs pending whatsoever*, I still get this DPC fired
> every 30ms instead of 20ms.
>
> Why?
>
> What could be explaining such gross rounding up? I understand if the
> system cannot honor an 19.5 ms request and providing 19-21 ms jitter,
> for example. But 30 ms instead of 20 ms ??? This is a 50% deviation...
>
> Any explanation?
>
>> Thanks,
>> Don
>

Alexander
Sun Mar 30 09:15:34 CDT 2008

Make sure you're not using LowImportance DPC. By default, DPC is
initialiazed with MediumImportance.
If you schedule the DPC to different target processor, MediumImportance DPC
might get throttled and have some latency in some conditions, too..

<0dbell@gmail.com> wrote in message
news:6c5f505b-4a62-4f87-b55a-ef0d4e19616c@t54g2000hsg.googlegroups.com...
>I have a DPC that is scheduled to be invoked by a timer every 20 ms.
>
> That DPC is responsible for simply fetching an IRP from a cancel-safe-
> queue, do an operation that takes **less than a microsecond**, then
> completing the IRP.
>
> Using high-resolution measurements (WPP etc.) the time it takes from
> the moment the IRP is placed into the cancel-safe-queue until it is
> completed is consistently 30 ms - for each and every IRP.
>
> My simple arithmetics suggests that since CPU use at the time of
> measurements shows less than 5%, that pend-to-complete time should
> actually be around 20 ms, not 30 ms. At the moment, I can't think of
> anything that would preempt the system in such a consistent manner
> that would *always* add 10 ms latency to invoking that DPC.
>
> Obviously I am wrong. Otherwise I wouldn't have received such results.
>
> What could be my mistake? What could be explaining that consistent 10
> ms latency?
>
> Thanks,
> Don

0dbell
Sun Mar 30 10:44:36 CDT 2008

On Mar 30, 10:16 am, "Alexander Grigoriev" <al...@earthlink.net>
wrote:
> The timer granularity is about 15 ms. You can only get it fired at 15, 30,
> 45, etc.
>

Wow! How on earth could have I known that? The WDK/DDK documentation
keeps mentioning that the default system timer is set at 10ms, so I
thought that a multiple of that would be a safe bet to *not* get
rounded to an unknown value.

Back then in the DOS days there used to be an only timer in the system
with a resolution of 18.2 ms but I thought that those days have long
gone since the introduction of high-performance counters in hardware,
supporting resolutions of *micro* seconds. Have I been mistaken?

I understand where the strange value of 18.2 ms came from, but 15 ms -
where is it derived from? Where, in the WDK documentation, can I find
information about that 15 ms granularity of DPCs?

Alexander, thank you very much for your help - I have been pulling my
hair in the last days trying to figure out timing measurements that I
could not explain.

I will refer to your other answer (regarding DPC importance) when I
get to experiment with KeSetImportanceDpc().

Thanks,
Don

Maxim
Sun Mar 30 12:59:02 CDT 2008

> Back then in the DOS days there used to be an only timer in the system
> with a resolution of 18.2 ms

18.2 ticks per second IIRC, which is around 55ms

> gone since the introduction of high-performance counters in hardware,
> supporting resolutions of *micro* seconds. Have I been mistaken?

With Windows - yes. Windows is just unable to measure time with accuracy more
then 10-15ms.

You can use HPETs and RDTSC in Windows, but you cannot associate any Windows
events with such a high-precision timer.

--
Maxim Shatskih, Windows DDK MVP
StorageCraft Corporation
maxim@storagecraft.com
http://www.storagecraft.com

Alexander
Sun Mar 30 14:39:52 CDT 2008

There is no DPC time granularity; most of the time it will fire as soon as
possible, except for some special cases. But the timer (KTIMER) is not
particularly precise; it only fires at the timer ticks. You can change its
resolution down to 1 or 2 ms. It used to affect system overhead
significantly, but for modern processors it's not a big deal anymore.

<0dbell@gmail.com> wrote in message
news:8b98a173-dded-4745-95f8-8277b0ab09a0@u10g2000prn.googlegroups.com...
> On Mar 30, 10:16 am, "Alexander Grigoriev" <al...@earthlink.net>
> wrote:
>> The timer granularity is about 15 ms. You can only get it fired at 15,
>> 30,
>> 45, etc.
>>
>
> Wow! How on earth could have I known that? The WDK/DDK documentation
> keeps mentioning that the default system timer is set at 10ms, so I
> thought that a multiple of that would be a safe bet to *not* get
> rounded to an unknown value.
>
> Back then in the DOS days there used to be an only timer in the system
> with a resolution of 18.2 ms but I thought that those days have long
> gone since the introduction of high-performance counters in hardware,
> supporting resolutions of *micro* seconds. Have I been mistaken?
>
> I understand where the strange value of 18.2 ms came from, but 15 ms -
> where is it derived from? Where, in the WDK documentation, can I find
> information about that 15 ms granularity of DPCs?
>
> Alexander, thank you very much for your help - I have been pulling my
> hair in the last days trying to figure out timing measurements that I
> could not explain.
>
> I will refer to your other answer (regarding DPC importance) when I
> get to experiment with KeSetImportanceDpc().
>
> Thanks,
> Don

Vladimir
Sun Mar 30 16:48:51 CDT 2008

Try to profile your scenario using Windows Performance Tools
(http://www.microsoft.com/whdc/system/sysperf/perftools.mspx).
Vladimir.

<0dbell@gmail.com> wrote in message
news:8b98a173-dded-4745-95f8-8277b0ab09a0@u10g2000prn.googlegroups.com...
> On Mar 30, 10:16 am, "Alexander Grigoriev" <al...@earthlink.net>
> wrote:
>> The timer granularity is about 15 ms. You can only get it fired at 15,
>> 30,
>> 45, etc.
>>
>
> Wow! How on earth could have I known that? The WDK/DDK documentation
> keeps mentioning that the default system timer is set at 10ms, so I
> thought that a multiple of that would be a safe bet to *not* get
> rounded to an unknown value.
>
> Back then in the DOS days there used to be an only timer in the system
> with a resolution of 18.2 ms but I thought that those days have long
> gone since the introduction of high-performance counters in hardware,
> supporting resolutions of *micro* seconds. Have I been mistaken?
>
> I understand where the strange value of 18.2 ms came from, but 15 ms -
> where is it derived from? Where, in the WDK documentation, can I find
> information about that 15 ms granularity of DPCs?
>
> Alexander, thank you very much for your help - I have been pulling my
> hair in the last days trying to figure out timing measurements that I
> could not explain.
>
> I will refer to your other answer (regarding DPC importance) when I
> get to experiment with KeSetImportanceDpc().
>
> Thanks,
> Don

Pavel
Mon Mar 31 20:54:04 CDT 2008

It seems that the timer granularity of 15 ms still remains unexplained,
after all discussions here and in ntdev.
All recent PCs I've tried, have 15 ms by default, and the minimal resolution
for them is 2 ms.
On older machines where the default resolution was 10 ms, the minimum was 1
ms.
(I've made a quick test based on Sysinternals clockres sample, using
NtSetTimerResolution, NtQueryTimerResolution)

Regards,
--PA

"Alexander Grigoriev" <alegr@earthlink.net> wrote in message
news:OY7QU3pkIHA.5260@TK2MSFTNGP03.phx.gbl...
> There is no DPC time granularity; most of the time it will fire as soon as
> possible, except for some special cases. But the timer (KTIMER) is not
> particularly precise; it only fires at the timer ticks. You can change its
> resolution down to 1 or 2 ms. It used to affect system overhead
> significantly, but for modern processors it's not a big deal anymore.
>
> <0dbell@gmail.com> wrote in message
> news:8b98a173-dded-4745-95f8-8277b0ab09a0@u10g2000prn.googlegroups.com...
>> On Mar 30, 10:16 am, "Alexander Grigoriev" <al...@earthlink.net>
>> wrote:
>>> The timer granularity is about 15 ms. You can only get it fired at 15,
>>> 30,
>>> 45, etc.
>>>
>>
>> Wow! How on earth could have I known that? The WDK/DDK documentation
>> keeps mentioning that the default system timer is set at 10ms, so I
>> thought that a multiple of that would be a safe bet to *not* get
>> rounded to an unknown value.
>>
>> Back then in the DOS days there used to be an only timer in the system
>> with a resolution of 18.2 ms but I thought that those days have long
>> gone since the introduction of high-performance counters in hardware,
>> supporting resolutions of *micro* seconds. Have I been mistaken?
>>
>> I understand where the strange value of 18.2 ms came from, but 15 ms -
>> where is it derived from? Where, in the WDK documentation, can I find
>> information about that 15 ms granularity of DPCs?
>>
>> Alexander, thank you very much for your help - I have been pulling my
>> hair in the last days trying to figure out timing measurements that I
>> could not explain.
>>
>> I will refer to your other answer (regarding DPC importance) when I
>> get to experiment with KeSetImportanceDpc().
>>
>> Thanks,
>> Don
>
>

Ben
Thu Apr 03 09:04:08 CDT 2008

Pavel A. wrote:
> It seems that the timer granularity of 15 ms still remains
> unexplained, after all discussions here and in ntdev.
> All recent PCs I've tried, have 15 ms by default, and the minimal
> resolution for them is 2 ms.
> On older machines where the default resolution was 10 ms, the minimum
> was 1 ms.

multiprocessor vs uniprocessor hal, perhaps.

> (I've made a quick test based on Sysinternals clockres sample, using
> NtSetTimerResolution, NtQueryTimerResolution)
>
> Regards,
> --PA
>
> "Alexander Grigoriev" <alegr@earthlink.net> wrote in message
> news:OY7QU3pkIHA.5260@TK2MSFTNGP03.phx.gbl...
>> There is no DPC time granularity; most of the time it will fire as
>> soon as possible, except for some special cases. But the timer
>> (KTIMER) is not particularly precise; it only fires at the timer
>> ticks. You can change its resolution down to 1 or 2 ms. It used to
>> affect system overhead significantly, but for modern processors it's
>> not a big deal anymore. <0dbell@gmail.com> wrote in message
>> news:8b98a173-dded-4745-95f8-8277b0ab09a0@u10g2000prn.googlegroups.com...
>>> On Mar 30, 10:16 am, "Alexander Grigoriev" <al...@earthlink.net>
>>> wrote:
>>>> The timer granularity is about 15 ms. You can only get it fired at
>>>> 15, 30,
>>>> 45, etc.
>>>>
>>>
>>> Wow! How on earth could have I known that? The WDK/DDK documentation
>>> keeps mentioning that the default system timer is set at 10ms, so I
>>> thought that a multiple of that would be a safe bet to *not* get
>>> rounded to an unknown value.
>>>
>>> Back then in the DOS days there used to be an only timer in the
>>> system with a resolution of 18.2 ms but I thought that those days
>>> have long gone since the introduction of high-performance counters
>>> in hardware, supporting resolutions of *micro* seconds. Have I been
>>> mistaken? I understand where the strange value of 18.2 ms came from, but
>>> 15
>>> ms - where is it derived from? Where, in the WDK documentation, can
>>> I find information about that 15 ms granularity of DPCs?
>>>
>>> Alexander, thank you very much for your help - I have been pulling
>>> my hair in the last days trying to figure out timing measurements
>>> that I could not explain.
>>>
>>> I will refer to your other answer (regarding DPC importance) when I
>>> get to experiment with KeSetImportanceDpc().
>>>
>>> Thanks,
>>> Don