Re: PCI pass-through problem for SN570 NVME SSD

["G.R." <firemeteor@users.sourceforge.net>]

[-- Attachment #1: Type: text/plain, Size: 2628 bytes --]

On Tue, Jul 5, 2022 at 12:21 AM Roger Pau Monné <roger.pau@citrix.com> wrote:
>
> On Mon, Jul 04, 2022 at 11:37:13PM +0800, G.R. wrote:
> > On Mon, Jul 4, 2022 at 11:15 PM G.R. <firemeteor@users.sourceforge.net> wrote:
> > >
> > > On Mon, Jul 4, 2022 at 10:51 PM G.R. <firemeteor@users.sourceforge.net> wrote:
> > > >
> > > > On Mon, Jul 4, 2022 at 9:09 PM Roger Pau Monné <roger.pau@citrix.com> wrote:
> > > > > Can you paste the lspci -vvv output for any other device you are also
> > > > > passing through to this guest?
> > > > >
> > >
> > > As reminded by this request, I tried to assign this nvme device to
> > > another FreeBSD12 domU.
> > Just to clarify, this time this NVME SSD is the only device I passed to this VM.
> >
> > > This time it does not fail at the VM setup stage, but the device is
> > > still not usable at the domU.
> > > The nvmecontrol command is not able to talk to the device at all:
> > > nvme0: IDENTIFY (06) sqid:0 cid:0 nsid:0 cdw10:00000001 cdw11:00000000
> > > nvme0: ABORTED - BY REQUEST (00/07) sqid:0 cid:0 cdw0:0
> > > nvme0: IDENTIFY (06) sqid:0 cid:0 nsid:0 cdw10:00000001 cdw11:00000000
> > > nvme0: ABORTED - BY REQUEST (00/07) sqid:0 cid:0 cdw0:0
> > >
> > > The QEMU log says the following:
> > > 00:05.0] Write-back to unknown field 0x09 (partially) inhibited (0x00)
> > > [00:05.0] If the device doesn't work, try enabling permissive mode
> > > [00:05.0] (unsafe) and if it helps report the problem to xen-devel
> > > [00:05.0] msi_msix_setup: Error: Mapping of MSI-X (err: 61, vec: 0x30, entry 0)
> >
> > I retried with the following:
> > pci=['05:00.0,permissive=1,msitranslate=1']
> > Those extra options suppressed some error logging, but still didn't
> > make the device usable to the domU.
> > The nvmecontrol command still get ABORTED result from the kernel...
> >
> > The only thing remained in the QEMU file is this one:
> > [00:05.0] msi_msix_setup: Error: Mapping of MSI-X (err: 61, vec: 0x30, entry 0)
>
> Hm it seems like Xen doesn't find the position of the MSI-X table
> correctly, given there's only one error path from msi.c returning
> -ENODATA (61).
>
> Are there errors from pciback when this happens?  I would expect the
> call to pci_prepare_msix() from pciback to fail and thus also report
> some error?
>
> I think it's likely I will have to provide an additional debug patch
> to Xen, maybe Jan has an idea of what could be going on.
>
pciback reports the same MSI-x related error.
But even with DEBUG enabled, I didn't see more context reported.
Please find details from the attachment.

> Roger.

