Long URB cancellation at Vista

NTDEV
1

We encountered a strange USB behaviour at Vista. Basically, when my driver calls IoCancelIrp() for an URB/IRP previously submitted for interrupt endpoint, it returns immediatelly TRUE but completion routine is called long time before. Time is random between 0 - 516 ms with median around 400 ms. It is way too much.

It occurs only at some machines and with both x86 and x64 system. No problem at XP as usual. Machines differ, some have Intel Core Duo and some Athlons x64 and different chipsets. All have OHCI HCs but I have other machine with OHCI which doesn’t show a problem.

Any idea what could cause something like this?

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

2

Sorry, I mean completion routine is called long time *after* IoCancelIrp() of course. And there is no other USB activity at this moment.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

From: xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com] on behalf of Michal Vodicka[SMTP:xxxxx@upek.com]
Reply To: Windows System Software Devs Interest List
Sent: Thursday, January 11, 2007 6:53 AM
To: Windows System Software Devs Interest List
Subject: [ntdev] Long URB cancellation at Vista

We encountered a strange USB behaviour at Vista. Basically, when my driver calls IoCancelIrp() for an URB/IRP previously submitted for interrupt endpoint, it returns immediatelly TRUE but completion routine is called long time before. Time is random between 0 - 516 ms with median around 400 ms. It is way too much.

It occurs only at some machines and with both x86 and x64 system. No problem at XP as usual. Machines differ, some have Intel Core Duo and some Athlons x64 and different chipsets. All have OHCI HCs but I have other machine with OHCI which doesn’t show a problem.

Any idea what could cause something like this?

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

Questions? First check the Kernel Driver FAQ at http://www.osronline.com/article.cfm?id=256

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

3

IoCancelIrp has no timing guarantees and 400 ms is not that long. What problem is the “delay” causing?

d

4

The problem is the way how user mode code which use it is written. It instructs driver to enable interrupt endpoint polling and waits. Device indicates data availability using special interrupt value which in turn awakes code. Code examines the value and if it is expected, it calls the driver to stop polling and instruct device to start send data. It is synchronous so device doesn’t start data transfer until polling is stopped (driver now always reused the IRP and restarts polling automatically).

Yes, the software can be changed. We can stop polling asynchronously. I can make driver more intelligent to not resubmit URB when desired value is read (so there is nothing to cancel).

But the delay can be only symptom, not the problem itself. I presume root cause is worse problem. Our software works with no delays at w2k, XP and at most Vista machines. Only some have this problem and always when I saw something like this there were some race conditions in the USB stack. I’m affraid other USB communication can be blocked for the same time.

I understand there is no timing guarantee but why should interrupt endpoint polling stop take so long time? Even if I make it completely asynchronous, polling during data transfer unnecessarily consumes bandwidth. Our device design presumes events are serialized. It is fingerprint reader which should handle 20 cm/s finger move and has almost no memory. It sends all data immediatelly to host software. Imagine what we capture with 400 ms delay (virtually nothing); it is ages.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

From: xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com] on behalf of xxxxx@Microsoft.com[SMTP:xxxxx@Microsoft.com]
Reply To: Windows System Software Devs Interest List
Sent: Thursday, January 11, 2007 7:41 AM
To: Windows System Software Devs Interest List
Subject: RE:[ntdev] Long URB cancellation at Vista

IoCancelIrp has no timing guarantees and 400 ms is not that long. What problem is the “delay” causing?

d

Questions? First check the Kernel Driver FAQ at http://www.osronline.com/article.cfm?id=256

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

5

Intel ICH based systems have EHCI, not OHCI (and the companion controllers are UHCI)
Is your scanner high speed (USB2) or less (USB1) ? if the latter, it is attached to a companion controller.

Regards,
–PA

6

xxxxx@Microsoft.com wrote:

IoCancelIrp has no timing guarantees and 400 ms is not that long.

Not that long? A modern CPU will have executed almost a billion
instructions in that amount of time!

I understand there are no timing guarantees, but that number seems about
three orders of magnitude too large to me.

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

7

> ----------

From: xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com] on behalf of Tim Roberts[SMTP:xxxxx@probo.com]
Reply To: Windows System Software Devs Interest List
Sent: Thursday, January 11, 2007 6:43 PM
To: Windows System Software Devs Interest List
Subject: Re: [ntdev] Long URB cancellation at Vista

xxxxx@Microsoft.com wrote:
> IoCancelIrp has no timing guarantees and 400 ms is not that long.

Not that long? A modern CPU will have executed almost a billion
instructions in that amount of time!

Exactly. In addition, these computers have nothing else to do during test and CPU utilization is near to zero.

I understand there are no timing guarantees, but that number seems about
three orders of magnitude too large to me.

For me, too. Normally I can measure 0 or 15 ms.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

