Out of Order IRP Submission/Completion under Vista

NTDEV
1

Hi,

I’ve recently started testing a driver under Windows Vista. The driver was originally written a while back with Windows 2000 and XP in mind, and has been used on extensively without any problems. Initially my testing suggested that it would also work under Vista. However, after closer examination I discovered a problem…

The driver reads from a USB device by submitting 8 URBs. These URBs are in the form of IRPs created using IoAllocateIrp. Normally when a URB completes, the data it contains is passed to the user, the IRP is reused using IoReuseIrp, and it is resubmitted. However, I also pass a structure to the completion routine which contains the index of the URB. The URB is only processed if it is the next one to complete. If not, it is added to a list and processed when all previous URBs have been received and processed.

This all works well under XP and 2000, and deals with any out of order completion which may occur on multi-processor/core machines. However, under Vista things don’t quite go to plan. Occasionally a URB will complete out of order and the driver will re-order it. The problem is that the data contained within the out of order URB is actually in order.

I’ll try and show this with an example. This is how things should work, and how it works under XP/2000:
URB 0 submitted
URB 1 submitted
URB 2 submitted
URB 3 submitted
URB 4 submitted
URB 5 submitted
URB 6 submitted
URB 7 submitted
URB 0 completes - data 0 passed to user
URB 0 re-submitted
URB 1 completes - data 1 passed to user
URB 1 re-submitted
URB 2 completes - data 2 passed to user
URB 2 re-submitted
URB 3 completes - data 3 passed to user
URB 3 re-submitted
URB 4 completes - data 4 passed to user
URB 4 re-submitted
URB 5 completes - data 5 passed to user
URB 5 re-submitted
URB 6 completes - data 6 passed to user
URB 6 re-submitted
URB 7 completes - data 7 passed to user
URB 7 re-submitted
URB 0 completes - data 8 passed to user
URB 0 re-submitted
URB 4 completes - data 12 not passed to user
URB 1 completes - data 9 passed to user
URB 1 re-submitted
URB 2 completes - data 10 passed to user
URB 2 re-submitted
URB 3 completes - data 11 passed to user
URB 3 re-submitted
Data 12 passed to user
URB 4 re-submitted
URB 5 completes - data 13 passed to user
URB 5 re-submitted
URB 6 completes - data 14 passed to user
URB 6 re-submitted
URB 7 completes - data 15 passed to user
URB 7 re-submitted

And this is what occasionally happens under Vista:
URB 0 submitted
URB 1 submitted
URB 2 submitted
URB 3 submitted
URB 4 submitted
URB 5 submitted
URB 6 submitted
URB 7 submitted
URB 0 completes - data 0 passed to user
URB 0 re-submitted
URB 1 completes - data 1 passed to user
URB 1 re-submitted
URB 2 completes - data 2 passed to user
URB 2 re-submitted
URB 3 completes - data 3 passed to user
URB 3 re-submitted
URB 4 completes - data 4 passed to user
URB 4 re-submitted
URB 5 completes - data 5 passed to user
URB 5 re-submitted
URB 6 completes - data 6 passed to user
URB 6 re-submitted
URB 7 completes - data 7 passed to user
URB 7 re-submitted
URB 0 completes - data 8 passed to user
URB 0 re-submitted
URB 4 completes - data 9 not passed to user
URB 1 completes - data 10 passed to user
URB 1 re-submitted
URB 2 completes - data 11 passed to user
URB 2 re-submitted
URB 3 completes - data 12 passed to user
URB 3 re-submitted
Data 9 passed to user
URB 4 re-submitted
URB 5 completes - data 13 passed to user
URB 5 re-submitted
URB 6 completes - data 14 passed to user
URB 6 re-submitted
URB 7 completes - data 15 passed to user
URB 7 re-submitted

