If a request times out, StorPort will try to reset the unit and make it
abort all in progress I/O requests. If the reset doesn’t complete then
that’s bad business, usually this means that the hardware has ceased
responding (especially if you’re seeing this with two different drivers for
the same device).
Random guess, but do you have the disk configured to power down when idle
(!popolicy will tell you, but that requires symbols)? I’d try shutting that
off and see if that helps at all.
-scott
OSR
@OSRDrivers
wrote in message news:xxxxx@ntdev…
With my debug USB cable in hand, I was *finally* able to get some real data
out of this. Sorry for wasting everyone’s time with the pathetic attempts at
local debugging earlier in this thread.
Unfortunately, I don’t have the symbols for this (no symbols for 15055 as
of yet, I’ve contacted WinDbgFb and we’ll see if we hear back. I may have to
debug this on a clean install of a different build that triggers the issue
yet has the debug symbols available… *sigh*).
Anyway, this is what I get:
0: kd> !wmitrace.logdump EventLog-System
| |
| NT symbols are not available |
| reduced functionality |
|
(WmiTrace) LogDump for Logger Id 0x0c |
Found Buffers: 2 Messages: 2, sorting entries |
[0]0000.0000:: 131339913007908456 [Microsoft-Windows-StorPort/Bus reset |
/OpCodeBusReset]Bus reset occured on storport adapter (Port Number: 1) |
[0]0000.0000:: 131339913307864363 [Microsoft-Windows-StorPort/None /Info]A |
request timed out for Storport Device (Port = 1, Path = 0, Target = 0, Lun = |
0). |
Corresponding Class Disk Device Guid is |
{0d61954a-3e28-2ff4-3116-b0b7bdd7c44b}. |
Total of 2 Messages from 2 Buffers |
0: kd> !storclass
0: kd> !storadapter
STORPORT adapters:
==================
Driver Object Extension State
-----------------------------------------------------------------
\Driver\secnvme ffffc883f4bc2050 ffffc883f4bc21a0 Working
\Driver\storahci ffffc883f4bb5050 ffffc883f4bb51a0 Working
0: kd> !storadapter ffffc883f4bc2050
ADAPTER
DeviceObj : ffffc883f4bc2050 AdapterExt: ffffc883f4bc21a0 DriverObj :
ffffc883f4ba58d0
DeviceState : Working
LowerDO ffffc883f4b59620 PhysicalDO ffffc883f4b59840
SlowLock Free RemLock -666
SystemPowerState: Working AdapterPowerState D0 Full Duplex
Bus 4 Slot 0 DMA ffffc883f4bd0dd0 Interrupt 0000000000000000
Allocated ResourceList ffffc883f4bc6960
Translated ResourceList ffffc883f4ba78f0
Gateway: Outstanding 0 Lower 1024 High 1024
PortConfigInfo ffffc883f4bc22d0
HwInit ffffc883f4ba83b0 HwDeviceExt ffffc883f2c6b010 (10024 bytes)
SrbExt 4560 bytes LUExt 0 bytes
Normal Logical Units:
Product SCSI ID Object Extension Pnd
Out Ct State
----------------------------------------------------------------------------------------
NVMe Samsung SS 0 0 0 ffffc883f4b9e060 ffffc883f4b9e1b0 35
0 0 Working
Zombie Logical Units:
Product SCSI ID Object Extension Pnd
Out Ct State
--------------------------------------------------------------------------------------
0: kd> !storunit ffffc883f4b9e060
DO ffffc883f4b9e060 Ext ffffc883f4b9e1b0 Adapter ffffc883f4bc21a0
Working
Vendor: NVMe Product: Samsung SSD 950 SCSI ID: (0, 0, 0)
Claimed Enumerated
SlowLock Free RemLock 38 PageCount 2
QueueTagList: ffffc883f4b9e2b0 Outstanding: Head 0000000000000000
Tail 0000000000000000 Timeout 0 (Ticking Down)
DeviceQueue ffffc883f4b9e340 Depth: 254 Status: Not Frozen
PauseCount: 1 BusyCount: 0
IO Gateway: Busy Count 0 Pause Count 0
Requests: Outstanding 0 Device 35 ByPass 0
[Device-Queued Requests]
IRP SRB Type SRB XRB Command
MDL SGList Timeout
-----------------------------------------------------------------------------------------------------------------------------------
ffffc88400fd6bb0 [STORAGE] ffffc88400fd6db0 n/a SCSI/WRITE (10)
ffffda80a7131ea0 n/a 65s
ffffc883ff39a010 [STORAGE] ffffc88401285a10 n/a SCSI/WRITE (10)
ffffda80a0b27750 n/a 65s
ffffc8840106a4f0 [STORAGE] ffffc8840106a6f0 n/a SCSI/READ (10)
ffffc883f46b83a0 n/a 65s
ffffc88400fdaa20 [STORAGE] ffffc883fecde200 n/a SCSI/WRITE (10)
ffffc883f492a200 n/a 65s
ffffc884013dfd40 [STORAGE] ffffc884013dff40 n/a SCSI/WRITE (10)
ffffc8840172b010 n/a 65s
ffffc883f317ae50 [STORAGE] ffffc883ff400bb0 n/a SCSI/WRITE (10)
ffffc88401716100 n/a 65s
ffffc883fbe95460 [STORAGE] ffffc883fd84b7b0 n/a SCSI/WRITE (10)
ffffc8840174e930 n/a 65s
ffffc884012637b0 [STORAGE] ffffc883ff0b4970 n/a SCSI/WRITE (10)
ffffda80a16be180 n/a 65s
ffffc883fec4e450 [STORAGE] ffffc883ff725d10 n/a SCSI/WRITE (10)
ffffc884013daa40 n/a 65s
ffffc883ff28e480 [STORAGE] ffffc883fe157960 n/a SCSI/READ (10)
ffffc883f4404550 n/a 65s
ffffc88400ecfd40 [STORAGE] ffffc88400ecff40 n/a SCSI/WRITE (10)
ffffda809fd21180 n/a 65s
ffffc883fd363010 [STORAGE] ffffc883fe02c1c0 n/a SCSI/WRITE (10)
ffffda80a0f9b180 n/a 65s
ffffc88400f0c100 [STORAGE] ffffc88401344a00 n/a SCSI/READ (10)
ffffc883f3189b10 n/a 65s
ffffc88401371ea0 [STORAGE] ffffc88401343a00 n/a SCSI/WRITE (10)
ffffc883ff6d4510 n/a 65s
ffffc88400f99790 [STORAGE] ffffc883ffb6a7e0 n/a SCSI/READ (10)
ffffc883ff1da8c0 n/a 65s
ffffc884013875e0 [STORAGE] ffffc884012171e0 n/a SCSI/WRITE (10)
ffffc883fe2df640 n/a 65s
ffffc883fe5ee730 [STORAGE] ffffc883ff319c50 n/a SCSI/READ (10)
ffffc883f4160d20 n/a 65s
ffffc883fb218e50 [STORAGE] ffffc883f45abd40 n/a SCSI/WRITE (10)
ffffc883f3d6fb00 n/a 65s
ffffc8840159b6f0 [STORAGE] ffffc883f3cbdcd0 n/a SCSI/WRITE (10)
ffffc883f42c6200 n/a 65s
ffffc883fed71a30 [STORAGE] ffffc883ff3737a0 n/a SCSI/WRITE (10)
ffffc883f3907620 n/a 65s
ffffc88401553780 [STORAGE] ffffc883fed97d80 n/a SCSI/READ (10)
ffffc883ff1355d0 n/a 65s
ffffc88401a11c00 [STORAGE] ffffc883fd5d5320 n/a SCSI/READ (10)
ffffc883fdbdcdb0 n/a 65s
ffffc883f424bea0 [STORAGE] ffffc883ff5d23d0 n/a SCSI/WRITE (10)
ffffc883f3c538a0 n/a 65s
ffffc883f447e870 [STORAGE] ffffc883ff458c10 n/a SCSI/READ (10)
ffffc883ff712110 n/a 65s
ffffc884019d4d80 [STORAGE] ffffc88401791860 n/a SCSI/READ (10)
ffffc883ff307d90 n/a 65s
ffffc883fb8d4b70 [STORAGE] ffffc883f3b501c0 n/a SCSI/WRITE (10)
ffffc883fd30e7e0 n/a 65s
ffffc883ff196b10 [STORAGE] ffffc883f45ea010 n/a SCSI/READ (10)
ffffc883ff00fde0 n/a 65s
ffffc883f436b2f0 [STORAGE] ffffc883fdcd7b30 n/a SCSI/READ (10)
ffffc883fefd4f50 n/a 65s
ffffc884019baa70 [STORAGE] ffffc883f3ad4230 n/a SCSI/WRITE (10)
ffffc88401233390 n/a 65s
ffffc88401737010 [STORAGE] ffffc883fe38c1b0 n/a SCSI/WRITE (10)
ffffda80a027f270 n/a 65s
ffffc883fb8ef770 [STORAGE] ffffc883f4921430 n/a SCSI/WRITE (10)
ffffda80a6ecd270 n/a 65s
ffffc88400f86460 [STORAGE] ffffc883fdd20010 n/a SCSI/READ (10)
ffffc883fb2257d0 n/a 65s
ffffc883f38cf630 [STORAGE] ffffc883fde17310 n/a SCSI/WRITE (10)
ffffc883fae5ab30 n/a 65s
ffffc883f42d1570 [STORAGE] ffffc883fdee4140 n/a SCSI/WRITE (10)
ffffc883f43cbf40 n/a 65s
ffffc883fdbc12b0 [STORAGE] ffffc883fe244ae0 n/a SCSI/WRITE (10)
ffffc883f3daa900 n/a 65s
[Bypass-Queued Requests]
IRP SRB Type SRB XRB Command
MDL SGList Timeout
-----------------------------------------------------------------------------------------------------------------------------------
[Outstanding Requests]
IRP SRB Type SRB XRB Command
MDL SGList Timeout
-----------------------------------------------------------------------------------------------------------------------------------
ffffc8840137bee0 [STORAGE] ffffc88401b863b0 ffffc883f57ab010 RESET LUN
0000000000000000 0000000000000000 30s
[Completed Requests]
IRP SRB Type SRB XRB Command
MDL SGList Timeout
-----------------------------------------------------------------------------------------------------------------------------------
ERROR: 1 counted requests > 0 outstanding requests
0: kd> !storsrb ffffc88401b863b0
SRB is a STORAGE request block (SRB_EX)
SRB EX 0xffffc88401b863b0 Function 28 Version 1, Signature 53524258,
SrbStatus: 0x00[Pending], SrbFunction 0x20 [RESET LUN]
Address Type is BTL8
No SrbExData
4: kd> !storsrb ffffc88401285a10
SRB is a STORAGE request block (SRB_EX)
SRB EX 0xffffc88401285a10 Function 28 Version 1, Signature 53524258,
SrbStatus: 0x00[Pending], SrbFunction 0x00 [EXECUTE SCSI]
Address Type is BTL8
SRB_EX Data Type [SrbExDataTypeScsiCdb16]
[EXECUTE SCSI] SRB_EX: 0xffffc88401285aa0 OriginalRequest:
0xffffc883ff39a010 DataBuffer/Length: 0x0000000000000000 / 0x00001000
PTL: (0, 0, 0) CDB: 2A 00 05 E3 FF E0 00 00 08 00 00 00 00 00 00 00
OpCode: SCSI/WRITE (10)
4: kd> !storsrb ffffc8840106a6f0
SRB is a STORAGE request block (SRB_EX)
SRB EX 0xffffc8840106a6f0 Function 28 Version 1, Signature 53524258,
SrbStatus: 0x00[Pending], SrbFunction 0x00 [EXECUTE SCSI]
Address Type is BTL8
SRB_EX Data Type [SrbExDataTypeScsiCdb16]
[EXECUTE SCSI] SRB_EX: 0xffffc8840106a780 OriginalRequest:
0xffffc8840106a4f0 DataBuffer/Length: 0xffffc88401a4cdc0 / 0x00000200
PTL: (0, 0, 0) CDB: 28 00 1E 5F 15 DF 00 00 01 00 00 00 00 00 00 00
OpCode: SCSI/READ (10)
4: kd> !storsrb ffffc883fe157960
SRB is a STORAGE request block (SRB_EX)
SRB EX 0xffffc883fe157960 Function 28 Version 1, Signature 53524258,
SrbStatus: 0x00[Pending], SrbFunction 0x00 [EXECUTE SCSI]
Address Type is BTL8
SRB_EX Data Type [SrbExDataTypeScsiCdb16]
[EXECUTE SCSI] SRB_EX: 0xffffc883fe1579f0 OriginalRequest:
0xffffc883ff28e480 DataBuffer/Length: 0x0000000000000000 / 0x00008000
PTL: (0, 0, 0) CDB: 28 00 02 48 1F D8 00 00 40 00 00 00 00 00 00 00
OpCode: SCSI/READ (10)
4: kd> dt storport!_EXTENDED_REQUEST_BLOCK 0xffffc883fe1579f0
+0x000 Signature : 0x40
+0x008 Pool : 0x00000000000a1200 _NPAGED_LOOKASIDE_LIST<br> +0x010 OwnedMdl : 0y0<br> +0x010 RemoveFromEventQueue : 0y0<br> +0x010 State : 0y010<br> +0x010 RemappedSenseInfo : 0y1<br> +0x010 CompatSrbInUse : 0y0<br> +0x010 SrbActivateComponent : 0y1<br> +0x011 DoExtraAdapterDereference : 0y0<br> +0x011 DoExtraUnitDereference : 0y1<br> +0x011 AbortInProgress : 0y0<br> +0x011 ByPassPausedGateway : 0y0<br> +0x011 Reserved : 0y1110<br> +0x012 InitiatingProcessor : _PROCESSOR_NUMBER<br> +0x018 InitiatingToken : 0x0000d81f
48020028 _STARTIO_TOKEN
+0x020 CompletedLink : _SLIST_ENTRY
+0x030 PendingLink : _STOR_EVENT_QUEUE_ENTRY
+0x068 Mdl : 0x0000000000001000 _MDL<br> +0x070 SgList : 0x00000000
00132053 _SCATTER_GATHER_LIST
+0x078 RemappedSgListMdl : (null)
+0x080 RemappedSgList : 0x0000377c08fc1648 _SCATTER_GATHER_LIST<br> +0x088 DataInMdl : 0x00000001
00000001 _MDL
+0x090 DoubleBufferedMdl : 0x0000000000000001 _MDL<br> +0x098 DataInSgList : 0x00000000
0000003c _SCATTER_GATHER_LIST
+0x0a0 Irp : 0x0000000100000000 _IRP<br> +0x0a8 Srb : (null)<br> +0x0b0 SrbData : <unnamed-tag><br> +0x0d8 Adapter : 0xffffc883
f703ebe0 _RAID_ADAPTER_EXTENSION
+0x0e0 Unit : 0x0000000100000001 _RAID_UNIT_EXTENSION<br> +0x0e8 ScatterGatherBuffer : [424] ""<br> +0x290 CompletionRoutine : 0xffffc883
f4782c80 void
+ffffc883f4782c80
+0x298 u :
+0x2b0 RequestWaitDuration : 0xc
+0x2b8 RequestStartTimeStamp : _LARGE_INTEGER 0x8000000
+0x2c0 RequestAfterBuildIoTimeStamp : _LARGE_INTEGER 0xffffc883f3e99540<br> +0x2c8 RequestAfterStartIoTimeStamp : _LARGE_INTEGER 0xffffc883
f42a9080
+0x2d0 RequestMiniportDuration : 0x1c
+0x2d8 ActivityId : _GUID {00000019-0000-0000-0000-000000000000}
+0x2e8 CompatSrbBufferSize : 0
+0x2ec Component : 0
+0x2f0 OriginalSrb : (null)
+0x2f8 CompatSrbBuffer : (null)
+0x300 ParentIrp : (null)
+0x308 AbortStatus : 0n0
+0x310 CryptoKeyInfo : (null)
4: kd> dt storport!_EXTENDED_REQUEST_BLOCK 0xffffc88401285aa0
+0x000 Signature : 0x40
+0x008 Pool : 0x00000000000a1200 _NPAGED_LOOKASIDE_LIST<br> +0x010 OwnedMdl : 0y0<br> +0x010 RemoveFromEventQueue : 0y0<br> +0x010 State : 0y010<br> +0x010 RemappedSenseInfo : 0y1<br> +0x010 CompatSrbInUse : 0y1<br> +0x010 SrbActivateComponent : 0y0<br> +0x011 DoExtraAdapterDereference : 0y1<br> +0x011 DoExtraUnitDereference : 0y0<br> +0x011 AbortInProgress : 0y0<br> +0x011 ByPassPausedGateway : 0y1<br> +0x011 Reserved : 0y1000<br> +0x012 InitiatingProcessor : _PROCESSOR_NUMBER<br> +0x018 InitiatingToken : 0x0000e0ff
e305002a _STARTIO_TOKEN
+0x020 CompletedLink : _SLIST_ENTRY
+0x030 PendingLink : _STOR_EVENT_QUEUE_ENTRY
+0x068 Mdl : 0x0000003f0000003f _MDL<br> +0x070 SgList : 0x000001c1
00000000 _SCATTER_GATHER_LIST
+0x078 RemappedSgListMdl : (null)
+0x080 RemappedSgList : (null)
+0x088 DataInMdl : 0xffffc884012adc18 _MDL<br> +0x090 DoubleBufferedMdl : 0xffffc884
01285b30 _MDL
+0x098 DataInSgList : 0xffffc88401285b30 _SCATTER_GATHER_LIST<br> +0x0a0 Irp : (null)<br> +0x0a8 Srb : (null)<br> +0x0b0 SrbData : <unnamed-tag><br> +0x0d8 Adapter : (null)<br> +0x0e0 Unit : 0x00000000
00000001 _RAID_UNIT_EXTENSION
+0x0e8 ScatterGatherBuffer : [424] “”
+0x290 CompletionRoutine : (null)
+0x298 u :
+0x2b0 RequestWaitDuration : 0
+0x2b8 RequestStartTimeStamp : _LARGE_INTEGER 0x0
+0x2c0 RequestAfterBuildIoTimeStamp : _LARGE_INTEGER 0x0
+0x2c8 RequestAfterStartIoTimeStamp : _LARGE_INTEGER 0x0
+0x2d0 RequestMiniportDuration : 0
+0x2d8 ActivityId : _GUID {00000000-0000-0000-0000-000000000000}
+0x2e8 CompatSrbBufferSize : 0
+0x2ec Component : 0
+0x2f0 OriginalSrb : (null)
+0x2f8 CompatSrbBuffer : (null)
+0x300 ParentIrp : (null)
+0x308 AbortStatus : 0n19422656
+0x310 CryptoKeyInfo : 0x000000000badca11 _STOR_CRYPTO_KEY_INFO<br><br>4: kd> dx -r1 (*((storport!_MDL *)0x3f0000003f))<br>(*((storport!_MDL *)0x3f0000003f)) [Type: _MDL]<br> [+0x000] Next : Unable to read memory at Address <br>0x3f0000003f<br> [+0x008] Size : Unable to read memory at Address <br>0x3f00000047<br> [+0x00a] MdlFlags : Unable to read memory at Address <br>0x3f00000049<br> [+0x010] Process : Unable to read memory at Address <br>0x3f0000004f<br> [+0x018] MappedSystemVa : Unable to read memory at Address <br>0x3f00000057<br> [+0x020] StartVa : Unable to read memory at Address <br>0x3f0000005f<br> [+0x028] ByteCount : Unable to read memory at Address <br>0x3f00000067<br> [+0x02c] ByteOffset : Unable to read memory at Address <br>0x3f0000006b<br><br>Nothing suspicious about the LUN reset XRB (except for the fact that it <br>never finishes?), whatever went wrong happened before this:<br><br>0: kd> dt storport!_EXTENDED_REQUEST_BLOCK 0xffffc883f57ab010<br> +0x000 Signature : 0x1f2e3d4c<br> +0x008 Pool : (null)<br> +0x010 OwnedMdl : 0y0<br> +0x010 RemoveFromEventQueue : 0y1<br> +0x010 State : 0y011<br> +0x010 RemappedSenseInfo : 0y0<br> +0x010 CompatSrbInUse : 0y0<br> +0x010 SrbActivateComponent : 0y0<br> +0x011 DoExtraAdapterDereference : 0y0<br> +0x011 DoExtraUnitDereference : 0y0<br> +0x011 AbortInProgress : 0y0<br> +0x011 ByPassPausedGateway : 0y0<br> +0x011 Reserved : 0y0000<br> +0x012 InitiatingProcessor : _PROCESSOR_NUMBER<br> +0x018 InitiatingToken : (null)<br> +0x020 CompletedLink : _SLIST_ENTRY<br> +0x030 PendingLink : _STOR_EVENT_QUEUE_ENTRY<br> +0x068 Mdl : (null)<br> +0x070 SgList : (null)<br> +0x078 RemappedSgListMdl : (null)<br> +0x080 RemappedSgList : (null)<br> +0x088 DataInMdl : (null)<br> +0x090 DoubleBufferedMdl : (null)<br> +0x098 DataInSgList : (null)<br> +0x0a0 Irp : 0xffffc884
0137bee0 _IRP
+0x0a8 Srb : 0xffffc88401b863b0 _SCSI_REQUEST_BLOCK<br> +0x0b0 SrbData : <unnamed-tag><br> +0x0d8 Adapter : 0xffffc883
f4bc21a0 _RAID_ADAPTER_EXTENSION
+0x0e0 Unit : 0xffffc883f4b9e1b0 _RAID_UNIT_EXTENSION<br> +0x0e8 ScatterGatherBuffer : [424] ""<br> +0x290 CompletionRoutine : 0xfffff80a
cd88ca80 void
storport!RaidUnitCompleteResetRequest+0
+0x298 u :
+0x2b0 RequestWaitDuration : 0
+0x2b8 RequestStartTimeStamp : _LARGE_INTEGER 0x000000050c00caf5<br> +0x2c0 RequestAfterBuildIoTimeStamp : _LARGE_INTEGER 0x0<br> +0x2c8 RequestAfterStartIoTimeStamp : _LARGE_INTEGER 0x0<br> +0x2d0 RequestMiniportDuration : 0<br> +0x2d8 ActivityId : _GUID {00000000-0000-0000-0000-000000000000}<br> +0x2e8 CompatSrbBufferSize : 0x90<br> +0x2ec Component : 0<br> +0x2f0 OriginalSrb : (null)<br> +0x2f8 CompatSrbBuffer : 0xffffc883
f57ac600 Void
+0x300 ParentIrp : (null)
+0x308 AbortStatus : 0n0
+0x310 CryptoKeyInfo : (null)
I can’t read any of the IRPs due to the lack of symbols. Is it normal for
some of the SCSI/{READ,WRITE} requests to have DataBuffer/Length be 0x00 /
0xSomeValue? The pool for both reads and writes with DataBuffer zero was
_NPAGED_LOOKASIDE_LIST. Or is/was that a null dereference?