8

Scanner is full speed and there are EHCI + OHCI controllers. I’m not quite sure about their chipsets now.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

From: xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com] on behalf of xxxxx@writeme.com[SMTP:xxxxx@writeme.com]
Reply To: Windows System Software Devs Interest List
Sent: Thursday, January 11, 2007 4:23 PM
To: Windows System Software Devs Interest List
Subject: RE:[ntdev] Long URB cancellation at Vista

Intel ICH based systems have EHCI, not OHCI (and the companion controllers are UHCI)
Is your scanner high speed (USB2) or less (USB1) ? if the latter, it is attached to a companion controller.

Regards,
–PA

Questions? First check the Kernel Driver FAQ at http://www.osronline.com/article.cfm?id=256

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

9

Oh if only request cancellation were a compute bound problem. Then all
those CPU cycles would be useful.

-p

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Michal Vodicka
Sent: Thursday, January 11, 2007 1:33 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Long URB cancellation at Vista

From:
xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com
] on behalf of Tim Roberts[SMTP:xxxxx@probo.com]
Reply To: Windows System Software Devs Interest List
Sent: Thursday, January 11, 2007 6:43 PM
To: Windows System Software Devs Interest List
Subject: Re: [ntdev] Long URB cancellation at Vista

xxxxx@Microsoft.com wrote:
> IoCancelIrp has no timing guarantees and 400 ms is not that long.

Not that long? A modern CPU will have executed almost a billion
instructions in that amount of time!

Exactly. In addition, these computers have nothing else to do during
test and CPU utilization is near to zero.

I understand there are no timing guarantees, but that number seems
about
three orders of magnitude too large to me.

For me, too. Normally I can measure 0 or 15 ms.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256

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

10

I know. It looks as cancellation is postponed to some worker thread which is awakened once per 500 ms (upper bound is 516 ms). Or depends on something like this. Any idea how to find root cause of the problem?

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

From: xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com] on behalf of Peter Wieland[SMTP:xxxxx@windows.microsoft.com]
Reply To: Windows System Software Devs Interest List
Sent: Thursday, January 11, 2007 10:42 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Long URB cancellation at Vista

Oh if only request cancellation were a compute bound problem. Then all
those CPU cycles would be useful.

-p

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Michal Vodicka
Sent: Thursday, January 11, 2007 1:33 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Long URB cancellation at Vista

> ----------
> From:
xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com
] on behalf of Tim Roberts[SMTP:xxxxx@probo.com]
> Reply To: Windows System Software Devs Interest List
> Sent: Thursday, January 11, 2007 6:43 PM
> To: Windows System Software Devs Interest List
> Subject: Re: [ntdev] Long URB cancellation at Vista
>
> xxxxx@Microsoft.com wrote:
> > IoCancelIrp has no timing guarantees and 400 ms is not that long.
>
> Not that long? A modern CPU will have executed almost a billion
> instructions in that amount of time!
>
Exactly. In addition, these computers have nothing else to do during
test and CPU utilization is near to zero.

> I understand there are no timing guarantees, but that number seems
about
> three orders of magnitude too large to me.
>
For me, too. Normally I can measure 0 or 15 ms.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256

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

Questions? First check the Kernel Driver FAQ at http://www.osronline.com/article.cfm?id=256

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

11

What’s the call stack look like that calls IoCompleteRequest?

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of Michal Vodicka
Sent: Thursday, January 11, 2007 2:29 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Long URB cancellation at Vista

I know. It looks as cancellation is postponed to some worker thread which is awakened once per 500 ms (upper bound is 516 ms). Or depends on something like this. Any idea how to find root cause of the problem?

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

From: xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com] on behalf of Peter Wieland[SMTP:xxxxx@windows.microsoft.com]
Reply To: Windows System Software Devs Interest List
Sent: Thursday, January 11, 2007 10:42 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Long URB cancellation at Vista

Oh if only request cancellation were a compute bound problem. Then all
those CPU cycles would be useful.

-p

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Michal Vodicka
Sent: Thursday, January 11, 2007 1:33 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Long URB cancellation at Vista

> ----------
> From:
xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com
] on behalf of Tim Roberts[SMTP:xxxxx@probo.com]
> Reply To: Windows System Software Devs Interest List
> Sent: Thursday, January 11, 2007 6:43 PM
> To: Windows System Software Devs Interest List
> Subject: Re: [ntdev] Long URB cancellation at Vista
>
> xxxxx@Microsoft.com wrote:
> > IoCancelIrp has no timing guarantees and 400 ms is not that long.
>
> Not that long? A modern CPU will have executed almost a billion
> instructions in that amount of time!
>
Exactly. In addition, these computers have nothing else to do during
test and CPU utilization is near to zero.