So what’s happening is the data past to the user is out of sequence. Hope that all makes sense (and there’s no limit to the maximum post size)! I’ve checked with a CATC USB Analyser, and the USB traffic is definitely in the correct order. Running Verifier reports no bad things happening, and I’ve gone over my code without finding any problems.

So, to my questions. Is there some change in Vista that I don’t know about that’s causing this out of order completion? Or can anyone suggest something else that might be wrong to cause this? I’ve spent a great deal of time looking into this and have ran out of ideas.

Thanks in advance, and sorry for the long post.

2

How exactly does “the data it contains is passed to the user” happen?
Also what mechanisms are you using to control your ordering of
operations? Finally, is your user mode application single threaded?

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of
xxxxx@computing.dundee.ac.uk
Sent: Wednesday, September 12, 2007 6:04 AM
To: Windows System Software Devs Interest List
Subject: [ntdev] Out of Order IRP Submission/Completion under Vista

Hi,

I’ve recently started testing a driver under Windows Vista. The driver
was originally written a while back with Windows 2000 and XP in mind,
and has been used on extensively without any problems. Initially my
testing suggested that it would also work under Vista. However, after
closer examination I discovered a problem…

The driver reads from a USB device by submitting 8 URBs. These URBs are
in the form of IRPs created using IoAllocateIrp. Normally when a URB
completes, the data it contains is passed to the user, the IRP is reused
using IoReuseIrp, and it is resubmitted. However, I also pass a
structure to the completion routine which contains the index of the URB.
The URB is only processed if it is the next one to complete. If not, it
is added to a list and processed when all previous URBs have been
received and processed.

This all works well under XP and 2000, and deals with any out of order
completion which may occur on multi-processor/core machines. However,
under Vista things don’t quite go to plan. Occasionally a URB will
complete out of order and the driver will re-order it. The problem is
that the data contained within the out of order URB is actually in
order.

I’ll try and show this with an example. This is how things should work,
and how it works under XP/2000:
URB 0 submitted
URB 1 submitted
URB 2 submitted
URB 3 submitted
URB 4 submitted
URB 5 submitted
URB 6 submitted
URB 7 submitted
URB 0 completes - data 0 passed to user
URB 0 re-submitted
URB 1 completes - data 1 passed to user
URB 1 re-submitted
URB 2 completes - data 2 passed to user
URB 2 re-submitted
URB 3 completes - data 3 passed to user
URB 3 re-submitted
URB 4 completes - data 4 passed to user
URB 4 re-submitted
URB 5 completes - data 5 passed to user
URB 5 re-submitted
URB 6 completes - data 6 passed to user
URB 6 re-submitted
URB 7 completes - data 7 passed to user
URB 7 re-submitted
URB 0 completes - data 8 passed to user
URB 0 re-submitted
URB 4 completes - data 12 not passed to user
URB 1 completes - data 9 passed to user
URB 1 re-submitted
URB 2 completes - data 10 passed to user
URB 2 re-submitted
URB 3 completes - data 11 passed to user
URB 3 re-submitted
Data 12 passed to user
URB 4 re-submitted
URB 5 completes - data 13 passed to user
URB 5 re-submitted
URB 6 completes - data 14 passed to user
URB 6 re-submitted
URB 7 completes - data 15 passed to user
URB 7 re-submitted

And this is what occasionally happens under Vista:
URB 0 submitted
URB 1 submitted
URB 2 submitted
URB 3 submitted
URB 4 submitted
URB 5 submitted
URB 6 submitted
URB 7 submitted
URB 0 completes - data 0 passed to user
URB 0 re-submitted
URB 1 completes - data 1 passed to user
URB 1 re-submitted
URB 2 completes - data 2 passed to user
URB 2 re-submitted
URB 3 completes - data 3 passed to user
URB 3 re-submitted
URB 4 completes - data 4 passed to user
URB 4 re-submitted
URB 5 completes - data 5 passed to user
URB 5 re-submitted
URB 6 completes - data 6 passed to user
URB 6 re-submitted
URB 7 completes - data 7 passed to user
URB 7 re-submitted
URB 0 completes - data 8 passed to user
URB 0 re-submitted
URB 4 completes - data 9 not passed to user
URB 1 completes - data 10 passed to user
URB 1 re-submitted
URB 2 completes - data 11 passed to user
URB 2 re-submitted
URB 3 completes - data 12 passed to user
URB 3 re-submitted
Data 9 passed to user
URB 4 re-submitted
URB 5 completes - data 13 passed to user
URB 5 re-submitted
URB 6 completes - data 14 passed to user
URB 6 re-submitted
URB 7 completes - data 15 passed to user
URB 7 re-submitted

