What Did Storport Do With My I/O?

  • Article

In a previous article I showed how to track an I/O request from the filesystem, through the class driver, and to the storage driver.  In that article I concluded with "From this data we can usually assume that the request has been sent to the disk drive and we are waiting for the disk to respond" and "There may be conditions where the request is stuck in storport, or in the miniport". In this article I want to show what happens to the I/O request when gets to storport.sys.

 

You will find that the structures needed to investigate a request inside of storport can be dumped with the dt command using publicly available storport.sys symbols. However, until now those structures have not been useful to most debuggers because we have not described how an IRP goes through storport, or how to find an IRP once it has been sent to storport.

 

In the previous article I showed how to find the IRP that was sent to the storport miniport driver.  Below is the example IRP we will be using today.

 

48: kd> !irp fffffa81`4135a010

Irp is active with 5 stacks 3 is current (= 0xfffffa814135a170)

Mdl=fffffa8232ad1100: No System Buffer: Thread 00000000:  Irpstack trace.

     cmd  flg cl Device   File     Completion-Context

[  0, 0]   0  0 00000000 00000000 00000000-00000000

 

                        Args: 00000000 00000000 00000000 00000000

[  0, 0]   0  0 00000000 00000000 00000000-00000000

 

                        Args: 00000000 00000000 00000000 00000000

>[  f, 0]   0 e1 fffffa813ba0c060 00000000 fffff880011651a0-fffffa8141609cb0 Success Error Cancel pending

               \Driver\stormini mpio!MPIOPdoCompletion

                        Args: fffffa8231a15c10 00000000 00000000 fffffa813ba0c1b0

[  f, 0]   0 e1 fffffa80c329f400 00000000 fffff88001487f8c-fffffa81414bc9c0 Success Error Cancel pending

               \Driver\mpio     EmcpBase!PowerPlatformIoEnqueue

                        Args: fffffa8231a15c10 00000000 00000000 fffffa8141609cb0

[  f, 0]   0 e1 fffffa80c34ab550 00000000 fffff88001dbaa00-fffffa8231a15af0 Success Error Cancel pending

               \Driver\EmcpBase CLASSPNP!TransferPktComplete

                        Args: fffffa8231a15c10 00000000 00000000 00000000

 

Although the device object in the IRP is named \Driver\stormini, the dispatch routines for the driver all point to storport.  Storport is the port driver that handles queuing the request, stormini is the miniport.

 

48: kd> !drvobj \Driver\stormini 2

Driver object (fffffa80c19d5bf0) is for:

\Driver\stormini

DriverEntry:   fffff88001729008 stormini!StateHandler

DriverStartIo: 00000000

DriverUnload:  fffff8800168f28c stormini

AddDevice:     fffff88001416dc0 storport!DriverAddDevice

 

Dispatch routines:

[00] IRP_MJ_CREATE                      fffff880014582a0        storport!RaDriverCreateIrp

[01] IRP_MJ_CREATE_NAMED_PIPE           fffff80001a721d4        nt!IopInvalidDeviceRequest

[02] IRP_MJ_CLOSE                       fffff880014581c0        storport!RaDriverCloseIrp

[03] IRP_MJ_READ                        fffff80001a721d4        nt!IopInvalidDeviceRequest

[04] IRP_MJ_WRITE                       fffff80001a721d4        nt!IopInvalidDeviceRequest

[05] IRP_MJ_QUERY_INFORMATION           fffff80001a721d4        nt!IopInvalidDeviceRequest

[06] IRP_MJ_SET_INFORMATION             fffff80001a721d4        nt!IopInvalidDeviceRequest

[07] IRP_MJ_QUERY_EA                    fffff80001a721d4        nt!IopInvalidDeviceRequest

[08] IRP_MJ_SET_EA                      fffff80001a721d4        nt!IopInvalidDeviceRequest

[09] IRP_MJ_FLUSH_BUFFERS               fffff80001a721d4        nt!IopInvalidDeviceRequest

[0a] IRP_MJ_QUERY_VOLUME_INFORMATION    fffff80001a721d4        nt!IopInvalidDeviceRequest

[0b] IRP_MJ_SET_VOLUME_INFORMATION      fffff80001a721d4        nt!IopInvalidDeviceRequest

[0c] IRP_MJ_DIRECTORY_CONTROL           fffff80001a721d4        nt!IopInvalidDeviceRequest

[0d] IRP_MJ_FILE_SYSTEM_CONTROL         fffff80001a721d4        nt!IopInvalidDeviceRequest

[0e] IRP_MJ_DEVICE_CONTROL              fffff88001453010        storport!RaDriverDeviceControlIrp

[0f] IRP_MJ_INTERNAL_DEVICE_CONTROL     fffff880014016c0        storport!RaDriverScsiIrp

[10] IRP_MJ_SHUTDOWN                    fffff80001a721d4        nt!IopInvalidDeviceRequest

[11] IRP_MJ_LOCK_CONTROL                fffff80001a721d4        nt!IopInvalidDeviceRequest

[12] IRP_MJ_CLEANUP                     fffff80001a721d4        nt!IopInvalidDeviceRequest

[13] IRP_MJ_CREATE_MAILSLOT             fffff80001a721d4        nt!IopInvalidDeviceRequest

[14] IRP_MJ_QUERY_SECURITY              fffff80001a721d4        nt!IopInvalidDeviceRequest

[15] IRP_MJ_SET_SECURITY                fffff80001a721d4        nt!IopInvalidDeviceRequest

[16] IRP_MJ_POWER                       fffff8800141a9d0        storport!RaDriverPowerIrp

[17] IRP_MJ_SYSTEM_CONTROL              fffff88001458f40        storport!RaDriverSystemControlIrp

[18] IRP_MJ_DEVICE_CHANGE               fffff80001a721d4        nt!IopInvalidDeviceRequest

[19] IRP_MJ_QUERY_QUOTA                 fffff80001a721d4        nt!IopInvalidDeviceRequest

[1a] IRP_MJ_SET_QUOTA                   fffff80001a721d4        nt!IopInvalidDeviceRequest

[1b] IRP_MJ_PNP                         fffff88001459b00        storport!RaDriverPnpIrp

 

To find what storport has done with the IRP we must look at the unit.  The device extension contains the information regarding the state of the unit.

 

48: kd> !devobj fffffa813ba0c060

Device object (fffffa813ba0c060) is for:

000000aa \Driver\stormini DriverObject fffffa80c19d5bf0

Current Irp 00000000 RefCount 0 Type 00000007 Flags 00001050

Dacl fffff9a10049abb0 DevExt fffffa813ba0c1b0 DevObjExt fffffa813ba0c630 DevNode fffffa80c19dad90

ExtensionFlags (0x00000800)

                             Unknown flags 0x00000800

AttachedDevice (Upper) fffffa80c31ef9d0 \Driver\Disk

Device queue is not busy.

48: kd> dt storport!_RAID_UNIT_EXTENSION fffffa813ba0c1b0

   +0x000 ObjectType       : 1 ( RaidUnitObject )

   +0x008 DeviceObject     : 0xfffffa81`3ba0c060 _DEVICE_OBJECT

   +0x010 Adapter          : 0xfffffa80`c25a61b0 _RAID_ADAPTER_EXTENSION

   +0x018 SlowLock         : 0

   +0x020 DeviceState      : 1 ( DeviceStateWorking )

   +0x028 NextUnit         : _LIST_ENTRY [ 0xfffffa80`c25941d8 - 0xfffffa80`c25a6228 ]

   +0x038 UnitTableLink    : _LIST_ENTRY [ 0xfffffa80`c25a3320 - 0xfffffa80`c25e7b48 ]

   +0x048 Address          : _STOR_SCSI_ADDRESS

   +0x050 Identity         : _STOR_SCSI_IDENTITY

   +0x070 AlignmentInfo    : _STOR_ALIGNMENT_INFO

   +0x080 Flags            : <unnamed-tag>

   +0x088 ZeroOutstandingEvent : _KEVENT

   +0x0a0 OutstandingCount : 0n30

   +0x0a4 PagingPathCount  : 0

   +0x0a8 CrashDumpPathCount : 0

   +0x0ac HiberPathCount   : 0

   +0x0b0 TagList          : _QUEUE_TAG_LIST

   +0x0d0 IoQueue          : _IO_QUEUE

   +0x140 MaxQueueDepth    : 0xff

   +0x144 Power            : _RAID_POWER_STATE

   +0x150 PendingQueue     : _STOR_EVENT_QUEUE

   +0x170 PendingTimer     : _KTIMER

   +0x1b0 PendingDpc       : _KDPC

   +0x1f0 PauseTimer       : _KTIMER

   +0x230 PauseTimerDpc    : _KDPC

   +0x270 RestartDpc       : _KDPC

   +0x2b0 CommonBufferVAs  : (null)

   +0x2b8 CommonBufferSize : 0

   +0x2bc CommonBufferBlocks : 0

   +0x2c0 UnitExtension    : 0xfffffa80`c185dda0 Void

   +0x2c8 DefaultTimeout   : 0xa

   +0x2d0 DeferredList     : <unnamed-tag>

   +0x410 ResetCount       : 0n1

   +0x418 ResetResources   : _RAID_IO_RESOURCES

   +0x438 ResetResourcesAcquired : 0n1

   +0x43c SenseInfoSize    : 0x14 ''

   +0x440 IdleCounter      : (null)

   +0x448 PowerUpRequired  : 0n0

   +0x450 HierarchicalResetWorkItem : (null)

   +0x458 HierarchicalResetWorkItemTimeoutCountdown : 0n0

   +0x45c HierarchicalResetAbortCount : 1

   +0x460 HierarchicalResetWorkItemSpinLock : 0

   +0x468 RegistryParameters : _RAID_UNIT_REGISTRY_PARAMETERS

 