> I understand there are no timing guarantees, but that number seems
about
> three orders of magnitude too large to me.
>
For me, too. Normally I can measure 0 or 15 ms.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256

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

Questions? First check the Kernel Driver FAQ at http://www.osronline.com/article.cfm?id=256

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

Questions? First check the Kernel Driver FAQ at http://www.osronline.com/article.cfm?id=256

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

12

I’m not sure about on Vista, but I have run into issues with some
chipsets on XP. In these cases, the controller didn’t notify the driver
that it was ok to remove the transfer from the schedule (no interrupt).
Periodically the driver would check the state of the hardware just in
case. During this check, the driver would notice that the transfer was
ready to remove, and the cancellation would proceed.

During Winusb development, I had a cancellation unit test case. Usually
this test case would complete in less than 10ms, but occasionally it
would spike to a very large time (like you see below).

There was some work to improve this worst case time, though I’m not sure
what happened with that work.

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Michal Vodicka
Sent: Thursday, January 11, 2007 2:29 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Long URB cancellation at Vista

I know. It looks as cancellation is postponed to some worker thread
which is awakened once per 500 ms (upper bound is 516 ms). Or depends on
something like this. Any idea how to find root cause of the problem?

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

From:
xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com
] on behalf of Peter Wieland[SMTP:xxxxx@windows.microsoft.com]
Reply To: Windows System Software Devs Interest List
Sent: Thursday, January 11, 2007 10:42 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Long URB cancellation at Vista

Oh if only request cancellation were a compute bound problem. Then
all
those CPU cycles would be useful.

-p

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Michal Vodicka
Sent: Thursday, January 11, 2007 1:33 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Long URB cancellation at Vista

> ----------
> From:

xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com

] on behalf of Tim Roberts[SMTP:xxxxx@probo.com]
> Reply To: Windows System Software Devs Interest List
> Sent: Thursday, January 11, 2007 6:43 PM
> To: Windows System Software Devs Interest List
> Subject: Re: [ntdev] Long URB cancellation at Vista
>
> xxxxx@Microsoft.com wrote:
> > IoCancelIrp has no timing guarantees and 400 ms is not that long.
>
> Not that long? A modern CPU will have executed almost a billion
> instructions in that amount of time!
>
Exactly. In addition, these computers have nothing else to do during
test and CPU utilization is near to zero.

> I understand there are no timing guarantees, but that number seems
about
> three orders of magnitude too large to me.
>
For me, too. Normally I can measure 0 or 15 ms.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256

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

Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256

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

Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256

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

13

I haven’t debugged it, yet. It seems I’ll have to and this one looks like a good idea. Examine and compare with system which doesn’t show the delay. Thanks.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

From: xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com] on behalf of Arlie Davis[SMTP:xxxxx@microsoft.com]
Reply To: Windows System Software Devs Interest List
Sent: Thursday, January 11, 2007 11:45 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Long URB cancellation at Vista

What’s the call stack look like that calls IoCompleteRequest?

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of Michal Vodicka
Sent: Thursday, January 11, 2007 2:29 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Long URB cancellation at Vista

I know. It looks as cancellation is postponed to some worker thread which is awakened once per 500 ms (upper bound is 516 ms). Or depends on something like this. Any idea how to find root cause of the problem?

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