So what’s happening is the data past to the user is out of sequence.
Hope that all makes sense (and there’s no limit to the maximum post
size)! I’ve checked with a CATC USB Analyser, and the USB traffic is
definitely in the correct order. Running Verifier reports no bad things
happening, and I’ve gone over my code without finding any problems.

So, to my questions. Is there some change in Vista that I don’t know
about that’s causing this out of order completion? Or can anyone
suggest something else that might be wrong to cause this? I’ve spent a
great deal of time looking into this and have ran out of ideas.

Thanks in advance, and sorry for the long post.

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

3

The data is passed to the user using a shared buffer. My user-mode application is multi-threaded. However, I know things are going wrong long before the data is passed to the user. I’ve inserted debug statements in the driver to confirm that the data is out of order when the IRP completes.

Here’s the code from my completion routine:

NTSTATUS RECEIVE_URBCompleted(IN PDEVICE_OBJECT unused,
IN PIRP Irp, IN PMY_CONTEXT context)
{
PDEVICE_OBJECT fdo = context->fdo;
PDEVICE_EXTENSION pdx = (PDEVICE_EXTENSION)fdo->DeviceExtension;
KIRQL oldirql;

if (context->lock == TRUE)
{
KeAcquireSpinLock(&pdx->ReadLock, &oldirql);
context->oldirql = oldirql;
}
else
{
context->lock = TRUE;
oldirql = context->oldirql;
}

/* If this URB != next URB to process */
if (context->urbnum != pdx->NextReadURBExpected)
{
/* Add the URB to those not yet processed */
pdx->CompletedReadURBS[context->urbnum].Irp = Irp;
pdx->CompletedReadURBS[context->urbnum].context = context;

KeReleaseSpinLock(&pdx->ReadLock, oldirql);

return STATUS_MORE_PROCESSING_REQUIRED;
}

/* Process the URB */
RECEIVE_ProcessURB(fdo, Irp, context, &oldirql);

/* Increment next URB to process */
pdx->NextReadURBExpected++;

/* If next URB to process == number of URBs */
if (pdx->NextReadURBExpected == SPACEWIRE_USB_MAX_READ_URBS)
{
/* Next URB to process = 0 */
pdx->NextReadURBExpected = 0;
}

/* If the next expected URB has already completed */
if (pdx->CompletedReadURBS[pdx->NextReadURBExpected].Irp != NULL)
{
/* Complete the URB */
Irp = pdx->CompletedReadURBS[pdx->NextReadURBExpected].Irp;
pdx->CompletedReadURBS[pdx->NextReadURBExpected].Irp = NULL;
pdx->CompletedReadURBS[pdx->NextReadURBExpected].context->lock = FALSE;
pdx->CompletedReadURBS[pdx->NextReadURBExpected].context->oldirql = oldirql;

RECEIVE_URBCompleted(NULL, Irp,
pdx->CompletedReadURBS[pdx->NextReadURBExpected].context);
}
else
{
KeReleaseSpinLock(&pdx->ReadLock, oldirql);
}

return STATUS_MORE_PROCESSING_REQUIRED;
}

I added debug statements in there to check for out of order packets and to check for out of order data, which is why I know that it’s not a problem further up the stack.