[-- Attachment #2: pciback_dbg_xl-pci_assignable_XXX.log --]
[-- Type: text/x-log, Size: 6680 bytes --]

root@gaia:~# xl pci-assignable-add 05:00.0
libxl: warning: libxl_pci.c:814:libxl__device_pci_assignable_add: 0000:05:00.0 not bound to a driver, will not be rebound.

[  323.448115] xen_pciback: wants to seize 0000:05:00.0
[  323.448136] pciback 0000:05:00.0: xen_pciback: probing...
[  323.448137] pciback 0000:05:00.0: xen_pciback: seizing device
[  323.448162] pciback 0000:05:00.0: xen_pciback: pcistub_device_alloc
[  323.448162] pciback 0000:05:00.0: xen_pciback: initializing...
[  323.448163] pciback 0000:05:00.0: xen_pciback: initializing config
[  323.448344] pciback 0000:05:00.0: xen_pciback: enabling device
[  323.448425] xen: registering gsi 16 triggering 0 polarity 1
[  323.448428] Already setup the GSI :16
[  323.448497] pciback 0000:05:00.0: xen_pciback: save state of device
[  323.448642] pciback 0000:05:00.0: xen_pciback: resetting (FLR, D3, etc) the device
[  323.448707] pcieport 0000:00:1d.0: DPC: containment event, status:0x1f11 source:0x0000
[  323.448730] pcieport 0000:00:1d.0: DPC: unmasked uncorrectable error detected
[  323.448760] pcieport 0000:00:1d.0: PCIe Bus Error: severity=Uncorrected (Non-Fatal), type=Transaction Layer, (Receiver ID)
[  323.448786] pcieport 0000:00:1d.0:   device [8086:a330] error status/mask=00200000/00010000
[  323.448813] pcieport 0000:00:1d.0:    [21] ACSViol                (First)
[  324.690979] pciback 0000:05:00.0: not ready 1023ms after FLR; waiting
[  325.730706] pciback 0000:05:00.0: not ready 2047ms after FLR; waiting
[  327.997638] pciback 0000:05:00.0: not ready 4095ms after FLR; waiting
[  332.264251] pciback 0000:05:00.0: not ready 8191ms after FLR; waiting
[  340.584320] pciback 0000:05:00.0: not ready 16383ms after FLR; waiting
[  357.010896] pciback 0000:05:00.0: not ready 32767ms after FLR; waiting
[  391.143951] pciback 0000:05:00.0: not ready 65535ms after FLR; giving up
[  392.249252] pciback 0000:05:00.0: xen_pciback: reset device
[  392.249392] pciback 0000:05:00.0: xen_pciback: xen_pcibk_error_detected(bus:5,devfn:0)
[  392.249393] pciback 0000:05:00.0: xen_pciback: device is not found/assigned
[  392.397074] pciback 0000:05:00.0: xen_pciback: xen_pcibk_error_resume(bus:5,devfn:0)
[  392.397080] pciback 0000:05:00.0: xen_pciback: device is not found/assigned
[  392.397284] pcieport 0000:00:1d.0: AER: device recovery successful

libxl: error: libxl_pci.c:835:libxl__device_pci_assignable_add: failed to quarantine 0000:05:00.0

root@gaia:~# xl pci-assignable-remove 05:00.0
libxl: error: libxl_pci.c:853:libxl__device_pci_assignable_remove: failed to de-quarantine 0000:05:00.0
root@gaia:~# xl pci-assignable-add 05:00.0
libxl: warning: libxl_pci.c:794:libxl__device_pci_assignable_add: 0000:05:00.0 already assigned to pciback
root@gaia:~# xl pci-assignable-remove 05:00.0
[  603.928039] pciback 0000:05:00.0: xen_pciback: removing
[  603.928041] pciback 0000:05:00.0: xen_pciback: found device to remove 
[  603.928042] pciback 0000:05:00.0: xen_pciback: pcistub_device_release
[  604.033372] pcieport 0000:00:1d.0: DPC: containment event, status:0x1f11 source:0x0000
[  604.033512] pcieport 0000:00:1d.0: DPC: unmasked uncorrectable error detected
[  604.033631] pcieport 0000:00:1d.0: PCIe Bus Error: severity=Uncorrected (Non-Fatal), type=Transaction Layer, (Requester ID)
[  604.033758] pcieport 0000:00:1d.0:   device [8086:a330] error status/mask=00100000/00010000
[  604.033856] pcieport 0000:00:1d.0:    [20] UnsupReq               (First)
[  604.033939] pcieport 0000:00:1d.0: AER:   TLP Header: 34000000 05000010 00000000 88458845
[  604.034059] pci 0000:05:00.0: AER: can't recover (no error_detected callback)
[  604.034421] xen_pciback: removed 0000:05:00.0 from seize list
[  604.182597] pcieport 0000:00:1d.0: AER: device recovery successful

root@gaia:~# xl pci-assignable-add 05:00.0
libxl: warning: libxl_pci.c:814:libxl__device_pci_assignable_add: 0000:05:00.0 not bound to a driver, will not be rebound.
[  667.582051] xen_pciback: wants to seize 0000:05:00.0
[  667.582130] pciback 0000:05:00.0: xen_pciback: probing...
[  667.582134] pciback 0000:05:00.0: xen_pciback: seizing device
[  667.582228] pciback 0000:05:00.0: xen_pciback: pcistub_device_alloc
[  667.582231] pciback 0000:05:00.0: xen_pciback: initializing...
[  667.582235] pciback 0000:05:00.0: xen_pciback: initializing config
[  667.582548] pciback 0000:05:00.0: xen_pciback: enabling device
[  667.582599] pciback 0000:05:00.0: enabling device (0000 -> 0002)
[  667.582912] xen: registering gsi 16 triggering 0 polarity 1
[  667.582923] Already setup the GSI :16
[  667.583061] pciback 0000:05:00.0: xen_pciback: MSI-X preparation failed (-6)
[  667.583148] pciback 0000:05:00.0: xen_pciback: save state of device
[  667.583569] pciback 0000:05:00.0: xen_pciback: resetting (FLR, D3, etc) the device
[  667.689656] pciback 0000:05:00.0: xen_pciback: reset device

root@gaia:~# xl pci-assignable-remove 05:00.0
[  720.957988] pciback 0000:05:00.0: xen_pciback: removing
[  720.957996] pciback 0000:05:00.0: xen_pciback: found device to remove 
[  720.957999] pciback 0000:05:00.0: xen_pciback: pcistub_device_release
[  721.065222] pciback 0000:05:00.0: xen_pciback: MSI-X release failed (-16)
[  721.065667] xen_pciback: removed 0000:05:00.0 from seize list

root@gaia:~# xl pci-assignable-add 05:00.0
libxl: warning: libxl_pci.c:814:libxl__device_pci_assignable_add: 0000:05:00.0 not bound to a driver, will not be rebound.

[  763.888631] xen_pciback: wants to seize 0000:05:00.0
[  763.888690] pciback 0000:05:00.0: xen_pciback: probing...
[  763.888691] pciback 0000:05:00.0: xen_pciback: seizing device
[  763.888716] pciback 0000:05:00.0: xen_pciback: pcistub_device_alloc
[  763.888717] pciback 0000:05:00.0: xen_pciback: initializing...
[  763.888717] pciback 0000:05:00.0: xen_pciback: initializing config
[  763.888804] pciback 0000:05:00.0: xen_pciback: enabling device
[  763.888885] xen: registering gsi 16 triggering 0 polarity 1
[  763.888889] Already setup the GSI :16
[  763.888949] pciback 0000:05:00.0: xen_pciback: MSI-X preparation failed (-6)
[  763.888977] pciback 0000:05:00.0: xen_pciback: save state of device
[  763.889126] pciback 0000:05:00.0: xen_pciback: resetting (FLR, D3, etc) the device
[  763.994206] pciback 0000:05:00.0: xen_pciback: reset device

root@gaia:~# xl pci-assignable-remove 05:00.0
[  819.491000] pciback 0000:05:00.0: xen_pciback: removing
[  819.491002] pciback 0000:05:00.0: xen_pciback: found device to remove 
[  819.491003] pciback 0000:05:00.0: xen_pciback: pcistub_device_release
[  819.596113] pciback 0000:05:00.0: xen_pciback: MSI-X release failed (-16)
[  819.596466] xen_pciback: removed 0000:05:00.0 from seize list