> ----------
> From: xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com] on behalf of Peter Wieland[SMTP:xxxxx@windows.microsoft.com]
> Reply To: Windows System Software Devs Interest List
> Sent: Thursday, January 11, 2007 10:42 PM
> To: Windows System Software Devs Interest List
> Subject: RE: [ntdev] Long URB cancellation at Vista
>
> Oh if only request cancellation were a compute bound problem. Then all
> those CPU cycles would be useful.
>
> -p
>
> -----Original Message-----
> From: xxxxx@lists.osr.com
> [mailto:xxxxx@lists.osr.com] On Behalf Of Michal Vodicka
> Sent: Thursday, January 11, 2007 1:33 PM
> To: Windows System Software Devs Interest List
> Subject: RE: [ntdev] Long URB cancellation at Vista
>
> > ----------
> > From:
> xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com
> ] on behalf of Tim Roberts[SMTP:xxxxx@probo.com]
> > Reply To: Windows System Software Devs Interest List
> > Sent: Thursday, January 11, 2007 6:43 PM
> > To: Windows System Software Devs Interest List
> > Subject: Re: [ntdev] Long URB cancellation at Vista
> >
> > xxxxx@Microsoft.com wrote:
> > > IoCancelIrp has no timing guarantees and 400 ms is not that long.
> >
> > Not that long? A modern CPU will have executed almost a billion
> > instructions in that amount of time!
> >
> Exactly. In addition, these computers have nothing else to do during
> test and CPU utilization is near to zero.
>
> > I understand there are no timing guarantees, but that number seems
> about
> > three orders of magnitude too large to me.
> >
> For me, too. Normally I can measure 0 or 15 ms.
>
> Best regards,
>
> Michal Vodicka
> UPEK, Inc.
> [xxxxx@upek.com, http://www.upek.com]
>
> —
> Questions? First check the Kernel Driver FAQ at
> http://www.osronline.com/article.cfm?id=256
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
>
>
> —
> Questions? First check the Kernel Driver FAQ at http://www.osronline.com/article.cfm?id=256
>
> To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer
>

Questions? First check the Kernel Driver FAQ at http://www.osronline.com/article.cfm?id=256

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

Questions? First check the Kernel Driver FAQ at > http://www.osronline.com/article.cfm?id=256

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

14

It looks like very probable scenario. Is there any way how to identify problem can occur at given computer? Chipset version, HCs etc. The only thing I noticed so far is it occurs at OHCI HCs but not always. I haven’t seen a problem with UHCI but it doesn’t mean too much.

Our main concern is following. We indentified problem too late; software is already in the wild. Problem doesn’t make our device completely unusable because delay is random and when short enough, it works as expected. However, user experience is bad because it is necessary few attempts (we call it swipes) to get correct finger scan. If the problem occurs, we may not be even informed about it and users will have bad perception of our device.

The strange thing is XP don’t exhibit the problem at the same hardware, only Vista does. And there it is pretty consistent. Is it possible Vista drivers handles/programs controller different way?

Well, I’ll examine call stack to verify the theory :slight_smile:

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

From: xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com] on behalf of Randy Aull[SMTP:xxxxx@windows.microsoft.com]
Reply To: Windows System Software Devs Interest List
Sent: Thursday, January 11, 2007 11:53 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Long URB cancellation at Vista

I’m not sure about on Vista, but I have run into issues with some
chipsets on XP. In these cases, the controller didn’t notify the driver
that it was ok to remove the transfer from the schedule (no interrupt).
Periodically the driver would check the state of the hardware just in
case. During this check, the driver would notice that the transfer was
ready to remove, and the cancellation would proceed.

During Winusb development, I had a cancellation unit test case. Usually
this test case would complete in less than 10ms, but occasionally it
would spike to a very large time (like you see below).

There was some work to improve this worst case time, though I’m not sure
what happened with that work.

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Michal Vodicka
Sent: Thursday, January 11, 2007 2:29 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Long URB cancellation at Vista

I know. It looks as cancellation is postponed to some worker thread
which is awakened once per 500 ms (upper bound is 516 ms). Or depends on
something like this. Any idea how to find root cause of the problem?

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