Two parts of the device extension are relevant to finding the I/O request, the PendingQueue and the IoQueue.  Under most conditions, when a request is sent to storport it will be sent to the miniport driver and put on the PendingQueue.  The PendingQueue has a list of outstanding requests and a timer that is decremented every second.  The timer is refreshed when the request on the head of the queue is completed.  A request is completed when the miniport calls StorPortNotification with RequestComplete.  If the timer is decremented to 0, the request has timed out and storport will do a hierarchical reset to attempt to correct the problem.

 

In the below PendingQueue we can see that there is one entry in the queue, and the Timeout is set to -2.  Under most conditions the Timeout will be a value between 0 and 0x3c (0n60), indicating the number of seconds left in the timer.  A Timeout value of -2 indicates that there was a timeout and it is being handled.  A Timeout value of -1 indicates that the queue is empty.

 

48: kd> dt storport!_RAID_UNIT_EXTENSION fffffa813ba0c1b0 PendingQueue.

   +0x150 PendingQueue  :

      +0x000 List          : _LIST_ENTRY [ 0xfffff880`05906040 - 0xfffff880`05906040]

      +0x010 Lock          : 0

      +0x018 Timeout       : 0xfffffffe

 

Items in the queue will be in the form of an XRB, or Extended Request Block.  There is one request in the pending queue (we know there is one request because the Flink and Blink point to the same address).  The Irp for this XRB is not our IRP, so we need to go look somewhere else for our request.

 

