KeQueryInterruptTime() issue
in [Device Drivers]
|
From: JRHeisey on 21 Dec 2007 13:38 > - One millisecond is the smallest interrupt endpoint polling interval. > An interesting observation that is probably not relevant is that I can > see several calls to the interrupt endpoint completion routine in less > than a millisecond time frame then a 15.625 millisecond pause before > the next round of calls. I presume this is a result of some thread > scheduling quantum. I've reposted this from another thread as a side issue. I have additional comments. I've been thinking about this some more. I am using the KeQueryInterruptTime() for my timing data. I've included a sample of my timing data at the end of this message. KeQueryInterruptTime() is suppose to be a count of 100 nanoseconds in a 64 bit value. The numbers I display I only use the least significant 4 bytes. intComp - USB controller calls my device driver. IntRead - User mode calls IOCTL to read interrupt endpoint data. WComp - Kernel entry to Write on bulk endpoint. RComp - Kernel entry to Rread on bulk endpoint. UserWrite - User mode entry of write on bulk endpoint. UserRead - User mode entry of read on bulk endpoint. I find it odd that I can see many events where KeQueryInterruptTime() returns the same value. This now seems to me that the 15.625 quantum is a result of the granularity of the KeQueryInterruptTime() function. I used this function because I thought I would get better timing granularity. The Windows DDK help says: KeQueryInterruptTime can be used for performance tuning. This routine returns a finer grained measurement than calling KeQueryTickCount. A call to KeQueryInterruptTime has considerably less overhead than a call to KeQueryPerformanceCounter, as well. I've only executed this code on one computer so far. Perhaps this issue is system dependent? J.R. /////////////////////////////////////////////////////////////////////////////// Note: 'Delta ms' is KeQueryInterrupt time difference divided by 10000. KeQuery Delta InterruptTime ms Event 2662655427 15.625 IntRead 2662655427 0.000 IntComp 2662655427 0.000 IntRead 2662655427 0.000 IntComp 2662655427 0.000 IntRead 2662655427 0.000 WComp 2662655427 0.000 UserWrite 2662655427 0.000 RComp 2662655427 0.000 UserRead 2662811677 15.625 IntComp 2662811677 0.000 IntRead 2662811677 0.000 RComp 2662811677 0.000 UserRead 2662811677 0.000 IntComp 2662811677 0.000 IntRead 2662811677 0.000 IntComp 2662811677 0.000 IntRead 2662811677 0.000 WComp 2662811677 0.000 IntComp 2662811677 0.000 IntRead 2662811677 0.000 UserWrite 2662811677 0.000 RComp 2662811677 0.000 UserRead 2662811677 0.000 IntComp 2662811677 0.000 IntRead 2662811677 0.000 RComp 2662811677 0.000 UserRead 2662811677 0.000 IntComp 2662811677 0.000 IntRead 2662967927 15.625 WComp 2662967927 0.000 UserWrite 2662967927 0.000 RComp 2662967927 0.000 IntComp 2662967927 0.000 IntRead 2662967927 0.000 IntComp 2663124177 15.625 IntComp 2663124177 0.000 IntComp 2663124177 0.000 IntRead 2663124177 0.000 IntRead 2663124177 0.000 IntRead
From: Pavel A. on 21 Dec 2007 13:42 The 15.6 ms is suspisiously close to the timer tick value on many PC platforms... --PA <JRHeisey(a)aol.com> wrote in message news:38fd8e9b-cd6b-46d0-a10e-3b0c2a54d88c(a)b40g2000prf.googlegroups.com... >> - One millisecond is the smallest interrupt endpoint polling interval. > >> An interesting observation that is probably not relevant is that I can >> see several calls to the interrupt endpoint completion routine in less >> than a millisecond time frame then a 15.625 millisecond pause before >> the next round of calls. I presume this is a result of some thread >> scheduling quantum. > > I've reposted this from another thread as a side issue. I have > additional comments. > > I've been thinking about this some more. I am using the > KeQueryInterruptTime() for my timing data. I've included a sample of > my timing data at the end of this message. > > KeQueryInterruptTime() is suppose to be a count of 100 nanoseconds in > a 64 bit value. The numbers I display I only use the least significant > 4 bytes. > > intComp - USB controller calls my device driver. > IntRead - User mode calls IOCTL to read interrupt endpoint data. > WComp - Kernel entry to Write on bulk endpoint. > RComp - Kernel entry to Rread on bulk endpoint. > UserWrite - User mode entry of write on bulk endpoint. > UserRead - User mode entry of read on bulk endpoint. > > I find it odd that I can see many events where KeQueryInterruptTime() > returns the same value. This now seems to me that the 15.625 quantum > is a result of the granularity of the KeQueryInterruptTime() function. > I used this function because I thought I would get better timing > granularity. > > The Windows DDK help says: > > KeQueryInterruptTime can be used for performance tuning. This routine > returns a finer grained measurement than calling KeQueryTickCount. A > call to KeQueryInterruptTime has considerably less overhead than a > call to KeQueryPerformanceCounter, as well. > > I've only executed this code on one computer so far. Perhaps this > issue is system dependent? > > J.R. > /////////////////////////////////////////////////////////////////////////////// > Note: 'Delta ms' is KeQueryInterrupt time difference divided by 10000. > > KeQuery Delta > InterruptTime ms Event > > 2662655427 15.625 IntRead > 2662655427 0.000 IntComp > 2662655427 0.000 IntRead > 2662655427 0.000 IntComp > 2662655427 0.000 IntRead > 2662655427 0.000 WComp > 2662655427 0.000 UserWrite > 2662655427 0.000 RComp > 2662655427 0.000 UserRead > 2662811677 15.625 IntComp > 2662811677 0.000 IntRead > 2662811677 0.000 RComp > 2662811677 0.000 UserRead > 2662811677 0.000 IntComp > 2662811677 0.000 IntRead > 2662811677 0.000 IntComp > 2662811677 0.000 IntRead > 2662811677 0.000 WComp > 2662811677 0.000 IntComp > 2662811677 0.000 IntRead > 2662811677 0.000 UserWrite > 2662811677 0.000 RComp > 2662811677 0.000 UserRead > 2662811677 0.000 IntComp > 2662811677 0.000 IntRead > 2662811677 0.000 RComp > 2662811677 0.000 UserRead > 2662811677 0.000 IntComp > 2662811677 0.000 IntRead > 2662967927 15.625 WComp > 2662967927 0.000 UserWrite > 2662967927 0.000 RComp > 2662967927 0.000 IntComp > 2662967927 0.000 IntRead > 2662967927 0.000 IntComp > 2663124177 15.625 IntComp > 2663124177 0.000 IntComp > 2663124177 0.000 IntRead > 2663124177 0.000 IntRead > 2663124177 0.000 IntRead
From: Tim Roberts on 23 Dec 2007 00:31 JRHeisey(a)aol.com wrote: > >I've been thinking about this some more. I am using the >KeQueryInterruptTime() for my timing data. I've included a sample of >my timing data at the end of this message. >... >I find it odd that I can see many events where KeQueryInterruptTime() >returns the same value. This now seems to me that the 15.625 quantum >is a result of the granularity of the KeQueryInterruptTime() function. >I used this function because I thought I would get better timing >granularity. You only get better granularity if someone updates the timing interval. You might try running an application like this: int main() { timeBeginPeriod( 1 ); _getch(); timeEndPeriod( 1 ); } Then do your test while it waits for a keystroke. Have you considered using URB_FUNCTION_GET_CURRENT_FRAME_NUMBER for your timing? That will get you millisecond resolution. -- Tim Roberts, timr(a)probo.com Providenza & Boekelheide, Inc.
|
Pages: 1 Prev: Mirror Driver Installation Next: Device Status Code 37 (DriverEntry failure) spiteful problem. |