> ----------
> From:
xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com
] on behalf of Peter Wieland[SMTP:xxxxx@windows.microsoft.com]
> Reply To: Windows System Software Devs Interest List
> Sent: Thursday, January 11, 2007 10:42 PM
> To: Windows System Software Devs Interest List
> Subject: RE: [ntdev] Long URB cancellation at Vista
>
> Oh if only request cancellation were a compute bound problem. Then
all
> those CPU cycles would be useful.
>
> -p
>
> -----Original Message-----
> From: xxxxx@lists.osr.com
> [mailto:xxxxx@lists.osr.com] On Behalf Of Michal Vodicka
> Sent: Thursday, January 11, 2007 1:33 PM
> To: Windows System Software Devs Interest List
> Subject: RE: [ntdev] Long URB cancellation at Vista
>
> > ----------
> > From:
>
xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com
> ] on behalf of Tim Roberts[SMTP:xxxxx@probo.com]
> > Reply To: Windows System Software Devs Interest List
> > Sent: Thursday, January 11, 2007 6:43 PM
> > To: Windows System Software Devs Interest List>
> > Subject: Re: [ntdev] Long URB cancellation at Vista
> >
> > xxxxx@Microsoft.com wrote:
> > > IoCancelIrp has no timing guarantees and 400 ms is not that long.
> >
> > Not that long? A modern CPU will have executed almost a billion
> > instructions in that amount of time!
> >
> Exactly. In addition, these computers have nothing else to do during
> test and CPU utilization is near to zero.
>
> > I understand there are no timing guarantees, but that number seems
> about
> > three orders of magnitude too large to me.
> >
> For me, too. Normally I can measure 0 or 15 ms.
>
> Best regards,
>
> Michal Vodicka
> UPEK, Inc.
> [xxxxx@upek.com, http://www.upek.com]
>
> —
> Questions? First check the Kernel Driver FAQ at
> http://www.osronline.com/article.cfm?id=256
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
>
>
> —
> Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256
>
> To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer
>

Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256

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

Questions? First check the Kernel Driver FAQ at http://www.osronline.com/article.cfm?id=256

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

15

It looks like this. Problem occurs only if interrupt endpoint value was really read previously i.e. URB submit followed by cancel doesn’t exhibit problem. Also, USB communication at control endpoint causes immediate completion routine call. So it seems OS USB drivers have to touch HC to complete cancellation. Surprisingly, checking port status isn’t enough.

It seems the problem is related to OHCI HCs. Previously I though I have a computer with OHCI which doesn’t exhibit problem but it was a mistake – it does. At the same computer an UHCI HC is installed and there is no problem. Looks as an OHCI drivers bug (again, XP don’t have a problem).

Call stack is always the same at both OHCI and UHCI:

fffff80002861950 fffff80001848829 : 0000000000000000 fffffa8001b8e570 fffffa800415f620 0000000070627375 : tcusb!IntEpPollingCompletion+0xb02 [d:\p4root\tcdrv\main\src\tcdrv\intep.c @ 217]
fffff80002861ab0 fffff980030e358f : fffffa8002f3b050 fffffa8002f3b002 fffffa80021fe4b0 fffffa8002208c30 : nt!IopfCompleteRequest+0x1a9
fffff80002861b20 fffff980030e3c48 : 0000000054546b63 fffffa8001b8e570 fffffa8002f3b1a0 fffffa80c0000120 : USBPORT!USBPORT_Core_iCompleteDoneTransfer+0x8d3
fffff80002861c00 fffff980030e10ea : fffffa8033585043 fffffa8002f3b1a0 fffffa8002f3c080 fffffa8002f3b1a0 : USBPORT!USBPORT_Core_iIrpCsqCompleteDoneTransfer+0x514
fffff80002861c70 fffff980030cdfeb : fffffa8031636f49 fffffa8002f3c080 fffffa8002f3c002 fffffa8002f3b1a0 : USBPORT!USBPORT_Core_UsbIocDpc_Worker+0x13a
fffff80002861cc0 fffff800018422b5 : 0000004e41345558 fffffa8034776478 fffffa8002f3c080 fffff80001942a80 : USBPORT!USBPORT_Xdpc_Worker+0x26f
fffff80002861d10 fffff8000184206f : fffff980030cdd7c fffff80001942a80 0000000000000001 fffff80001947d80 : nt!KiRetireDpcList+0x145
fffff80002861d80 fffff800019f7704 : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 : nt!KiIdleLoop+0x5f
fffff80002861db0 00000000fffff800 : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 : nt!KiSystemStartup+0x1d4

Any idea how to “kick” OHCI driver the least intrusive way? Ideally without even control endpoint communication.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

From: xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com] on behalf of Randy Aull[SMTP:xxxxx@windows.microsoft.com]
Reply To: Windows System Software Devs Interest List
Sent: Thursday, January 11, 2007 11:53 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Long URB cancellation at Vista

I’m not sure about on Vista, but I have run into issues with some
chipsets on XP. In these cases, the controller didn’t notify the driver
that it was ok to remove the transfer from the schedule (no interrupt).
Periodically the driver would check the state of the hardware just in
case. During this check, the driver would notice that the transfer was
ready to remove, and the cancellation would proceed.

During Winusb development, I had a cancellation unit test case. Usually
this test case would complete in less than 10ms, but occasionally it
would spike to a very large time (like you see below).

There was some work to improve this worst case time, though I’m not sure
what happened with that work.

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Michal Vodicka
Sent: Thursday, January 11, 2007 2:29 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Long URB cancellation at Vista

I know. It looks as cancellation is postponed to some worker thread
which is awakened once per 500 ms (upper bound is 516 ms). Or depends on
something like this. Any idea how to find root cause of the problem?>

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