48: kd> dt storport!_EXTENDED_REQUEST_BLOCK 0xfffff880`05906040-30

   +0x000 Signature        : 0x1f2e3d4c

   +0x008 Pool             : (null)

   +0x010 OwnedMdl         : 0y0

   +0x010 RemoveFromEventQueue : 0y1

   +0x010 State            : 0y011

   +0x010 RemappedSenseInfo : 0y1

   +0x012 InitiatingProcessor : _PROCESSOR_NUMBER

   +0x018 InitiatingToken  : (null)

   +0x020 CompletedLink    : _SLIST_ENTRY

   +0x030 PendingLink      : _STOR_EVENT_QUEUE_ENTRY

   +0x048 Mdl              : (null)

   +0x050 SgList           : (null)

   +0x058 RemappedSgListMdl : (null)

   +0x060 RemappedSgList   : (null)

   +0x068 Irp              : 0xfffffa82`35142ee0 _IRP

   +0x070 Srb              : 0xfffffa81`41cf54a0 _SCSI_REQUEST_BLOCK

   +0x078 SrbData          : <unnamed-tag>

   +0x098 Adapter          : 0xfffffa80`c25a61b0 _RAID_ADAPTER_EXTENSION

   +0x0a0 Unit             : 0xfffffa81`3ba0c1b0 _RAID_UNIT_EXTENSION

   +0x0a8 ScatterGatherBuffer : [424]  ""

   +0x250 CompletionRoutine : 0xfffff880`014199d0     void  storport!RaidUnitCompleteResetRequest+0

   +0x258 u                : <unnamed-tag>

   +0x270 RequestStartTimeStamp : 0

 

