nvme-pci: Disabling device after reset failure: -5 occurs while AER recovery
Tushar Dave
tdave at nvidia.com
Fri Mar 10 17:45:48 PST 2023
On 3/10/2023 3:53 PM, Bjorn Helgaas wrote:
> [+cc Lukas, beginning of thread:
> https://lore.kernel.org/all/de1b20e5-ded1-0aae-2221-f5d470d91015@nvidia.com/]
>
> On Fri, Mar 10, 2023 at 02:39:19PM -0800, Tushar Dave wrote:
>> On 3/9/23 09:53, Bjorn Helgaas wrote:
>>> On Wed, Mar 08, 2023 at 07:34:58PM -0800, Tushar Dave wrote:
>>>> On 3/7/23 03:59, Sagi Grimberg wrote:
>>>>> On 3/2/23 02:09, Tushar Dave wrote:
>>>>>> We are observing NVMe device disabled due to reset failure after
>>>>>> injecting Malformed TLP. DPC/AER recovery succeed but NVMe fails.
>>>>>> I tried this on 2 different system and it is 100% reproducible with 6.2
>>>>>> kernel.
>>>>>>
>>>>>> On my system, Samsung NVMe SSD Controller PM173X is directly behind the
>>>>>> Broadcom PCIe Switch Downstream Port.
>>>>>> MalformedTLP is injected by changing MaxPayload Size(MPS) of PCIe switch
>>>>>> to 128B (keeping NVMe device MPS 512B).
>>>>>>
>>>>>> e.g.
>>>>>> # change MPS of PCIe switch (a9:10.0)
>>>>>> $ setpci -v -s a9:10.0 cap_exp+0x8.w
>>>>>> 0000:a9:10.0 (cap 10 @68) @70 = 0857
>>>>>> $ setpci -v -s a9:10.0 cap_exp+0x8.w=0x0817
>>>>>> 0000:a9:10.0 (cap 10 @68) @70 0817
>>>>>> $ lspci -s a9:10.0 -vvv | grep -w DevCtl -A 2
>>>>>> DevCtl: CorrErr+ NonFatalErr+ FatalErr+ UnsupReq-
>>>>>> RlxdOrd+ ExtTag- PhantFunc- AuxPwr- NoSnoop+
>>>>>> MaxPayload 128 bytes, MaxReadReq 128 bytes
>>>>>>
>>>>>> # run some traffic on nvme (ab:00.0)
>>>>>> $ dd if=/dev/nvme0n1 of=/tmp/test bs=4K
>>>>>> dd: error reading '/dev/nvme0n1': Input/output error
>>>>>> 2+0 records in
>>>>>> 2+0 records out
>>>>>> 8192 bytes (8.2 kB, 8.0 KiB) copied, 0.0115304 s, 710 kB/s
>>>>>>
>>>>>> #kernel log:
>>>>>> [ 163.034889] pcieport 0000:a5:01.0: EDR: EDR event received
>>>>>> [ 163.041671] pcieport 0000:a5:01.0: EDR: Reported EDR dev: 0000:a9:10.0
>>>>>> [ 163.049071] pcieport 0000:a9:10.0: DPC: containment event,
>>>>>> status:0x2009 source:0x0000
>>>>>> [ 163.058014] pcieport 0000:a9:10.0: DPC: unmasked uncorrectable error
>>>>>> detected
>>>>>> [ 163.066081] pcieport 0000:a9:10.0: PCIe Bus Error:
>>>>>> severity=Uncorrected (Fatal), type=Transaction Layer, (Receiver ID)
>>>>>> [ 163.078151] pcieport 0000:a9:10.0: device [1000:c030] error
>>>>>> status/mask=00040000/00180000
>>>>>> [ 163.087613] pcieport 0000:a9:10.0: [18] MalfTLP
>>>>>> (First)
>>>>>> [ 163.095281] pcieport 0000:a9:10.0: AER: TLP Header: 60000080
>>>>>> ab0000ff 00000001 d1fd0000
>>>>>> [ 163.104517] pcieport 0000:a9:10.0: AER: broadcast error_detected message
>>>>>> [ 163.112095] nvme nvme0: frozen state error detected, reset controller
>>>>>> [ 163.150716] nvme0c0n1: I/O Cmd(0x2) @ LBA 16, 32 blocks, I/O Error
>>>>>> (sct 0x3 / sc 0x71)
>>>>>> [ 163.159802] I/O error, dev nvme0c0n1, sector 16 op 0x0:(READ) flags
>>>>>> 0x4080700 phys_seg 4 prio class 2
>>>>>> [ 163.383661] pcieport 0000:a9:10.0: AER: broadcast slot_reset message
>>>>>> [ 163.390895] nvme nvme0: restart after slot reset
>>>>>> [ 163.396230] nvme 0000:ab:00.0: restoring config space at offset 0x3c
>>>>>> (was 0x100, writing 0x1ff)
>>>>>> [ 163.406079] nvme 0000:ab:00.0: restoring config space at offset 0x30
>>>>>> (was 0x0, writing 0xe0600000)
>>>>>> [ 163.416212] nvme 0000:ab:00.0: restoring config space at offset 0x10
>>>>>> (was 0x4, writing 0xe0710004)
>>>>>> [ 163.426326] nvme 0000:ab:00.0: restoring config space at offset 0xc
>>>>>> (was 0x0, writing 0x8)
>>>>>> [ 163.435666] nvme 0000:ab:00.0: restoring config space at offset 0x4
>>>>>> (was 0x100000, writing 0x100546)
>>>>>> [ 163.446026] pcieport 0000:a9:10.0: AER: broadcast resume message
>>>>>> [ 163.468311] nvme 0000:ab:00.0: saving config space at offset 0x0
>>>>>> (reading 0xa824144d)
>>>>>> [ 163.477209] nvme 0000:ab:00.0: saving config space at offset 0x4
>>>>>> (reading 0x100546)
>>>>>> [ 163.485876] nvme 0000:ab:00.0: saving config space at offset 0x8
>>>>>> (reading 0x1080200)
>>>>>> [ 163.495399] nvme 0000:ab:00.0: saving config space at offset 0xc
>>>>>> (reading 0x8)
>>>>>> [ 163.504149] nvme 0000:ab:00.0: saving config space at offset 0x10
>>>>>> (reading 0xe0710004)
>>>>>> [ 163.513596] nvme 0000:ab:00.0: saving config space at offset 0x14
>>>>>> (reading 0x0)
>>>>>> [ 163.522310] nvme 0000:ab:00.0: saving config space at offset 0x18
>>>>>> (reading 0x0)
>>>>>> [ 163.531013] nvme 0000:ab:00.0: saving config space at offset 0x1c
>>>>>> (reading 0x0)
>>>>>> [ 163.539704] nvme 0000:ab:00.0: saving config space at offset 0x20
>>>>>> (reading 0x0)
>>>>>> [ 163.548353] nvme 0000:ab:00.0: saving config space at offset 0x24
>>>>>> (reading 0x0)
>>>>>> [ 163.556983] nvme 0000:ab:00.0: saving config space at offset 0x28
>>>>>> (reading 0x0)
>>>>>> [ 163.565615] nvme 0000:ab:00.0: saving config space at offset 0x2c
>>>>>> (reading 0xa80a144d)
>>>>>> [ 163.574899] nvme 0000:ab:00.0: saving config space at offset 0x30
>>>>>> (reading 0xe0600000)
>>>>>> [ 163.584215] nvme 0000:ab:00.0: saving config space at offset 0x34
>>>>>> (reading 0x40)
>>>>>> [ 163.592941] nvme 0000:ab:00.0: saving config space at offset 0x38
>>>>>> (reading 0x0)
>>>>>> [ 163.601554] nvme 0000:ab:00.0: saving config space at offset 0x3c
>>>>>> (reading 0x1ff)
>>>>>> [ 210.089132] block nvme0n1: no usable path - requeuing I/O
>>>>>> [ 223.776595] nvme nvme0: I/O 18 QID 0 timeout, disable controller
>>>>>> [ 223.825236] nvme nvme0: Identify Controller failed (-4)
>>>>>> [ 223.832145] nvme nvme0: Disabling device after reset failure: -5
>>>>>
>>>>> At this point the device is not going to recover.
>>>>
>>>> Yes, I agree.
>>>>
>>>> I looked little bit more and found that nvme reset failure and second DPC,
>>>> both were due to nvme_slot_reset() restoring MPS as part of
>>>> pci_restore_state().
>>>>
>>>> AFAICT, after the first DPC event occurs, nvme device MPS gets changed to
>>>> _default_ value 128B (this is likely due to DPC link retraining). However as
>>>> part of software AER recovery, nvme_slot_reset() restores device state, and
>>>> that brings the nvme device MPS back to 512B. (MPS of PCIe switch a9:10.0
>>>> still remains at 128B).
>>>>
>>>> At this point when nvme_reset_ctrl->nvme_reset_work() tries to enable the
>>>> device, malformedTLP again getting generated and that causes second DPC,
>>>> makes NVMe controller reset to fail as well.
>>>
>>> This sounds like the behavior I expect. IIUC:
>>>
>>> - Switch and NVMe MPS are 512B
>>> - NVMe config space saved (including MPS=512B)
>>> - You change Switch MPS to 128B
>>> - NVMe does DMA with payload > 128B
>>> - Switch reports Malformed TLP because TLP is larger than its MPS
>>> - Recovery resets NVMe, which sets MPS to the default of 128B
>>> - nvme_slot_reset() restores NVMe config space (MPS is now 512B)
>>> - Subsequent NVMe DMA with payload > 128B repeats cycle
>>>
>>> What do you think *should* be happening here? I don't see a PCI
>>> problem here. If you change MPS on the Switch without coordinating
>>> with NVMe, things aren't going to work. Or am I missing something?
>>
>> I agree this is expected but there are instances where I do _not_ see the
>> issue occurring. That is due to involvement of pciehp, which add and
>> configure nvme device - (coordinates MPS with pcie switch, and the new MPS
>> will get saved too. So future tests of this kind won't reproduce this issue
>> and that is understood).
>>
>> IMO though, the result of the test should be consistent.
>> Either pciehp/DPC should take care of device recovery 100% all the time;
>> Or we consider nvme recovery failure as an expected result because MPS of
>> pcie switch got changed without coordinating with nvme.
>>
>> What do you think?
>
> In the log below, pciehp obviously is enabled; should I infer that in
> the log above, it is not?
pciehp is enabled all the time. In the log above and below.
I do not have answer yet why pciehp shows-up only in some tests (due to DPC link
down/up) and not in others like you noticed in both the logs.
>
> Generally we've avoided handling a device reset as a remove/add event
> because upper layers can't deal well with that. But in the log below
> it looks like pciehp *did* treat the DPC containment as a remove/add,
> which of course involves configuring the "new" device and its MPS
> settings.
yes and that puzzled me why? especially when"Link Down/Up ignored (recovered by
DPC)". Do we still have race somewhere, I am not sure.
>
> [ 217.071200] pcieport 0000:a9:10.0: AER: broadcast slot_reset message
> [ 217.071217] nvme nvme0: restart after slot reset
> [ 217.071234] pcieport 0000:a9:10.0: pciehp: Slot(272): Link Down/Up ignored (recovered by DPC)
> [ 217.071250] pcieport 0000:a9:10.0: pciehp: pciehp_check_link_active: lnk_status = 2044
> [ 217.071259] pcieport 0000:a9:10.0: pciehp: Slot(272): Card not present
> [ 217.071267] pcieport 0000:a9:10.0: pciehp: pciehp_unconfigure_device: domain:bus:dev = 0000:ab:00
> [ 217.071320] nvme 0000:ab:00.0: restoring config space at offset 0x3c (was 0x100, writing 0x1ff)
> [ 217.071451] nvme 0000:ab:00.0: nvme_slot_reset: after pci_restore_state, DEVCTL: 0x5957
>
> The .slot_reset() method (nvme_slot_reset()) is called *after* the
> device has been reset, and the device is supposed to be ready for the
> driver to use it. But here it looks like pciehp thinks ab:00.0 is not
> present, so it removes it. Later ab:00.0 is present again, so we
> re-enumerate it:
that is correct.
>
> [ 217.311892] pcieport 0000:a9:10.0: pciehp: Slot(272): Card present
> [ 217.311897] pcieport 0000:a9:10.0: pciehp: Slot(272): Link Up
> [ 217.455159] pcieport 0000:a9:10.0: pciehp: pciehp_check_link_status: lnk_status = 2044
> [ 217.455222] pci 0000:ab:00.0: [144d:a824] type 00 class 0x010802
>
> What kernel are you testing? 53b54ad074de ("PCI/DPC: Await readiness
> of secondary bus after reset") looks like it could be related, but
> you'd have to be using v6.3-rc1 or later to get it.
I am on v6.2 but I will give a try to v6.3-rc1 and get back.
>
>> e.g. [ when pciehp takes care of things]
>>
>> [ 216.608538] pcieport 0000:a9:10.0: pciehp: pending interrupts 0x0108 from
>> Slot Status
>> [ 216.639954] pcieport 0000:a5:01.0: EDR: EDR event received
>> [ 216.640429] pcieport 0000:a5:01.0: EDR: Reported EDR dev: 0000:a9:10.0
>> [ 216.640438] pcieport 0000:a9:10.0: DPC: containment event, status:0x2009
>> source:0x0000
>> [ 216.640442] pcieport 0000:a9:10.0: DPC: unmasked uncorrectable error detected
>> [ 216.640452] pcieport 0000:a9:10.0: PCIe Bus Error: severity=Uncorrected
>> (Fatal), type=Transaction Layer, (Receiver ID)
>> [ 216.652549] pcieport 0000:a9:10.0: device [1000:c030] error
>> status/mask=00040000/00180000
>> [ 216.661975] pcieport 0000:a9:10.0: [18] MalfTLP (First)
>> [ 216.669647] pcieport 0000:a9:10.0: AER: TLP Header: 60000080 ab0000ff
>> 00000102 276fe000
>> [ 216.678890] pcieport 0000:a9:10.0: AER: broadcast error_detected message
>> [ 216.678898] nvme nvme0: frozen state error detected, reset controller
>> [ 216.842570] nvme0c0n1: I/O Cmd(0x2) @ LBA 16, 32 blocks, I/O Error (sct
>> 0x3 / sc 0x71)
>> [ 216.851684] I/O error, dev nvme0c0n1, sector 16 op 0x0:(READ) flags
>> 0x4080700 phys_seg 4 prio class 2
>> [ 217.071200] pcieport 0000:a9:10.0: AER: broadcast slot_reset message
>> [ 217.071217] nvme nvme0: restart after slot reset
>> [ 217.071228] nvme 0000:ab:00.0: nvme_slot_reset: before pci_restore_state
>> DEVCTL: 0x2910
>> [ 217.071234] pcieport 0000:a9:10.0: pciehp: Slot(272): Link Down/Up
>> ignored (recovered by DPC)
>> [ 217.071250] pcieport 0000:a9:10.0: pciehp: pciehp_check_link_active:
>> lnk_status = 2044
>> [ 217.071259] pcieport 0000:a9:10.0: pciehp: Slot(272): Card not present
>> [ 217.071267] pcieport 0000:a9:10.0: pciehp: pciehp_unconfigure_device:
>> domain:bus:dev = 0000:ab:00
>> [ 217.071320] nvme 0000:ab:00.0: restoring config space at offset 0x3c (was
>> 0x100, writing 0x1ff)
>> [ 217.071346] nvme 0000:ab:00.0: restoring config space at offset 0x30 (was
>> 0x0, writing 0xe0600000)
>> [ 217.071373] nvme 0000:ab:00.0: restoring config space at offset 0x10 (was
>> 0x4, writing 0xe0710004)
>> [ 217.071383] nvme 0000:ab:00.0: restoring config space at offset 0xc (was
>> 0x0, writing 0x8)
>> [ 217.071394] nvme 0000:ab:00.0: restoring config space at offset 0x4 (was
>> 0x100000, writing 0x100546)
>> [ 217.071451] nvme 0000:ab:00.0: nvme_slot_reset: after pci_restore_state,
>> DEVCTL: 0x5957
>> [ 217.071464] pcieport 0000:a9:10.0: AER: broadcast resume message
>> [ 217.071467] nvme 0000:ab:00.0: PME# disabled
>> [ 217.071513] pcieport 0000:a9:10.0: AER: device recovery successful
>> [ 217.071522] pcieport 0000:a9:10.0: EDR: DPC port successfully recovered
>> [ 217.071526] nvme 0000:ab:00.0: vgaarb: pci_notify
>> [ 217.071531] pcieport 0000:a5:01.0: EDR: Status for 0000:a9:10.0: 0x80
>> [ 217.071614] nvme nvme0: ctrl state 6 is not RESETTING
>> [ 217.103486] Buffer I/O error on dev nvme0n1, logical block 2, async page read
>> [ 217.308778] pci 0000:ab:00.0: vgaarb: pci_notify
>> [ 217.308831] pci 0000:ab:00.0: vgaarb: pci_notify
>> [ 217.311299] pci 0000:ab:00.0: vgaarb: pci_notify
>> [ 217.311863] pci 0000:ab:00.0: device released
>> [ 217.311887] pcieport 0000:a9:10.0: pciehp: pciehp_check_link_active:
>> lnk_status = 2044
>> [ 217.311892] pcieport 0000:a9:10.0: pciehp: Slot(272): Card present
>> [ 217.311897] pcieport 0000:a9:10.0: pciehp: Slot(272): Link Up
>> [ 217.455159] pcieport 0000:a9:10.0: pciehp: pciehp_check_link_status:
>> lnk_status = 2044
>> [ 217.455222] pci 0000:ab:00.0: [144d:a824] type 00 class 0x010802
>> [ 217.455275] pci 0000:ab:00.0: reg 0x10: [mem 0xe0710000-0xe0717fff 64bit]
>> [ 217.455362] pci 0000:ab:00.0: reg 0x30: [mem 0xe0600000-0xe060ffff pref]
>> [ 217.455380] pci 0000:ab:00.0: Max Payload Size set to 128 (was 512, max 512)
>> [ 217.455726] pci 0000:ab:00.0: reg 0x20c: [mem 0xe0610000-0xe0617fff 64bit]
>> [ 217.455732] pci 0000:ab:00.0: VF(n) BAR0 space: [mem
>> 0xe0610000-0xe070ffff 64bit] (contains BAR0 for 32 VFs)
>> [ 217.456307] pci 0000:ab:00.0: vgaarb: pci_notify
>> [ 217.456404] pcieport 0000:a9:10.0: bridge window [io 0x1000-0x0fff] to
>> [bus ab] add_size 1000
>> [ 217.456413] pcieport 0000:a9:10.0: bridge window [mem
>> 0x00100000-0x000fffff 64bit pref] to [bus ab] add_size 200000 add_align
>> 100000
>> [ 217.456430] pcieport 0000:a9:10.0: BAR 15: no space for [mem size
>> 0x00200000 64bit pref]
>> [ 217.456436] pcieport 0000:a9:10.0: BAR 15: failed to assign [mem size
>> 0x00200000 64bit pref]
>> [ 217.456440] pcieport 0000:a9:10.0: BAR 13: no space for [io size 0x1000]
>> [ 217.456444] pcieport 0000:a9:10.0: BAR 13: failed to assign [io size 0x1000]
>> [ 217.456451] pcieport 0000:a9:10.0: BAR 15: no space for [mem size
>> 0x00200000 64bit pref]
>> [ 217.456457] pcieport 0000:a9:10.0: BAR 15: failed to assign [mem size
>> 0x00200000 64bit pref]
>> [ 217.456464] pcieport 0000:a9:10.0: BAR 13: no space for [io size 0x1000]
>> [ 217.456470] pcieport 0000:a9:10.0: BAR 13: failed to assign [io size 0x1000]
>> [ 217.456480] pci 0000:ab:00.0: BAR 6: assigned [mem 0xe0600000-0xe060ffff pref]
>> [ 217.456488] pci 0000:ab:00.0: BAR 0: assigned [mem 0xe0610000-0xe0617fff 64bit]
>> [ 217.456509] pci 0000:ab:00.0: BAR 7: assigned [mem 0xe0618000-0xe0717fff 64bit]
>> [ 217.456517] pcieport 0000:a9:10.0: PCI bridge to [bus ab]
>> [ 217.456526] pcieport 0000:a9:10.0: bridge window [mem 0xe0600000-0xe07fffff]
>> [ 217.456614] nvme 0000:ab:00.0: vgaarb: pci_notify
>> [ 217.456624] nvme 0000:ab:00.0: runtime IRQ mapping not provided by arch
>> [ 217.457452] nvme nvme10: pci function 0000:ab:00.0
>> [ 217.458154] nvme 0000:ab:00.0: saving config space at offset 0x0 (reading
>> 0xa824144d)
>> [ 217.458166] nvme 0000:ab:00.0: saving config space at offset 0x4 (reading
>> 0x100546)
>> [ 217.458173] nvme 0000:ab:00.0: saving config space at offset 0x8 (reading
>> 0x1080200)
>> [ 217.458179] nvme 0000:ab:00.0: saving config space at offset 0xc (reading 0x8)
>> [ 217.458185] nvme 0000:ab:00.0: saving config space at offset 0x10
>> (reading 0xe0610004)
>> [ 217.458192] nvme 0000:ab:00.0: saving config space at offset 0x14 (reading 0x0)
>> [ 217.458198] nvme 0000:ab:00.0: saving config space at offset 0x18 (reading 0x0)
>> [ 217.458202] nvme 0000:ab:00.0: saving config space at offset 0x1c (reading 0x0)
>> [ 217.458207] nvme 0000:ab:00.0: saving config space at offset 0x20 (reading 0x0)
>> [ 217.458212] nvme 0000:ab:00.0: saving config space at offset 0x24 (reading 0x0)
>> [ 217.458217] nvme 0000:ab:00.0: saving config space at offset 0x28 (reading 0x0)
>> [ 217.458222] nvme 0000:ab:00.0: saving config space at offset 0x2c
>> (reading 0xa80a144d)
>> [ 217.458227] nvme 0000:ab:00.0: saving config space at offset 0x30
>> (reading 0xe0600000)
>> [ 217.458237] nvme 0000:ab:00.0: saving config space at offset 0x34 (reading 0x40)
>> [ 217.458242] nvme 0000:ab:00.0: saving config space at offset 0x38 (reading 0x0)
>> [ 217.458247] nvme 0000:ab:00.0: saving config space at offset 0x3c (reading 0x1ff)
>> [ 217.462192] nvme nvme10: Shutdown timeout set to 10 seconds
>> [ 217.520625] nvme nvme10: 63/0/0 default/read/poll queues
More information about the Linux-nvme
mailing list