> ----------
> From:
xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com
] on behalf of Peter Wieland[SMTP:xxxxx@windows.microsoft.com]
> Reply To: Windows System Software Devs Interest List
> Sent: Thursday, January 11, 2007 10:42 PM
> To: Windows System Software Devs Interest List
> Subject: RE: [ntdev] Long URB cancellation at Vista
>
> Oh if only request cancellation were a compute bound problem. Then
all
> those CPU cycles would be useful.
>
> -p
>
> -----Original Message-----
> From: xxxxx@lists.osr.com
> [mailto:xxxxx@lists.osr.com] On Behalf Of Michal Vodicka
> Sent: Thursday, January 11, 2007 1:33 PM
> To: Windows System Software Devs Interest List
> Subject: RE: [ntdev] Long URB cancellation at Vista
>
> > ----------
> > From:
>
xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com
> ] on behalf of Tim Roberts[SMTP:xxxxx@probo.com]
> > Reply To: Windows System Software Devs Interest List
> > Sent: Thursday, January 11, 2007 6:43 PM
> > To: Windows System Software Devs Interest List
> > Subject: Re: [ntdev] Long URB cancellation at Vista
> >
> > xxxxx@Microsoft.com wrote:
> > > IoCancelIrp has no timing guarantees and 400 ms is not that long.
> >
> > Not that long? A modern CPU will have executed almost a billion
> > instructions in that amount of time!
> >
> Exactly. In addition, these computers have nothing else to do during
> test and CPU utilization is near to zero.
>
> > I understand there are no timing guarantees, but that number seems
> about
> > three orders of magnitude too large to me.
> >
> For me, too. Normally I can measure 0 or 15 ms.
>
> Best regards,
>
> Michal Vodicka
> UPEK, Inc.
> [xxxxx@upek.com, http://www.upek.com]
>
> —
> Questions? First check the Kernel Driver FAQ at
> http://www.osronline.com/article.cfm?id=256
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
>
>
> —
> Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256
>
> To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer
>

Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256

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

Questions? First check the Kernel Driver FAQ at http://www.osronline.com/article.cfm?id=256

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

16

I’ve forwarded this onto our core usb team. I’ll see what I can dig up.

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Michal Vodicka
Sent: Thursday, January 11, 2007 11:26 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Long URB cancellation at Vista

It looks like this. Problem occurs only if interrupt endpoint value was
really read previously i.e. URB submit followed by cancel doesn’t
exhibit problem. Also, USB communication at control endpoint causes
immediate completion routine call. So it seems OS USB drivers have to
touch HC to complete cancellation. Surprisingly, checking port status
isn’t enough.

It seems the problem is related to OHCI HCs. Previously I though I have
a computer with OHCI which doesn’t exhibit problem but it was a mistake
– it does. At the same computer an UHCI HC is installed and there is no
problem. Looks as an OHCI drivers bug (again, XP don’t have a problem).

Call stack is always the same at both OHCI and UHCI:

fffff80002861950 fffff80001848829 : 0000000000000000 fffffa8001b8e570 fffffa800415f620 0000000070627375 :
tcusb!IntEpPollingCompletion+0xb02
[d:\p4root\tcdrv\main\src\tcdrv\intep.c @ 217]
fffff80002861ab0 fffff980030e358f : fffffa8002f3b050 fffffa8002f3b002 fffffa80021fe4b0 fffffa8002208c30 :
nt!IopfCompleteRequest+0x1a9
fffff80002861b20 fffff980030e3c48 : 0000000054546b63 fffffa8001b8e570 fffffa8002f3b1a0 fffffa80c0000120 :
USBPORT!USBPORT_Core_iCompleteDoneTransfer+0x8d3
fffff80002861c00 fffff980030e10ea : fffffa8033585043 fffffa8002f3b1a0 fffffa8002f3c080 fffffa8002f3b1a0 :
USBPORT!USBPORT_Core_iIrpCsqCompleteDoneTransfer+0x514
fffff80002861c70 fffff980030cdfeb : fffffa8031636f49 fffffa8002f3c080 fffffa8002f3c002 fffffa8002f3b1a0 :
USBPORT!USBPORT_Core_UsbIocDpc_Worker+0x13a
fffff80002861cc0 fffff800018422b5 : 0000004e41345558 fffffa8034776478 fffffa8002f3c080 fffff80001942a80 :
USBPORT!USBPORT_Xdpc_Worker+0x26f
fffff80002861d10 fffff8000184206f : fffff980030cdd7c fffff80001942a80 0000000000000001 fffff80001947d80 :
nt!KiRetireDpcList+0x145
fffff80002861d80 fffff800019f7704 : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 :
nt!KiIdleLoop+0x5f
fffff80002861db0 00000000fffff800 : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 :
nt!KiSystemStartup+0x1d4

Any idea how to “kick” OHCI driver the least intrusive way? Ideally
without even control endpoint communication.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

From:
xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com
] on behalf of Randy Aull[SMTP:xxxxx@windows.microsoft.com]
Reply To: Windows System Software Devs Interest List
Sent: Thursday, January 11, 2007 11:53 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Long URB cancellation at Vista

I’m not sure about on Vista, but I have run into issues with some
chipsets on XP. In these cases, the controller didn’t notify the
driver
that it was ok to remove the transfer from the schedule (no
interrupt).
Periodically the driver would check the state of the hardware just in
case. During this check, the driver would notice that the transfer
was
ready to remove, and the cancellation would proceed.

During Winusb development, I had a cancellation unit test case.
Usually
this test case would complete in less than 10ms, but occasionally it
would spike to a very large time (like you see below).

There was some work to improve this worst case time, though I’m not
sure
what happened with that work.

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Michal Vodicka
Sent: Thursday, January 11, 2007 2:29 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Long URB cancellation at Vista

I know. It looks as cancellation is postponed to some worker thread
which is awakened once per 500 ms (upper bound is 516 ms). Or depends
on
something like this. Any idea how to find root cause of the problem?>

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

> ----------
> From:

xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com

] on behalf of Peter Wieland[SMTP:xxxxx@windows.microsoft.com]
> Reply To: Windows System Software Devs Interest List
> Sent: Thursday, January 11, 2007 10:42 PM
> To: Windows System Software Devs Interest List
> Subject: RE: [ntdev] Long URB cancellation at Vista
>
> Oh if only request cancellation were a compute bound problem. Then
all
> those CPU cycles would be useful.
>
> -p
>
> -----Original Message-----
> From: xxxxx@lists.osr.com
> [mailto:xxxxx@lists.osr.com] On Behalf Of Michal
Vodicka
> Sent: Thursday, January 11, 2007 1:33 PM
> To: Windows System Software Devs Interest List
> Subject: RE: [ntdev] Long URB cancellation at Vista
>
> > ----------
> > From:
>

xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com

> ] on behalf of Tim Roberts[SMTP:xxxxx@probo.com]
> > Reply To: Windows System Software Devs Interest List
> > Sent: Thursday, January 11, 2007 6:43 PM
> > To: Windows System Software Devs Interest List
> > Subject: Re: [ntdev] Long URB cancellation at Vista
> >
> > xxxxx@Microsoft.com wrote:
> > > IoCancelIrp has no timing guarantees and 400 ms is not that
long.
> >
> > Not that long? A modern CPU will have executed almost a billion
> > instructions in that amount of time!
> >
> Exactly. In addition, these computers have nothing else to do during
> test and CPU utilization is near to zero.
>
> > I understand there are no timing guarantees, but that number seems
> about
> > three orders of magnitude too large to me.
> >
> For me, too. Normally I can measure 0 or 15 ms.
>
> Best regards,
>
> Michal Vodicka
> UPEK, Inc.
> [xxxxx@upek.com, http://www.upek.com]
>
> —
> Questions? First check the Kernel Driver FAQ at
> http://www.osronline.com/article.cfm?id=256
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
>
>
> —
> Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256
>
> To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer
>

Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256

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

Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256

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

Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256

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

17

Great, thanks.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

From: xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com] on behalf of Randy Aull[SMTP:xxxxx@windows.microsoft.com]
Reply To: Windows System Software Devs Interest List
Sent: Friday, January 12, 2007 7:04 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Long URB cancellation at Vista

I’ve forwarded this onto our core usb team. I’ll see what I can dig up.

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Michal Vodicka
Sent: Thursday, January 11, 2007 11:26 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Long URB cancellation at Vista

It looks like this. Problem occurs only if interrupt endpoint value was
really read previously i.e. URB submit followed by cancel doesn’t
exhibit problem. Also, USB communication at control endpoint causes
immediate completion routine call. So it seems OS USB drivers have to
touch HC to complete cancellation. Surprisingly, checking port status
isn’t enough.

It seems the problem is related to OHCI HCs. Previously I though I have
a computer with OHCI which doesn’t exhibit problem but it was a mistake
– it does. At the same computer an UHCI HC is installed and there is no
problem. Looks as an OHCI drivers bug (again, XP don’t have a problem).

Call stack is always the same at both OHCI and UHCI:

fffff80002861950 fffff80001848829 : 0000000000000000 fffffa8001b8e570 fffffa800415f620 0000000070627375 :
tcusb!IntEpPollingCompletion+0xb02
[d:\p4root\tcdrv\main\src\tcdrv\intep.c @ 217]
fffff80002861ab0 fffff980030e358f : fffffa8002f3b050 fffffa8002f3b002 fffffa80021fe4b0 fffffa8002208c30 :
nt!IopfCompleteRequest+0x1a9
fffff80002861b20 fffff980030e3c48 : 0000000054546b63 fffffa8001b8e570 fffffa8002f3b1a0 fffffa80c0000120 :
USBPORT!USBPORT_Core_iCompleteDoneTransfer+0x8d3
fffff80002861c00 fffff980030e10ea : fffffa8033585043 fffffa8002f3b1a0 fffffa8002f3c080 fffffa8002f3b1a0 :
USBPORT!USBPORT_Core_iIrpCsqCompleteDoneTransfer+0x514
fffff80002861c70 fffff980030cdfeb : fffffa8031636f49 fffffa8002f3c080 fffffa8002f3c002 fffffa8002f3b1a0 :
USBPORT!USBPORT_Core_UsbIocDpc_Worker+0x13a
fffff80002861cc0 fffff800018422b5 : 0000004e41345558 fffffa8034776478 fffffa8002f3c080 fffff80001942a80 :
USBPORT!USBPORT_Xdpc_Worker+0x26f
fffff80002861d10 fffff8000184206f : fffff980030cdd7c fffff80001942a80 0000000000000001 fffff80001947d80 :
nt!KiRetireDpcList+0x145
fffff80002861d80 fffff800019f7704 : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 :
nt!KiIdleLoop+0x5f
fffff80002861db0 00000000fffff800 : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 :
nt!KiSystemStartup+0x1d4