If the unit is in a state where the request cannot be sent to the miniport, the requests will be queued on the DeviceQueue in the IoQueue. Storport may not be able to send the request to the miniport because the queue is full, the queue is paused, or because an untagged request is outstanding and tagged requests cannot be sent until the untagged request is completed.

 

In the below DeviceQueue we can see that the unit is paused (the PauseCount is 1).  This would explain why our request is not in the PendingQueue.  It should be in the DeviceQueue.

 

48: kd> dt storport!_RAID_UNIT_EXTENSION fffffa813ba0c1b0 IoQueue.DeviceQueue.

   +0x0d0 IoQueue              :

      +0x010 DeviceQueue          :

         +0x000 Type                 : 0n258

         +0x002 Size                 : 0n88

         +0x008 Gateway              : 0xfffffa80`c25a6470_STOR_IO_GATEWAY

         +0x010 DeviceList           : _LIST_ENTRY [ 0xfffffa81`4232d3a8 - 0xfffffa81`4172c768 ]

         +0x020 ByPassList           : _LIST_ENTRY [ 0xfffffa81`3ba0c2b0 - 0xfffffa81`3ba0c2b0 ]

         +0x030 Lock                 : 0

         +0x038 Depth                : 0n32

         +0x03c OutstandingCount     : 0n0

         +0x040 DeviceCount          : 0n27

         +0x044 ByPassCount          : 0n0

         +0x048 ByPassPowerCount     : 0n0

         +0x04c PauseCount           : 0n1

         +0x050 BusyCount            : 0n0

         +0x054 Frozen               : 0 ''

         +0x055 Locked               : 0 ''

         +0x056 Untagged             : 0 ''

         +0x057 PowerLocked          : 0 ''

 

Requests from the DeviceQueue are in the DeviceList.  We can dump the DeviceList with !list and look for our IRP.

 

48: kd> !list "-t nt!_IRP.Tail.Overlay.DeviceQueueEntry.DeviceListEntry.Flink -x\"??@$extret\" 0xfffffa814232d3a8-78"

unsigned int64 0xfffffa81`4232d330

 

unsigned int64 0xfffffa81`bea59630

 

unsigned int64 0xfffffa81`41dad420

 

unsigned int64 0xfffffa82`32e90770

 

unsigned int64 0xfffffa81`4135a010

<snip the end of the list>

 

Now that we have found our request in the DeviceQueue's DeviceList we may want to look into why the request has not been sent to the disk and put on the PendingQueue.  Earlier I mentioned that the Timeout value in the PendingQueue is -2, indicating that a request in the PendingQueue has timed out.  If we take another look at the XRB from the PendingQueue, we see that the CompletionRoutine is RaidUnitCompleteResetRequest.  This indicates that a LUN reset request was sent to the disk, and it timed out. When a LUN reset times out storport calls the miniport’s bus reset function. When the bus reset function is called the miniport is required to complete all requests issued to it.  In this instance the reset was issued, but for some reason the reset has not yet completed and so all of the outstanding requests are stuck.  For more information on storport timeouts, see our article on Event 129 Errors.