Any idea how to “kick” OHCI driver the least intrusive way? Ideally
without even control endpoint communication.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

> ----------
> From:
xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com
] on behalf of Randy Aull[SMTP:xxxxx@windows.microsoft.com]
> Reply To: Windows System Software Devs Interest List
> Sent: Thursday, January 11, 2007 11:53 PM
> To: Windows System Software Devs Interest List
> Subject: RE: [ntdev] Long URB cancellation at Vista
>
> I’m not sure about on Vista, but I have run into issues with some
> chipsets on XP. In these cases, the controller didn’t notify the
driver
> that it was ok to remove the transfer from the schedule (no
interrupt).
> Periodically the driver would check the state of the hardware just in
> case. During this check, the driver would notice that the transfer>
was
> ready to remove, and the cancellation would proceed.
>
> During Winusb development, I had a cancellation unit test case.
Usually
> this test case would complete in less than 10ms, but occasionally it
> would spike to a very large time (like you see below).
>
> There was some work to improve this worst case time, though I’m not
sure
> what happened with that work.
>
> -----Original Message-----
> From: xxxxx@lists.osr.com
> [mailto:xxxxx@lists.osr.com] On Behalf Of Michal Vodicka
> Sent: Thursday, January 11, 2007 2:29 PM
> To: Windows System Software Devs Interest List
> Subject: RE: [ntdev] Long URB cancellation at Vista
>
> I know. It looks as cancellation is postponed to some worker thread
> which is awakened once per 500 ms (upper bound is 516 ms). Or depends
on
> something like this. Any idea how to find root cause of the problem?>
>
> Best regards,
>
> Michal Vodicka
> UPEK, Inc.
> [xxxxx@upek.com, http://www.upek.com]
>
>
> > ----------
> > From:
>
xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com
> ] on behalf of Peter Wieland[SMTP:xxxxx@windows.microsoft.com]
> > Reply To: Windows System Software Devs Interest List
> > Sent: Thursday, January 11, 2007 10:42 PM
> > To: Windows System Software Devs Interest List
> > Subject: RE: [ntdev] Long URB cancellation at Vista
> >
> > Oh if only request cancellation were a compute bound problem. Then
> all
> > those CPU cycles would be useful.
> >
> > -p
> >
> > -----Original Message-----
> > From: xxxxx@lists.osr.com
> > [mailto:xxxxx@lists.osr.com] On Behalf Of Michal
Vodicka
> > Sent: Thursday, January 11, 2007 1:33 PM
> > To: Windows System Software Devs Interest List
> > Subject: RE: [ntdev] Long URB cancellation at Vista
> >
> > > ----------
> > > From:
> >
>
xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com
> > ] on behalf of Tim Roberts[SMTP:xxxxx@probo.com]
> > > Reply To: Windows System Software Devs Interest List
> > > Sent: Thursday, January 11, 2007 6:43 PM
> > > To: Windows System Software Devs Interest List
> > > Subject: Re: [ntdev] Long URB cancellation at Vista
> > >
> > > xxxxx@Microsoft.com wrote:
> > > > IoCancelIrp has no timing guarantees and 400 ms is not that
long.
> > >
> > > Not that long? A modern CPU will have executed almost a billion
> > > instructions in that amount of time!
> > >
> > Exactly. In addition, these computers have nothing else to do during
> > test and CPU utilization is near to zero.
> >
> > > I understand there are no timing guarantees, but that number seems
> > about
> > > three orders of magnitude too large to me.
> > >
> > For me, too. Normally I can measure 0 or 15 ms.
> >
> > Best regards,
> >
> > Michal Vodicka
> > UPEK, Inc.
> > [xxxxx@upek.com, http://www.upek.com]
> >
> > —
> > Questions? First check the Kernel Driver FAQ at
> > http://www.osronline.com/article.cfm?id=256
> >
> > To unsubscribe, visit the List Server section of OSR Online at
> > http://www.osronline.com/page.cfm?name=ListServer
> >
> >
> > —
> > Questions? First check the Kernel Driver FAQ at
> http://www.osronline.com/article.cfm?id=256
> >
> > To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
> >
>
> —
> Questions? First check the Kernel Driver FAQ at
> http://www.osronline.com/article.cfm?id=256
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
>
> —
> Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256
>
> To unsubscribe, visit the List Server section of OSR Online at>
http://www.osronline.com/page.cfm?name=ListServer
>

Questions? First check the Kernel Driver FAQ at
http://www.osronline.com/article.cfm?id=256

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

Questions? First check the Kernel Driver FAQ at http://www.osronline.com/article.cfm?id=256

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