LinuxLists.cc - Regression due to "device property: Make it possible to use secondary firmware nodes" Re: Xen-unstable + linux 4.1-mergewindow: problems with PV guest pci passthrough: pcifront pci-0: pciback not responding!!!

2015-05-11 15:20:41

Subject: Regression due to "device property: Make it possible to use secondary firmware nodes" Re: Xen-unstable + linux 4.1-mergewindow: problems with PV guest pci passthrough: pcifront pci-0: pciback not responding!!!

On Tue, May 05, 2015 at 12:18:49AM +0200, Sander Eikelenboom wrote:
> Hello Sander,
>
> Monday, April 27, 2015, 5:48:00 PM, you wrote:
>
> > Hi David / Konrad,
>
> > Here the other problem i found, which is introduced somewhere in the
> > 4.1 mergewindow:
>
> > on 4.1.0-rc1 (with the one revert to get things booting) i get this in
> > the PV Guest console:
>
> > [ 0.517392] crc32c_combine: 8373 self tests passed
> > [ 0.517608] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
> > [ 0.517655] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
> > [ 0.517677] cpcihp_generic: Generic port I/O CompactPCI Hot Plug Driver version: 0.1
> > [ 0.517684] cpcihp_generic: not configured, disabling.
> > [ 0.517700] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
> > [ 0.517713] acpiphp_ibm: ibm_acpiphp_init: acpi_walk_namespace failed
> > [ 0.519849] usbcore: registered new interface driver udlfb
> > [ 0.613289] xen:xen_evtchn: Event-channel device installed
> > [ 0.613436] pcifront pci-0: Installing PCI frontend
> > [ 0.613578] pcifront pci-0: Creating PCI Frontend Bus 0000:00
> > [ 0.613616] pcifront pci-0: PCI host bridge to bus 0000:00
> > [ 0.613624] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
> > [ 0.613631] pci_bus 0000:00: root bus resource [mem 0x00000000-0xffffffffffff]
> > [ 0.613638] pci_bus 0000:00: root bus resource [bus 00-ff]
> > [ 0.616672] pcifront pci-0: pciback not responding!!!
> > [ 2.613762] clocksource tsc: mask: 0xffffffffffffffff max_cycles: 0x2e20fd6f2ba, max_idle_ns: 440795302556 ns
> > [ 2.614275] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
> > [ 2.614682] Linux agpgart interface v0.103
> > [ 2.614731] Hangcheck: starting hangcheck timer 0.9.1 (tick is 180 seconds, margin is 60 seconds).
> > [ 2.614762] [drm] Initialized drm 1.1.0 20060810
> > [ 2.614789] [drm] radeon kernel modesetting enabled.
> > [ 2.616529] brd: module loaded
> > [ 2.617844] loop: module loaded
> > [ 2.620008] pcifront pci-0: pciback not responding!!!
> > [ 4.621490] pcifront pci-0: pciback not responding!!!
> > [ 6.621866] pcifront pci-0: pciback not responding!!!
> > [ 8.622421] pcifront pci-0: pciback not responding!!!
> > etc. etc. etc.
>
>
> > Where on 4.0.0 it get:
>
> > [ 0.442554] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
> > [ 0.442583] acpiphp_ibm: ibm_acpiphp_init: acpi_walk_namespace failed
> > [ 0.443293] pcifront pci-0: Allocated pdev @ 0xffff88001ab23c00 pdev->sh_info @ 0xffff88001937f000
> > [ 0.444885] pcifront pci-0: publishing successful!
> > [ 0.445302] usbcore: registered new interface driver udlfb
> > [ 0.445829] xen:xen_evtchn: Event-channel device installed
> > [ 0.446499] pcifront pci-0: Installing PCI frontend
> > [ 0.446715] pcifront pci-0: Creating PCI Frontend Bus 0000:00
> > [ 0.446951] pcifront pci-0: PCI host bridge to bus 0000:00
> > [ 0.446960] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
> > [ 0.446968] pci_bus 0000:00: root bus resource [mem 0x00000000-0xffffffffffff]
> > [ 0.446988] pci_bus 0000:00: root bus resource [bus 00-ff]
> > [ 0.447002] pci_bus 0000:00: scanning bus
> > [ 0.447140] pci 0000:00:00.0: [13f6:0111] type 00 class 0x040100
> > [ 0.447520] pci 0000:00:00.0: reg 0x10: [io 0x7800-0x78ff]
> > [ 0.449148] pci 0000:00:00.0: supports D1 D2
> > [ 0.449791] pci_bus 0000:00: fixups for bus
> > [ 0.449794] pci_bus 0000:00: bus scan returning with max=00
> > [ 0.450604] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
> > [ 0.451991] Linux agpgart interface v0.103
> > [ 0.452160] Hangcheck: starting hangcheck timer 0.9.1 (tick is 180 seconds, margin is 60 seconds).
> > [ 0.452222] [drm] Initialized drm 1.1.0 20060810
> > [ 0.452300] [drm] radeon kernel modesetting enabled.
> > [ 0.462384] pcifront pci-0: claiming resource 0000:00:00.0/0
>
> > But i thought the patches that would change pci bus scanning were destined for
> > 4.2 though ...
>
> > --
> > Sander
>
> Hi David / Konrad,
>
> I have bisected this one .. it leads to:
>
> commit 97badf873ab60e841243b66133ff9eff2a46ef29
> Author: Rafael J. Wysocki <[email protected]>
> Date: Fri Apr 3 23:23:37 2015 +0200
>
> device property: Make it possible to use secondary firmware nodes
>
> Since i didn't see it directly related to pci-front, i double checked by
> reverting this commit(and 9b73262ccbf2fb0060303f047863214269e64f9a since it
> build depends on the other) on 4.1-rc2.
>
> Reverting in the guest kernel indeed makes pci-front work correct again.

That is quite odd. And sadly I am due for vacation at the end of this week
so own't be able to look at this (and prepare an debug patch for the MSI
addendum debug patch either).

Rafael,

Were there any other bug reports about this particular commit?

Thank you!

>
> --
> Sander
>

2015-05-12 00:34:51

by Rafael J. Wysocki

[permalink] [raw]

Subject: Re: Regression due to "device property: Make it possible to use secondary firmware nodes" Re: Xen-unstable + linux 4.1-mergewindow: problems with PV guest pci passthrough: pcifront pci-0: pciback not responding!!!

On Monday, May 11, 2015 11:20:29 AM Konrad Rzeszutek Wilk wrote:
> On Tue, May 05, 2015 at 12:18:49AM +0200, Sander Eikelenboom wrote:
> > Hello Sander,
> >
> > Monday, April 27, 2015, 5:48:00 PM, you wrote:
> >
> > > Hi David / Konrad,
> >
> > > Here the other problem i found, which is introduced somewhere in the
> > > 4.1 mergewindow:
> >
> > > on 4.1.0-rc1 (with the one revert to get things booting) i get this in
> > > the PV Guest console:
> >
> > > [ 0.517392] crc32c_combine: 8373 self tests passed
> > > [ 0.517608] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
> > > [ 0.517655] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
> > > [ 0.517677] cpcihp_generic: Generic port I/O CompactPCI Hot Plug Driver version: 0.1
> > > [ 0.517684] cpcihp_generic: not configured, disabling.
> > > [ 0.517700] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
> > > [ 0.517713] acpiphp_ibm: ibm_acpiphp_init: acpi_walk_namespace failed
> > > [ 0.519849] usbcore: registered new interface driver udlfb
> > > [ 0.613289] xen:xen_evtchn: Event-channel device installed
> > > [ 0.613436] pcifront pci-0: Installing PCI frontend
> > > [ 0.613578] pcifront pci-0: Creating PCI Frontend Bus 0000:00
> > > [ 0.613616] pcifront pci-0: PCI host bridge to bus 0000:00
> > > [ 0.613624] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
> > > [ 0.613631] pci_bus 0000:00: root bus resource [mem 0x00000000-0xffffffffffff]
> > > [ 0.613638] pci_bus 0000:00: root bus resource [bus 00-ff]
> > > [ 0.616672] pcifront pci-0: pciback not responding!!!
> > > [ 2.613762] clocksource tsc: mask: 0xffffffffffffffff max_cycles: 0x2e20fd6f2ba, max_idle_ns: 440795302556 ns
> > > [ 2.614275] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
> > > [ 2.614682] Linux agpgart interface v0.103
> > > [ 2.614731] Hangcheck: starting hangcheck timer 0.9.1 (tick is 180 seconds, margin is 60 seconds).
> > > [ 2.614762] [drm] Initialized drm 1.1.0 20060810
> > > [ 2.614789] [drm] radeon kernel modesetting enabled.
> > > [ 2.616529] brd: module loaded
> > > [ 2.617844] loop: module loaded
> > > [ 2.620008] pcifront pci-0: pciback not responding!!!
> > > [ 4.621490] pcifront pci-0: pciback not responding!!!
> > > [ 6.621866] pcifront pci-0: pciback not responding!!!
> > > [ 8.622421] pcifront pci-0: pciback not responding!!!
> > > etc. etc. etc.
> >
> >
> > > Where on 4.0.0 it get:
> >
> > > [ 0.442554] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
> > > [ 0.442583] acpiphp_ibm: ibm_acpiphp_init: acpi_walk_namespace failed
> > > [ 0.443293] pcifront pci-0: Allocated pdev @ 0xffff88001ab23c00 pdev->sh_info @ 0xffff88001937f000
> > > [ 0.444885] pcifront pci-0: publishing successful!
> > > [ 0.445302] usbcore: registered new interface driver udlfb
> > > [ 0.445829] xen:xen_evtchn: Event-channel device installed
> > > [ 0.446499] pcifront pci-0: Installing PCI frontend
> > > [ 0.446715] pcifront pci-0: Creating PCI Frontend Bus 0000:00
> > > [ 0.446951] pcifront pci-0: PCI host bridge to bus 0000:00
> > > [ 0.446960] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
> > > [ 0.446968] pci_bus 0000:00: root bus resource [mem 0x00000000-0xffffffffffff]
> > > [ 0.446988] pci_bus 0000:00: root bus resource [bus 00-ff]
> > > [ 0.447002] pci_bus 0000:00: scanning bus
> > > [ 0.447140] pci 0000:00:00.0: [13f6:0111] type 00 class 0x040100
> > > [ 0.447520] pci 0000:00:00.0: reg 0x10: [io 0x7800-0x78ff]
> > > [ 0.449148] pci 0000:00:00.0: supports D1 D2
> > > [ 0.449791] pci_bus 0000:00: fixups for bus
> > > [ 0.449794] pci_bus 0000:00: bus scan returning with max=00
> > > [ 0.450604] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
> > > [ 0.451991] Linux agpgart interface v0.103
> > > [ 0.452160] Hangcheck: starting hangcheck timer 0.9.1 (tick is 180 seconds, margin is 60 seconds).
> > > [ 0.452222] [drm] Initialized drm 1.1.0 20060810
> > > [ 0.452300] [drm] radeon kernel modesetting enabled.
> > > [ 0.462384] pcifront pci-0: claiming resource 0000:00:00.0/0
> >
> > > But i thought the patches that would change pci bus scanning were destined for
> > > 4.2 though ...
> >
> > > --
> > > Sander
> >
> > Hi David / Konrad,
> >
> > I have bisected this one .. it leads to:
> >
> > commit 97badf873ab60e841243b66133ff9eff2a46ef29
> > Author: Rafael J. Wysocki <[email protected]>
> > Date: Fri Apr 3 23:23:37 2015 +0200
> >
> > device property: Make it possible to use secondary firmware nodes
> >
> > Since i didn't see it directly related to pci-front, i double checked by
> > reverting this commit(and 9b73262ccbf2fb0060303f047863214269e64f9a since it
> > build depends on the other) on 4.1-rc2.
> >
> > Reverting in the guest kernel indeed makes pci-front work correct again.
>
> That is quite odd.

Yes, that's weird.

> And sadly I am due for vacation at the end of this week
> so own't be able to look at this (and prepare an debug patch for the MSI
> addendum debug patch either).
>
>
> Rafael,
>
> Were there any other bug reports about this particular commit?

Not that I'm aware of.

I'll look at that tomorrow when I'm a bit less tired.

--
I speak only for myself.
Rafael J. Wysocki, Intel Open Source Technology Center.

2015-05-12 15:24:53

by Sander Eikelenboom

[permalink] [raw]

Subject: Re: Regression due to "device property: Make it possible to use secondary firmware nodes" Re: Xen-unstable + linux 4.1-mergewindow: problems with PV guest pci passthrough: pcifront pci-0: pciback not responding!!!

2015-05-12 15:20:01

by Rafael J. Wysocki

[permalink] [raw]

Subject: Re: Regression due to "device property: Make it possible to use secondary firmware nodes" Re: Xen-unstable + linux 4.1-mergewindow: problems with PV guest pci passthrough: pcifront pci-0: pciback not responding!!!

On Tuesday, May 12, 2015 02:59:57 AM Rafael J. Wysocki wrote:
> On Monday, May 11, 2015 11:20:29 AM Konrad Rzeszutek Wilk wrote:
> > On Tue, May 05, 2015 at 12:18:49AM +0200, Sander Eikelenboom wrote:
> > > Hello Sander,
> > >
> > > Monday, April 27, 2015, 5:48:00 PM, you wrote:
> > >
> > > > Hi David / Konrad,
> > >
> > > > Here the other problem i found, which is introduced somewhere in the
> > > > 4.1 mergewindow:
> > >
> > > > on 4.1.0-rc1 (with the one revert to get things booting) i get this in
> > > > the PV Guest console:
> > >
> > > > [ 0.517392] crc32c_combine: 8373 self tests passed
> > > > [ 0.517608] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
> > > > [ 0.517655] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
> > > > [ 0.517677] cpcihp_generic: Generic port I/O CompactPCI Hot Plug Driver version: 0.1
> > > > [ 0.517684] cpcihp_generic: not configured, disabling.
> > > > [ 0.517700] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
> > > > [ 0.517713] acpiphp_ibm: ibm_acpiphp_init: acpi_walk_namespace failed
> > > > [ 0.519849] usbcore: registered new interface driver udlfb
> > > > [ 0.613289] xen:xen_evtchn: Event-channel device installed
> > > > [ 0.613436] pcifront pci-0: Installing PCI frontend
> > > > [ 0.613578] pcifront pci-0: Creating PCI Frontend Bus 0000:00
> > > > [ 0.613616] pcifront pci-0: PCI host bridge to bus 0000:00
> > > > [ 0.613624] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
> > > > [ 0.613631] pci_bus 0000:00: root bus resource [mem 0x00000000-0xffffffffffff]
> > > > [ 0.613638] pci_bus 0000:00: root bus resource [bus 00-ff]
> > > > [ 0.616672] pcifront pci-0: pciback not responding!!!
> > > > [ 2.613762] clocksource tsc: mask: 0xffffffffffffffff max_cycles: 0x2e20fd6f2ba, max_idle_ns: 440795302556 ns
> > > > [ 2.614275] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
> > > > [ 2.614682] Linux agpgart interface v0.103
> > > > [ 2.614731] Hangcheck: starting hangcheck timer 0.9.1 (tick is 180 seconds, margin is 60 seconds).
> > > > [ 2.614762] [drm] Initialized drm 1.1.0 20060810
> > > > [ 2.614789] [drm] radeon kernel modesetting enabled.
> > > > [ 2.616529] brd: module loaded
> > > > [ 2.617844] loop: module loaded
> > > > [ 2.620008] pcifront pci-0: pciback not responding!!!
> > > > [ 4.621490] pcifront pci-0: pciback not responding!!!
> > > > [ 6.621866] pcifront pci-0: pciback not responding!!!
> > > > [ 8.622421] pcifront pci-0: pciback not responding!!!
> > > > etc. etc. etc.
> > >
> > >
> > > > Where on 4.0.0 it get:
> > >
> > > > [ 0.442554] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
> > > > [ 0.442583] acpiphp_ibm: ibm_acpiphp_init: acpi_walk_namespace failed
> > > > [ 0.443293] pcifront pci-0: Allocated pdev @ 0xffff88001ab23c00 pdev->sh_info @ 0xffff88001937f000
> > > > [ 0.444885] pcifront pci-0: publishing successful!
> > > > [ 0.445302] usbcore: registered new interface driver udlfb
> > > > [ 0.445829] xen:xen_evtchn: Event-channel device installed
> > > > [ 0.446499] pcifront pci-0: Installing PCI frontend
> > > > [ 0.446715] pcifront pci-0: Creating PCI Frontend Bus 0000:00
> > > > [ 0.446951] pcifront pci-0: PCI host bridge to bus 0000:00
> > > > [ 0.446960] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
> > > > [ 0.446968] pci_bus 0000:00: root bus resource [mem 0x00000000-0xffffffffffff]
> > > > [ 0.446988] pci_bus 0000:00: root bus resource [bus 00-ff]
> > > > [ 0.447002] pci_bus 0000:00: scanning bus
> > > > [ 0.447140] pci 0000:00:00.0: [13f6:0111] type 00 class 0x040100
> > > > [ 0.447520] pci 0000:00:00.0: reg 0x10: [io 0x7800-0x78ff]
> > > > [ 0.449148] pci 0000:00:00.0: supports D1 D2
> > > > [ 0.449791] pci_bus 0000:00: fixups for bus
> > > > [ 0.449794] pci_bus 0000:00: bus scan returning with max=00
> > > > [ 0.450604] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
> > > > [ 0.451991] Linux agpgart interface v0.103
> > > > [ 0.452160] Hangcheck: starting hangcheck timer 0.9.1 (tick is 180 seconds, margin is 60 seconds).
> > > > [ 0.452222] [drm] Initialized drm 1.1.0 20060810
> > > > [ 0.452300] [drm] radeon kernel modesetting enabled.
> > > > [ 0.462384] pcifront pci-0: claiming resource 0000:00:00.0/0
> > >
> > > > But i thought the patches that would change pci bus scanning were destined for
> > > > 4.2 though ...
> > >
> > > > --
> > > > Sander
> > >
> > > Hi David / Konrad,
> > >
> > > I have bisected this one .. it leads to:
> > >
> > > commit 97badf873ab60e841243b66133ff9eff2a46ef29
> > > Author: Rafael J. Wysocki <[email protected]>
> > > Date: Fri Apr 3 23:23:37 2015 +0200
> > >
> > > device property: Make it possible to use secondary firmware nodes
> > >
> > > Since i didn't see it directly related to pci-front, i double checked by
> > > reverting this commit(and 9b73262ccbf2fb0060303f047863214269e64f9a since it
> > > build depends on the other) on 4.1-rc2.
> > >
> > > Reverting in the guest kernel indeed makes pci-front work correct again.
> >
> > That is quite odd.
>
> Yes, that's weird.
>
> > And sadly I am due for vacation at the end of this week
> > so own't be able to look at this (and prepare an debug patch for the MSI
> > addendum debug patch either).
> >
> >
> > Rafael,
> >
> > Were there any other bug reports about this particular commit?
>
> Not that I'm aware of.
>
> I'll look at that tomorrow when I'm a bit less tired.

So since device_add_property_set() is not currently used, the commit it's
been bisected to should not have any functional effects on anything, but
nevertheless please apply the appended debug patch and see if you get any
extra output from it.

That said, the commit might make a difference for Xen if there's an already
existing initialization ordering issue, because it slows down the ACPI/PCI
initialization a bit (due to the new checks in set_primary_fwnode()) and
something already racy with respect to it may be able to win the race now.

So I'm wondering, for example, if adding something like msleep(100); at the
beginning of pcifront_init() (right after the initial checks) will make any
difference.

---
drivers/base/core.c | 4 ++++
1 file changed, 4 insertions(+)

Index: linux-pm/drivers/base/core.c
===================================================================
--- linux-pm.orig/drivers/base/core.c
+++ linux-pm/drivers/base/core.c
@@ -2167,11 +2167,15 @@ void set_primary_fwnode(struct device *d
if (fwnode_is_primary(fn))
fn = fn->secondary;

+ WARN_ON_ONCE(fn);
+
fwnode->secondary = fn;
dev->fwnode = fwnode;
} else {
dev->fwnode = fwnode_is_primary(dev->fwnode) ?
dev->fwnode->secondary : NULL;
+
+ WARN_ON_ONCE(dev->fwnode);
}
}
EXPORT_SYMBOL_GPL(set_primary_fwnode);

2015-05-12 22:52:48

by Sander Eikelenboom

[permalink] [raw]

Subject: Re: Regression due to "device property: Make it possible to use secondary firmware nodes" Re: Xen-unstable + linux 4.1-mergewindow: problems with PV guest pci passthrough: pcifront pci-0: pciback not responding!!!

Tuesday, May 12, 2015, 5:45:06 PM, you wrote:

> On Tuesday, May 12, 2015 02:59:57 AM Rafael J. Wysocki wrote:
>> On Monday, May 11, 2015 11:20:29 AM Konrad Rzeszutek Wilk wrote:
>> > On Tue, May 05, 2015 at 12:18:49AM +0200, Sander Eikelenboom wrote:
>> > > Hello Sander,
>> > >
>> > > Monday, April 27, 2015, 5:48:00 PM, you wrote:
>> > >
>> > > > Hi David / Konrad,
>> > >
>> > > > Here the other problem i found, which is introduced somewhere in the
>> > > > 4.1 mergewindow:
>> > >
>> > > > on 4.1.0-rc1 (with the one revert to get things booting) i get this in
>> > > > the PV Guest console:
>> > >
>> > > > [ 0.517392] crc32c_combine: 8373 self tests passed
>> > > > [ 0.517608] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
>> > > > [ 0.517655] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
>> > > > [ 0.517677] cpcihp_generic: Generic port I/O CompactPCI Hot Plug Driver version: 0.1
>> > > > [ 0.517684] cpcihp_generic: not configured, disabling.
>> > > > [ 0.517700] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
>> > > > [ 0.517713] acpiphp_ibm: ibm_acpiphp_init: acpi_walk_namespace failed
>> > > > [ 0.519849] usbcore: registered new interface driver udlfb
>> > > > [ 0.613289] xen:xen_evtchn: Event-channel device installed
>> > > > [ 0.613436] pcifront pci-0: Installing PCI frontend
>> > > > [ 0.613578] pcifront pci-0: Creating PCI Frontend Bus 0000:00
>> > > > [ 0.613616] pcifront pci-0: PCI host bridge to bus 0000:00
>> > > > [ 0.613624] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
>> > > > [ 0.613631] pci_bus 0000:00: root bus resource [mem 0x00000000-0xffffffffffff]
>> > > > [ 0.613638] pci_bus 0000:00: root bus resource [bus 00-ff]
>> > > > [ 0.616672] pcifront pci-0: pciback not responding!!!
>> > > > [ 2.613762] clocksource tsc: mask: 0xffffffffffffffff max_cycles: 0x2e20fd6f2ba, max_idle_ns: 440795302556 ns
>> > > > [ 2.614275] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
>> > > > [ 2.614682] Linux agpgart interface v0.103
>> > > > [ 2.614731] Hangcheck: starting hangcheck timer 0.9.1 (tick is 180 seconds, margin is 60 seconds).
>> > > > [ 2.614762] [drm] Initialized drm 1.1.0 20060810
>> > > > [ 2.614789] [drm] radeon kernel modesetting enabled.
>> > > > [ 2.616529] brd: module loaded
>> > > > [ 2.617844] loop: module loaded
>> > > > [ 2.620008] pcifront pci-0: pciback not responding!!!
>> > > > [ 4.621490] pcifront pci-0: pciback not responding!!!
>> > > > [ 6.621866] pcifront pci-0: pciback not responding!!!
>> > > > [ 8.622421] pcifront pci-0: pciback not responding!!!
>> > > > etc. etc. etc.
>> > >
>> > >
>> > > > Where on 4.0.0 it get:
>> > >
>> > > > [ 0.442554] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
>> > > > [ 0.442583] acpiphp_ibm: ibm_acpiphp_init: acpi_walk_namespace failed
>> > > > [ 0.443293] pcifront pci-0: Allocated pdev @ 0xffff88001ab23c00 pdev->sh_info @ 0xffff88001937f000
>> > > > [ 0.444885] pcifront pci-0: publishing successful!
>> > > > [ 0.445302] usbcore: registered new interface driver udlfb
>> > > > [ 0.445829] xen:xen_evtchn: Event-channel device installed
>> > > > [ 0.446499] pcifront pci-0: Installing PCI frontend
>> > > > [ 0.446715] pcifront pci-0: Creating PCI Frontend Bus 0000:00
>> > > > [ 0.446951] pcifront pci-0: PCI host bridge to bus 0000:00
>> > > > [ 0.446960] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
>> > > > [ 0.446968] pci_bus 0000:00: root bus resource [mem 0x00000000-0xffffffffffff]
>> > > > [ 0.446988] pci_bus 0000:00: root bus resource [bus 00-ff]
>> > > > [ 0.447002] pci_bus 0000:00: scanning bus
>> > > > [ 0.447140] pci 0000:00:00.0: [13f6:0111] type 00 class 0x040100
>> > > > [ 0.447520] pci 0000:00:00.0: reg 0x10: [io 0x7800-0x78ff]
>> > > > [ 0.449148] pci 0000:00:00.0: supports D1 D2
>> > > > [ 0.449791] pci_bus 0000:00: fixups for bus
>> > > > [ 0.449794] pci_bus 0000:00: bus scan returning with max=00
>> > > > [ 0.450604] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
>> > > > [ 0.451991] Linux agpgart interface v0.103
>> > > > [ 0.452160] Hangcheck: starting hangcheck timer 0.9.1 (tick is 180 seconds, margin is 60 seconds).
>> > > > [ 0.452222] [drm] Initialized drm 1.1.0 20060810
>> > > > [ 0.452300] [drm] radeon kernel modesetting enabled.
>> > > > [ 0.462384] pcifront pci-0: claiming resource 0000:00:00.0/0
>> > >
>> > > > But i thought the patches that would change pci bus scanning were destined for
>> > > > 4.2 though ...
>> > >
>> > > > --
>> > > > Sander
>> > >
>> > > Hi David / Konrad,
>> > >
>> > > I have bisected this one .. it leads to:
>> > >
>> > > commit 97badf873ab60e841243b66133ff9eff2a46ef29
>> > > Author: Rafael J. Wysocki <[email protected]>
>> > > Date: Fri Apr 3 23:23:37 2015 +0200
>> > >
>> > > device property: Make it possible to use secondary firmware nodes
>> > >
>> > > Since i didn't see it directly related to pci-front, i double checked by
>> > > reverting this commit(and 9b73262ccbf2fb0060303f047863214269e64f9a since it
>> > > build depends on the other) on 4.1-rc2.
>> > >
>> > > Reverting in the guest kernel indeed makes pci-front work correct again.
>> >
>> > That is quite odd.
>>
>> Yes, that's weird.
>>
>> > And sadly I am due for vacation at the end of this week
>> > so own't be able to look at this (and prepare an debug patch for the MSI
>> > addendum debug patch either).
>> >
>> >
>> > Rafael,
>> >
>> > Were there any other bug reports about this particular commit?
>>
>> Not that I'm aware of.
>>
>> I'll look at that tomorrow when I'm a bit less tired.

> So since device_add_property_set() is not currently used, the commit it's
> been bisected to should not have any functional effects on anything, but
> nevertheless please apply the appended debug patch and see if you get any
> extra output from it.

> That said, the commit might make a difference for Xen if there's an already
> existing initialization ordering issue, because it slows down the ACPI/PCI
> initialization a bit (due to the new checks in set_primary_fwnode()) and
> something already racy with respect to it may be able to win the race now.

> So I'm wondering, for example, if adding something like msleep(100); at the
> beginning of pcifront_init() (right after the initial checks) will make any
> difference.

Hi Rafael,

The WARN's don't trigger, so it's a red herring i suppose :-(
I also tried the msleep(100), but that didn't change anything as well.

Konrad,

I enabled (and extended) the debugging printk's in xen-pcifront.
Why is the code actually "scanning" all those BDF's ?
Hasn't pciback written the virtual slot into xenstore already ?

>From pciback side i get:
[ 523.502306] pciback 0000:03:06.0: resetting (FLR, D3, bus) the device
[ 523.502313] pciback 0000:03:06.0: OK
[ 523.502354] pciback 0000:03:06.0: restoring config space at offset 0x4 (was 0x2100000, writing 0x2100105)
[ 523.527080] pciback 0000:03:06.0: restoring config space at offset 0x4 (was 0x2100000, writing 0x2100105)
[ 524.537592] pciback 0000:03:06.0: restoring config space at offset 0xc (was 0x0, writing 0x4000)
[ 524.537621] pciback 0000:03:06.0: restoring config space at offset 0x4 (was 0x2100080, writing 0x2100000)
[ 524.560066] xen-pciback pci-19-0: allocated pdev @ 0xffff88002f768300
[ 524.561958] xen-pciback pci-19-0: getting be setup
[ 524.562339] xen-pciback pci-19-0: exporting dom 0 bus 3 slot 6 func 0
[ 524.562344] xen_pciback: vpci: 0000:03:06.0: assign to virtual slot 0
[ 524.562607] pciback 0000:03:06.0: registering for 19
[ 524.562881] xen-pciback pci-19-0: Publishing pci roots
[ 524.563269] xen-pciback pci-19-0: writing root 0 at 0000:00
[ 524.569003] xen-pciback pci-19-0: fe state changed 1
[ 525.407945] xen-pciback pci-19-0: fe state changed 3
[ 525.408370] xen-pciback pci-19-0: Reading frontend config
[ 525.408674] xen-pciback pci-19-0: Attaching to frontend resources - gnt_ref=8 evtchn=10
[ 525.408715] xen-pciback pci-19-0: Attached!
[ 525.408717] xen-pciback pci-19-0: Connecting...
[ 525.409629] xen-pciback pci-19-0: Connected? 0
[ 555.416997] xen-blkback: ring-ref 9, event-channel 11, protocol 1 (x86_64-abi) persistent grants
[ 1102.845227] xen-pciback pci-19-0: fe state changed 4
[ 1102.909699] vif vif-19-0 vif19.0: Guest Rx ready

>From pcifront side:
[ 0.665420] pcifront pci-0: Installing PCI frontend
[ 0.665584] pcifront pci-0: Creating PCI Frontend Bus 0000:00
[ 0.665631] pcifront pci-0: PCI host bridge to bus 0000:00
[ 0.665638] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
[ 0.665645] pci_bus 0000:00: root bus resource [mem 0x00000000-0xffffffffffff]
[ 0.665654] pci_bus 0000:00: root bus resource [bus 00-ff]
[ 0.665659] pci_bus 0000:00: scanning bus
[ 0.665666] pcifront pci-0: read dev=0000:00:00.0 - offset 0 size 4
[ 0.667330] pcifront pci-0: pciback not responding!!! irq:24 irq_flags:ffff880018c00004 ns: 1431462193392053000 ns_timeout: 1431462193392052000
[ 2.665795] clocksource tsc: mask: 0xffffffffffffffff max_cycles: 0x2e2108dd018, max_idle_ns: 440795268512 ns
[ 2.667763] brd: module loaded
[ 2.669244] loop: module loaded
[ 2.669421] pcifront pci-0: read dev=0000:00:01.0 - offset 0 size 4
[ 2.670009] pcifront pci-0: pciback not responding!!! irq:24 irq_flags:ffff880018c00004 ns: 1431462195395810000 ns_timeout: 1431462195395809000
[ 4.669545] pcifront pci-0: read dev=0000:00:02.0 - offset 0 size 4
[ 4.672797] pcifront pci-0: pciback not responding!!! irq:24 irq_flags:ffff880018c00004 ns: 1431462197395932000 ns_timeout: 1431462197395931000
[ 6.669817] pcifront pci-0: read dev=0000:00:03.0 - offset 0 size 4
[ 6.672908] pcifront pci-0: pciback not responding!!! irq:24 irq_flags:ffff880018c00004 ns: 1431462199396207000 ns_timeout: 1431462199396206000
[ 8.669901] pcifront pci-0: read dev=0000:00:04.0 - offset 0 size 4
[ 8.673182] pcifront pci-0: pciback not responding!!! irq:24 irq_flags:ffff880018c00004 ns: 1431462201396836000 ns_timeout: 1431462201396297000
[ 10.670587] pcifront pci-0: read dev=0000:00:05.0 - offset 0 size 4
[ 10.673829] pcifront pci-0: pciback not responding!!! irq:24 irq_flags:ffff880018c00004 ns: 1431462203396981000 ns_timeout: 1431462203396973000
[ 12.670810] pcifront pci-0: read dev=0000:00:06.0 - offset 0 size 4
[ 12.673995] pcifront pci-0: pciback not responding!!! irq:24 irq_flags:ffff880018c00004 ns: 1431462205397206000 ns_timeout: 1431462205397202000
[ 14.670943] pcifront pci-0: read dev=0000:00:07.0 - offset 0 size 4
[ 14.674205] pcifront pci-0: pciback not responding!!! irq:24 irq_flags:ffff880018c00004 ns: 1431462207397332000 ns_timeout: 1431462207397331000
[ 16.671076] pcifront pci-0: read dev=0000:00:08.0 - offset 0 size 4
[ 16.674331] pcifront pci-0: pciback not responding!!! irq:24 irq_flags:ffff880018c00004 ns: 1431462209397463000 ns_timeout: 1431462209397462000
[ 18.671133] pcifront pci-0: read dev=0000:00:09.0 - offset 0 size 4
[ 18.674438] pcifront pci-0: pciback not responding!!! irq:24 irq_flags:ffff880018c00004 ns: 1431462211397520000 ns_timeout: 1431462211397519000

<big snip>

[ 560.071316] pcifront pci-0: read dev=0000:00:1e.7 - offset 0 size 4
[ 560.073698] pcifront pci-0: pciback not responding!!! irq:24 irq_flags:ffff880018c00004 ns: 1431462752797707000 ns_timeout: 1431462752797706000
[ 562.072326] pcifront pci-0: read dev=0000:00:1f.0 - offset 0 size 4
[ 562.074707] pcifront pci-0: pciback not responding!!! irq:24 irq_flags:ffff880018c00004 ns: 1431462754798720000 ns_timeout: 1431462754798717000
[ 564.074359] pcifront pci-0: read dev=0000:00:1f.1 - offset 0 size 4
[ 564.076821] pcifront pci-0: pciback not responding!!! irq:24 irq_flags:ffff880018c00004 ns: 1431462756800762000 ns_timeout: 1431462756800761000
[ 566.075590] pcifront pci-0: read dev=0000:00:1f.2 - offset 0 size 4
[ 566.077791] pcifront pci-0: pciback not responding!!! irq:24 irq_flags:ffff880018c00004 ns: 1431462758801996000 ns_timeout: 1431462758801995000
[ 568.076680] pcifront pci-0: read dev=0000:00:1f.3 - offset 0 size 4
[ 568.079960] pcifront pci-0: pciback not responding!!! irq:24 irq_flags:ffff880018c00004 ns: 1431462760803264000 ns_timeout: 1431462760803084000
[ 570.077939] pcifront pci-0: read dev=0000:00:1f.4 - offset 0 size 4
[ 570.080267] pcifront pci-0: pciback not responding!!! irq:24 irq_flags:ffff880018c00004 ns: 1431462762804331000 ns_timeout: 1431462762804330000
[ 572.078953] pcifront pci-0: read dev=0000:00:1f.5 - offset 0 size 4
[ 572.081338] pcifront pci-0: pciback not responding!!! irq:24 irq_flags:ffff880018c00004 ns: 1431462764805354000 ns_timeout: 1431462764805349000
[ 574.080073] pcifront pci-0: read dev=0000:00:1f.6 - offset 0 size 4
[ 574.083323] pcifront pci-0: pciback not responding!!! irq:24 irq_flags:ffff880018c00004 ns: 1431462766806466000 ns_timeout: 1431462766806463000
[ 576.081077] pcifront pci-0: read dev=0000:00:1f.7 - offset 0 size 4
[ 576.083464] pcifront pci-0: pciback not responding!!! irq:24 irq_flags:ffff880018c00004 ns: 1431462768807992000 ns_timeout: 1431462768807468000
[ 578.102629] blkfront: xvda: flush diskcache: enabled; persistent grants: enabled; indirect descriptors: enabled;

Now pcifront timed out (and pciback reports a state change to 4 which is
"connected" .. which also seems a wrong fallthrough somewhere.

After reverting the two commits again .. i get a working pci device and this
output from pci-front:
[ 0.628804] pcifront pci-0: Installing PCI frontend
[ 0.629167] pcifront pci-0: Creating PCI Frontend Bus 0000:00
[ 0.629225] pcifront pci-0: PCI host bridge to bus 0000:00
[ 0.629237] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
[ 0.629254] pci_bus 0000:00: root bus resource [mem 0x00000000-0xffffffffffff]
[ 0.629269] pci_bus 0000:00: root bus resource [bus 00-ff]
[ 0.629285] pci_bus 0000:00: scanning bus
[ 0.629303] pcifront pci-0: read dev=0000:00:00.0 - offset 0 size 4
[ 0.629344] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444164529000 ns_timeout: 1431470446164504000
[ 0.629364] pcifront pci-0: read got back value 11113f6
[ 0.629383] pcifront pci-0: read dev=0000:00:00.0 - offset e size 1
[ 0.629413] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444164599000 ns_timeout: 1431470446164589000
[ 0.629433] pcifront pci-0: read got back value 0
[ 0.629452] pcifront pci-0: read dev=0000:00:00.0 - offset 6 size 2
[ 0.629483] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444164670000 ns_timeout: 1431470446164659000
[ 0.629504] pcifront pci-0: read got back value 210
[ 0.629518] pcifront pci-0: read dev=0000:00:00.0 - offset 34 size 1
[ 0.629547] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444164733000 ns_timeout: 1431470446164724000
[ 0.629566] pcifront pci-0: read got back value c0
[ 0.629579] pcifront pci-0: read dev=0000:00:00.0 - offset c0 size 2
[ 0.629609] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444164796000 ns_timeout: 1431470446164786000
[ 0.629632] pcifront pci-0: read got back value 1
[ 0.629647] pcifront pci-0: read dev=0000:00:00.0 - offset 8 size 4
[ 0.629676] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444164863000 ns_timeout: 1431470446164853000
[ 0.629696] pcifront pci-0: read got back value 4010010
[ 0.629709] pci 0000:00:00.0: [13f6:0111] type 00 class 0x040100
[ 0.629720] pcifront pci-0: read dev=0000:00:00.0 - offset 6 size 2
[ 0.629743] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444164929000 ns_timeout: 1431470446164920000
[ 0.629774] pcifront pci-0: read got back value 210
[ 0.629787] pcifront pci-0: read dev=0000:00:00.0 - offset 34 size 1
[ 0.629828] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444165014000 ns_timeout: 1431470446164999000
[ 0.629847] pcifront pci-0: read got back value c0
[ 0.629860] pcifront pci-0: read dev=0000:00:00.0 - offset c0 size 2
[ 0.629889] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444165076000 ns_timeout: 1431470446165067000
[ 0.629919] pcifront pci-0: read got back value 1
[ 0.629932] pcifront pci-0: read dev=0000:00:00.0 - offset 3d size 1
[ 0.629966] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444165152000 ns_timeout: 1431470446165138000
[ 0.630007] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444165194000 ns_timeout: 1431470446165138000
[ 0.630020] pcifront pci-0: read got back value 1
[ 0.630066] pcifront pci-0: read dev=0000:00:00.0 - offset 3c size 1
[ 0.630099] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444165285000 ns_timeout: 1431470446165275000
[ 0.630120] pcifront pci-0: read got back value 16
[ 0.630140] pcifront pci-0: read dev=0000:00:00.0 - offset 4 size 2
[ 0.630172] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444165358000 ns_timeout: 1431470446165348000
[ 0.630204] pcifront pci-0: read got back value 101
[ 0.630238] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444165421000 ns_timeout: 1431470446165414000
[ 0.630265] pcifront pci-0: read dev=0000:00:00.0 - offset 10 size 4
[ 0.630292] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444165480000 ns_timeout: 1431470446165472000
[ 0.630323] pcifront pci-0: read got back value 7801
[ 0.630354] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444165540000 ns_timeout: 1431470446165531000
[ 0.630389] pcifront pci-0: read dev=0000:00:00.0 - offset 10 size 4
[ 0.630425] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444165611000 ns_timeout: 1431470446165596000
[ 0.630456] pcifront pci-0: read got back value 100
[ 0.630489] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444165675000 ns_timeout: 1431470446165665000
[ 0.630529] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444165715000 ns_timeout: 1431470446165703000
[ 0.630571] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444165757000 ns_timeout: 1431470446165703000
[ 0.630613] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444165800000 ns_timeout: 1431470446165703000
[ 0.630655] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444165842000 ns_timeout: 1431470446165703000
[ 0.630698] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444165884000 ns_timeout: 1431470446165703000
[ 0.630733] pci 0000:00:00.0: reg 0x10: [io 0x7800-0x78ff]
[ 0.803637] pcifront pci-0: read dev=0000:00:00.0 - offset 4 size 2
[ 0.803701] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444338888000 ns_timeout: 1431470446338836000
[ 0.803712] pcifront pci-0: read got back value 101
[ 0.803861] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444339049000 ns_timeout: 1431470446338910000
[ 0.803876] pcifront pci-0: read dev=0000:00:00.0 - offset 14 size 4
[ 0.803920] pcifront pci-0: ?!?!? pciback responded !!! irq:24 irq_flags:ffff88001ab40004 ns: 1431470444339108000 ns_timeout: 143147044633907400

etc.

On a side note .. why is it actually "scanning" the bus and all possible BDF's ?
Shouldn't pcifront already be able to know the virtual slot pciback has written
to xenstore were the device(s) will be ?

The only direct change involving xen-pciback and pcifront seems to be:

commit ccc9d90a9a8b5c4ad7e9708ec41f75ff9e98d61d
Author: Wei Liu <[email protected]>
Date: Fri Apr 3 14:44:59 2015 +0800

xenbus_client: Extend interface to support multi-page ring

But my bisect didn't point that out :S

Any pointers were to add more debug code ?
--
Sander

> ---
> drivers/base/core.c | 4 ++++
> 1 file changed, 4 insertions(+)

> Index: linux-pm/drivers/base/core.c
> ===================================================================
> --- linux-pm.orig/drivers/base/core.c
> +++ linux-pm/drivers/base/core.c
> @@ -2167,11 +2167,15 @@ void set_primary_fwnode(struct device *d
> if (fwnode_is_primary(fn))
> fn = fn->secondary;
>
> + WARN_ON_ONCE(fn);
> +
> fwnode->secondary = fn;
> dev->fwnode = fwnode;
> } else {
> dev->fwnode = fwnode_is_primary(dev->fwnode) ?
> dev->fwnode->secondary : NULL;
> +
> + WARN_ON_ONCE(dev->fwnode);
> }
> }
> EXPORT_SYMBOL_GPL(set_primary_fwnode);

2015-05-12 23:05:16

by Rafael J. Wysocki

[permalink] [raw]

Subject: Re: Regression due to "device property: Make it possible to use secondary firmware nodes" Re: Xen-unstable + linux 4.1-mergewindow: problems with PV guest pci passthrough: pcifront pci-0: pciback not responding!!!

On Wednesday, May 13, 2015 12:52:36 AM Sander Eikelenboom wrote:
>
> Tuesday, May 12, 2015, 5:45:06 PM, you wrote:
>
> > On Tuesday, May 12, 2015 02:59:57 AM Rafael J. Wysocki wrote:
> >> On Monday, May 11, 2015 11:20:29 AM Konrad Rzeszutek Wilk wrote:
> >> > On Tue, May 05, 2015 at 12:18:49AM +0200, Sander Eikelenboom wrote:
> >> > > Hello Sander,
> >> > >
> >> > > Monday, April 27, 2015, 5:48:00 PM, you wrote:
> >> > >
> >> > > > Hi David / Konrad,
> >> > >
> >> > > > Here the other problem i found, which is introduced somewhere in the
> >> > > > 4.1 mergewindow:
> >> > >
> >> > > > on 4.1.0-rc1 (with the one revert to get things booting) i get this in
> >> > > > the PV Guest console:
> >> > >
> >> > > > [ 0.517392] crc32c_combine: 8373 self tests passed
> >> > > > [ 0.517608] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
> >> > > > [ 0.517655] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
> >> > > > [ 0.517677] cpcihp_generic: Generic port I/O CompactPCI Hot Plug Driver version: 0.1
> >> > > > [ 0.517684] cpcihp_generic: not configured, disabling.
> >> > > > [ 0.517700] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
> >> > > > [ 0.517713] acpiphp_ibm: ibm_acpiphp_init: acpi_walk_namespace failed
> >> > > > [ 0.519849] usbcore: registered new interface driver udlfb
> >> > > > [ 0.613289] xen:xen_evtchn: Event-channel device installed
> >> > > > [ 0.613436] pcifront pci-0: Installing PCI frontend
> >> > > > [ 0.613578] pcifront pci-0: Creating PCI Frontend Bus 0000:00
> >> > > > [ 0.613616] pcifront pci-0: PCI host bridge to bus 0000:00
> >> > > > [ 0.613624] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
> >> > > > [ 0.613631] pci_bus 0000:00: root bus resource [mem 0x00000000-0xffffffffffff]
> >> > > > [ 0.613638] pci_bus 0000:00: root bus resource [bus 00-ff]
> >> > > > [ 0.616672] pcifront pci-0: pciback not responding!!!
> >> > > > [ 2.613762] clocksource tsc: mask: 0xffffffffffffffff max_cycles: 0x2e20fd6f2ba, max_idle_ns: 440795302556 ns
> >> > > > [ 2.614275] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
> >> > > > [ 2.614682] Linux agpgart interface v0.103
> >> > > > [ 2.614731] Hangcheck: starting hangcheck timer 0.9.1 (tick is 180 seconds, margin is 60 seconds).
> >> > > > [ 2.614762] [drm] Initialized drm 1.1.0 20060810
> >> > > > [ 2.614789] [drm] radeon kernel modesetting enabled.
> >> > > > [ 2.616529] brd: module loaded
> >> > > > [ 2.617844] loop: module loaded
> >> > > > [ 2.620008] pcifront pci-0: pciback not responding!!!
> >> > > > [ 4.621490] pcifront pci-0: pciback not responding!!!
> >> > > > [ 6.621866] pcifront pci-0: pciback not responding!!!
> >> > > > [ 8.622421] pcifront pci-0: pciback not responding!!!
> >> > > > etc. etc. etc.
> >> > >
> >> > >
> >> > > > Where on 4.0.0 it get:
> >> > >
> >> > > > [ 0.442554] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
> >> > > > [ 0.442583] acpiphp_ibm: ibm_acpiphp_init: acpi_walk_namespace failed
> >> > > > [ 0.443293] pcifront pci-0: Allocated pdev @ 0xffff88001ab23c00 pdev->sh_info @ 0xffff88001937f000
> >> > > > [ 0.444885] pcifront pci-0: publishing successful!
> >> > > > [ 0.445302] usbcore: registered new interface driver udlfb
> >> > > > [ 0.445829] xen:xen_evtchn: Event-channel device installed
> >> > > > [ 0.446499] pcifront pci-0: Installing PCI frontend
> >> > > > [ 0.446715] pcifront pci-0: Creating PCI Frontend Bus 0000:00
> >> > > > [ 0.446951] pcifront pci-0: PCI host bridge to bus 0000:00
> >> > > > [ 0.446960] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
> >> > > > [ 0.446968] pci_bus 0000:00: root bus resource [mem 0x00000000-0xffffffffffff]
> >> > > > [ 0.446988] pci_bus 0000:00: root bus resource [bus 00-ff]
> >> > > > [ 0.447002] pci_bus 0000:00: scanning bus
> >> > > > [ 0.447140] pci 0000:00:00.0: [13f6:0111] type 00 class 0x040100
> >> > > > [ 0.447520] pci 0000:00:00.0: reg 0x10: [io 0x7800-0x78ff]
> >> > > > [ 0.449148] pci 0000:00:00.0: supports D1 D2
> >> > > > [ 0.449791] pci_bus 0000:00: fixups for bus
> >> > > > [ 0.449794] pci_bus 0000:00: bus scan returning with max=00
> >> > > > [ 0.450604] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
> >> > > > [ 0.451991] Linux agpgart interface v0.103
> >> > > > [ 0.452160] Hangcheck: starting hangcheck timer 0.9.1 (tick is 180 seconds, margin is 60 seconds).
> >> > > > [ 0.452222] [drm] Initialized drm 1.1.0 20060810
> >> > > > [ 0.452300] [drm] radeon kernel modesetting enabled.
> >> > > > [ 0.462384] pcifront pci-0: claiming resource 0000:00:00.0/0
> >> > >
> >> > > > But i thought the patches that would change pci bus scanning were destined for
> >> > > > 4.2 though ...
> >> > >
> >> > > > --
> >> > > > Sander
> >> > >
> >> > > Hi David / Konrad,
> >> > >
> >> > > I have bisected this one .. it leads to:
> >> > >
> >> > > commit 97badf873ab60e841243b66133ff9eff2a46ef29
> >> > > Author: Rafael J. Wysocki <[email protected]>
> >> > > Date: Fri Apr 3 23:23:37 2015 +0200
> >> > >
> >> > > device property: Make it possible to use secondary firmware nodes
> >> > >
> >> > > Since i didn't see it directly related to pci-front, i double checked by
> >> > > reverting this commit(and 9b73262ccbf2fb0060303f047863214269e64f9a since it
> >> > > build depends on the other) on 4.1-rc2.
> >> > >
> >> > > Reverting in the guest kernel indeed makes pci-front work correct again.
> >> >
> >> > That is quite odd.
> >>
> >> Yes, that's weird.
> >>
> >> > And sadly I am due for vacation at the end of this week
> >> > so own't be able to look at this (and prepare an debug patch for the MSI
> >> > addendum debug patch either).
> >> >
> >> >
> >> > Rafael,
> >> >
> >> > Were there any other bug reports about this particular commit?
> >>
> >> Not that I'm aware of.
> >>
> >> I'll look at that tomorrow when I'm a bit less tired.
>
> > So since device_add_property_set() is not currently used, the commit it's
> > been bisected to should not have any functional effects on anything, but
> > nevertheless please apply the appended debug patch and see if you get any
> > extra output from it.
>
> > That said, the commit might make a difference for Xen if there's an already
> > existing initialization ordering issue, because it slows down the ACPI/PCI
> > initialization a bit (due to the new checks in set_primary_fwnode()) and
> > something already racy with respect to it may be able to win the race now.
>
> > So I'm wondering, for example, if adding something like msleep(100); at the
> > beginning of pcifront_init() (right after the initial checks) will make any
> > difference.
>
> Hi Rafael,
>
> The WARN's don't trigger, so it's a red herring i suppose :-(

It seems so.

The commit also changes the size of struct acpi_device, but that shouldn't
matter.

> I also tried the msleep(100), but that didn't change anything as well.

I see.

Well, I'm not really familiar with the Xen-related code, so it is hard to
me to give you any useful advice here.

--
I speak only for myself.
Rafael J. Wysocki, Intel Open Source Technology Center.

2015-05-14 22:50:42

by Konrad Rzeszutek Wilk

[permalink] [raw]

Subject: Re: Regression due to "device property: Make it possible to use secondary firmware nodes" Re: Xen-unstable + linux 4.1-mergewindow: problems with PV guest pci passthrough: pcifront pci-0: pciback not responding!!!

Hi Konrad / David,

One a big snip on this thread, got some more debug info, hopefully this will
lead to something:

On a working kernel (with the two seemingly non related patches reverted) i get:

[ 0.717796] pcifront pci-0: Allocated pdev @ 0xffff880019e11780 pdev->sh_info @ 0xffff880018f58000
[ 0.717848] pcifront pci-0: ?!?!? before alloc gntref: 0
[ 0.717871] pcifront pci-0: ?!?!? after alloc gntref: 8
[ 0.717892] pcifront pci-0: ?!?!? before alloc evtchn: -1
[ 0.717915] pcifront pci-0: ?!?!? after alloc evtchn: 17
[ 0.717984] pcifront pci-0: ?!?!? bound evtchn:17 to irqhandler:-1 err:31
[ 0.721640] pcifront pci-0: publishing successful!
[ 0.723684] usbcore: registered new interface driver udlfb
[ 0.724664] xen:xen_evtchn: Event-channel device installed
[ 0.726597] pcifront pci-0: Installing PCI frontend
[ 0.726853] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[ 0.727059] pcifront pci-0: Creating PCI Frontend Bus 0000:00
[ 0.727363] pcifront pci-0: PCI host bridge to bus 0000:00
[ 0.727391] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
[ 0.727417] pci_bus 0000:00: root bus resource [mem 0x00000000-0xffffffffffff]
[ 0.727452] pci_bus 0000:00: root bus resource [bus 00-ff]
[ 0.727475] pci_bus 0000:00: scanning bus
[ 0.727503] pcifront pci-0: read dev=0000:00:00.0 - offset 0 size 4
[ 0.728253] Linux agpgart interface v0.103
[ 0.728387] Hangcheck: starting hangcheck timer 0.9.1 (tick is 180 seconds, margin is 60 seconds).
[ 0.728474] [drm] Initialized drm 1.1.0 20060810
[ 0.728551] [drm] radeon kernel modesetting enabled.
[ 0.730319] pcifront pci-0: ?!?!? pciback responded !!! irq:31 irq_flags:ffff880019e100a8 ns: 1431641785551700000 ns_timeout: 1431641787541235000 evtchn:17 gnt_ref:8
[ 0.730319] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
[ 0.730319] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
[ 0.730319] pcifront pci-0: read got back value 11113f6
[ 0.738845] pcifront pci-0: read dev=0000:00:00.0 - offset e size 1
[ 0.744976] brd: module loaded
[ 0.745204] pcifront pci-0: ?!?!? pciback responded !!! irq:31 irq_flags:ffff880019e100a8 ns: 1431641785562852000 ns_timeout: 1431641787552580000 evtchn:17 gnt_ref:8
[ 0.745204] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:14 size:1
[ 0.745204] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:14 size:1
[ 0.745204] pcifront pci-0: read got back value 0
[ 0.749204] pcifront pci-0: read dev=0000:00:00.0 - offset 6 size 2
[ 0.750155] loop: module loaded
[ 0.752527] pcifront pci-0: ?!?!? pciback responded !!! irq:31 irq_flags:ffff880019e100a8 ns: 1431641785570841000 ns_timeout: 1431641787562917000 evtchn:17 gnt_ref:8
[ 0.752527] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:6 size:2
[ 0.752527] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:6 size:2
[ 0.752527] pcifront pci-0: read got back value 210
[ 0.757187] pcifront pci-0: read dev=0000:00:00.0 - offset 34 size 1

Were as in the non-working situation i get:

[ 0.751244] pcifront pci-0: Allocated pdev @ 0xffff880019ec2e00 pdev->sh_info @ 0xffff88001aa51000
[ 0.751295] pcifront pci-0: ?!?!? before alloc gntref: 0
[ 0.751315] pcifront pci-0: ?!?!? after alloc gntref: 8
[ 0.751334] pcifront pci-0: ?!?!? before alloc evtchn: -1
[ 0.751355] pcifront pci-0: ?!?!? after alloc evtchn: 17
[ 0.751422] pcifront pci-0: ?!?!? bound evtchn:17 to irqhandler:-1 err:31
[ 0.755215] pcifront pci-0: publishing successful!
[ 0.757341] usbcore: registered new interface driver udlfb
[ 0.758365] xen:xen_evtchn: Event-channel device installed
[ 0.760419] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[ 0.760819] pcifront pci-0: Installing PCI frontend
[ 0.761518] pcifront pci-0: Creating PCI Frontend Bus 0000:00
[ 0.761684] pcifront pci-0: PCI host bridge to bus 0000:00
[ 0.761710] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
[ 0.761733] pci_bus 0000:00: root bus resource [mem 0x00000000-0xffffffffffff]
[ 0.761763] pci_bus 0000:00: root bus resource [bus 00-ff]
[ 0.761783] pci_bus 0000:00: scanning bus
[ 0.761805] pcifront pci-0: read dev=0000:00:00.0 - offset 0 size 4
[ 0.767207] Linux agpgart interface v0.103
[ 0.767362] Hangcheck: starting hangcheck timer 0.9.1 (tick is 180 seconds, margin is 60 seconds).
[ 0.767439] [drm] Initialized drm 1.1.0 20060810
[ 0.767515] [drm] radeon kernel modesetting enabled.
[ 0.766948] pcifront pci-0: pciback not responding!!! irq:31 irq_flags:ffff880019ec0028 ns: 1431641983026498000 ns_timeout: 1431641983026497000 evtchn:0 gnt_ref:0
[ 0.766948] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
[ 0.766948] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
[ 0.766948] pcifront pci-0: other err read got back err: ffffffff value: 0
[ 2.762062] pcifront pci-0: read dev=0000:00:01.0 - offset 0 size 4
[ 2.765203] pcifront pci-0: pciback not responding!!! irq:31 irq_flags:ffff880019ec0028 ns: 1431641985026742000 ns_timeout: 1431641985026741000 evtchn:0 gnt_ref:0
[ 2.765203] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
[ 2.765203] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
[ 2.765203] pcifront pci-0: other err read got back err: ffffffff value: 0
[ 4.762172] pcifront pci-0: read dev=0000:00:02.0 - offset 0 size 4
[ 4.764231] brd: module loaded
[ 4.765508] loop: module loaded
[ 4.766748] pcifront pci-0: pciback not responding!!! irq:31 irq_flags:ffff880019ec0028 ns: 1431641987026850000 ns_timeout: 1431641987026849000 evtchn:0 gnt_ref:0
[ 4.766748] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
[ 4.766748] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
[ 4.766748] pcifront pci-0: other err read got back err: ffffffff value: 0
[ 6.762248] pcifront pci-0: read dev=0000:00:03.0 - offset 0 size 4
[ 6.765545] pcifront pci-0: pciback not responding!!! irq:31 irq_flags:ffff880019ec0028 ns: 1431641989026930000 ns_timeout: 1431641989026929000 evtchn:0 gnt_ref:0
[ 6.765545] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
[ 6.765545] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
[ 6.765545] pcifront pci-0: other err read got back err: ffffffff value: 0
[ 8.762329] pcifront pci-0: read dev=0000:00:04.0 - offset 0 size 4
[ 8.765626] pcifront pci-0: pciback not responding!!! irq:31 irq_flags:ffff880019ec0028 ns: 1431641991027006000 ns_timeout: 1431641991027005000 evtchn:0 gnt_ref:0
[ 8.765626] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
[ 8.765626] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
[ 8.765626] pcifront pci-0: other err read got back err: ffffffff value: 0
[ 10.762410] pcifront pci-0: read dev=0000:00:05.0 - offset 0 size 4
[ 10.765701] pcifront pci-0: pciback not responding!!! irq:31 irq_flags:ffff880019ec0028 ns: 1431641993027087000 ns_timeout: 1431641993027086000 evtchn:0 gnt_ref:0
[ 10.765701] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
[ 10.765701] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
[ 10.765701] pcifront pci-0: other err read got back err: ffffffff value: 0
[ 12.762472] pcifront pci-0: read dev=0000:00:06.0 - offset 0 size 4

So somehow in the non-working situation, pdev->evtchn and pdev->gnt_ref are 0 in
xen-pcifront.c:do_pci_op(), so no wonder it's not getting a response back ...

Question is .. why ?

--
Sander

2015-05-14 22:47:35

by Sander Eikelenboom

[permalink] [raw]

Subject: Re: Regression due to "device property: Make it possible to use secondary firmware nodes" Re: Xen-unstable + linux 4.1-mergewindow: problems with PV guest pci passthrough: pcifront pci-0: pciback not responding!!!

Sorry for the resend, i messed up the to's en from's.

Hi Konrad / David,

One big snip on this thread, got some more debug info, hopefully this will
lead to something:

On a working kernel (with the two seemingly non related patches reverted) i get:

[ 0.717796] pcifront pci-0: Allocated pdev @ 0xffff880019e11780 pdev->sh_info @ 0xffff880018f58000
[ 0.717848] pcifront pci-0: ?!?!? before alloc gntref: 0
[ 0.717871] pcifront pci-0: ?!?!? after alloc gntref: 8
[ 0.717892] pcifront pci-0: ?!?!? before alloc evtchn: -1
[ 0.717915] pcifront pci-0: ?!?!? after alloc evtchn: 17
[ 0.717984] pcifront pci-0: ?!?!? bound evtchn:17 to irqhandler:-1 err:31
[ 0.721640] pcifront pci-0: publishing successful!
[ 0.723684] usbcore: registered new interface driver udlfb
[ 0.724664] xen:xen_evtchn: Event-channel device installed
[ 0.726597] pcifront pci-0: Installing PCI frontend
[ 0.726853] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[ 0.727059] pcifront pci-0: Creating PCI Frontend Bus 0000:00
[ 0.727363] pcifront pci-0: PCI host bridge to bus 0000:00
[ 0.727391] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
[ 0.727417] pci_bus 0000:00: root bus resource [mem 0x00000000-0xffffffffffff]
[ 0.727452] pci_bus 0000:00: root bus resource [bus 00-ff]
[ 0.727475] pci_bus 0000:00: scanning bus
[ 0.727503] pcifront pci-0: read dev=0000:00:00.0 - offset 0 size 4
[ 0.728253] Linux agpgart interface v0.103
[ 0.728387] Hangcheck: starting hangcheck timer 0.9.1 (tick is 180 seconds, margin is 60 seconds).
[ 0.728474] [drm] Initialized drm 1.1.0 20060810
[ 0.728551] [drm] radeon kernel modesetting enabled.
[ 0.730319] pcifront pci-0: ?!?!? pciback responded !!! irq:31 irq_flags:ffff880019e100a8 ns: 1431641785551700000 ns_timeout: 1431641787541235000 evtchn:17 gnt_ref:8
[ 0.730319] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
[ 0.730319] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
[ 0.730319] pcifront pci-0: read got back value 11113f6
[ 0.738845] pcifront pci-0: read dev=0000:00:00.0 - offset e size 1
[ 0.744976] brd: module loaded
[ 0.745204] pcifront pci-0: ?!?!? pciback responded !!! irq:31 irq_flags:ffff880019e100a8 ns: 1431641785562852000 ns_timeout: 1431641787552580000 evtchn:17 gnt_ref:8
[ 0.745204] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:14 size:1
[ 0.745204] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:14 size:1
[ 0.745204] pcifront pci-0: read got back value 0
[ 0.749204] pcifront pci-0: read dev=0000:00:00.0 - offset 6 size 2
[ 0.750155] loop: module loaded
[ 0.752527] pcifront pci-0: ?!?!? pciback responded !!! irq:31 irq_flags:ffff880019e100a8 ns: 1431641785570841000 ns_timeout: 1431641787562917000 evtchn:17 gnt_ref:8
[ 0.752527] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:6 size:2
[ 0.752527] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:6 size:2
[ 0.752527] pcifront pci-0: read got back value 210
[ 0.757187] pcifront pci-0: read dev=0000:00:00.0 - offset 34 size 1

Were as in the non-working situation i get:

[ 0.751244] pcifront pci-0: Allocated pdev @ 0xffff880019ec2e00 pdev->sh_info @ 0xffff88001aa51000
[ 0.751295] pcifront pci-0: ?!?!? before alloc gntref: 0
[ 0.751315] pcifront pci-0: ?!?!? after alloc gntref: 8
[ 0.751334] pcifront pci-0: ?!?!? before alloc evtchn: -1
[ 0.751355] pcifront pci-0: ?!?!? after alloc evtchn: 17
[ 0.751422] pcifront pci-0: ?!?!? bound evtchn:17 to irqhandler:-1 err:31
[ 0.755215] pcifront pci-0: publishing successful!
[ 0.757341] usbcore: registered new interface driver udlfb
[ 0.758365] xen:xen_evtchn: Event-channel device installed
[ 0.760419] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[ 0.760819] pcifront pci-0: Installing PCI frontend
[ 0.761518] pcifront pci-0: Creating PCI Frontend Bus 0000:00
[ 0.761684] pcifront pci-0: PCI host bridge to bus 0000:00
[ 0.761710] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
[ 0.761733] pci_bus 0000:00: root bus resource [mem 0x00000000-0xffffffffffff]
[ 0.761763] pci_bus 0000:00: root bus resource [bus 00-ff]
[ 0.761783] pci_bus 0000:00: scanning bus
[ 0.761805] pcifront pci-0: read dev=0000:00:00.0 - offset 0 size 4
[ 0.767207] Linux agpgart interface v0.103
[ 0.767362] Hangcheck: starting hangcheck timer 0.9.1 (tick is 180 seconds, margin is 60 seconds).
[ 0.767439] [drm] Initialized drm 1.1.0 20060810
[ 0.767515] [drm] radeon kernel modesetting enabled.
[ 0.766948] pcifront pci-0: pciback not responding!!! irq:31 irq_flags:ffff880019ec0028 ns: 1431641983026498000 ns_timeout: 1431641983026497000 evtchn:0 gnt_ref:0
[ 0.766948] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
[ 0.766948] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
[ 0.766948] pcifront pci-0: other err read got back err: ffffffff value: 0
[ 2.762062] pcifront pci-0: read dev=0000:00:01.0 - offset 0 size 4
[ 2.765203] pcifront pci-0: pciback not responding!!! irq:31 irq_flags:ffff880019ec0028 ns: 1431641985026742000 ns_timeout: 1431641985026741000 evtchn:0 gnt_ref:0
[ 2.765203] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
[ 2.765203] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
[ 2.765203] pcifront pci-0: other err read got back err: ffffffff value: 0
[ 4.762172] pcifront pci-0: read dev=0000:00:02.0 - offset 0 size 4
[ 4.764231] brd: module loaded
[ 4.765508] loop: module loaded
[ 4.766748] pcifront pci-0: pciback not responding!!! irq:31 irq_flags:ffff880019ec0028 ns: 1431641987026850000 ns_timeout: 1431641987026849000 evtchn:0 gnt_ref:0
[ 4.766748] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
[ 4.766748] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
[ 4.766748] pcifront pci-0: other err read got back err: ffffffff value: 0
[ 6.762248] pcifront pci-0: read dev=0000:00:03.0 - offset 0 size 4
[ 6.765545] pcifront pci-0: pciback not responding!!! irq:31 irq_flags:ffff880019ec0028 ns: 1431641989026930000 ns_timeout: 1431641989026929000 evtchn:0 gnt_ref:0
[ 6.765545] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
[ 6.765545] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
[ 6.765545] pcifront pci-0: other err read got back err: ffffffff value: 0
[ 8.762329] pcifront pci-0: read dev=0000:00:04.0 - offset 0 size 4
[ 8.765626] pcifront pci-0: pciback not responding!!! irq:31 irq_flags:ffff880019ec0028 ns: 1431641991027006000 ns_timeout: 1431641991027005000 evtchn:0 gnt_ref:0
[ 8.765626] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
[ 8.765626] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
[ 8.765626] pcifront pci-0: other err read got back err: ffffffff value: 0
[ 10.762410] pcifront pci-0: read dev=0000:00:05.0 - offset 0 size 4
[ 10.765701] pcifront pci-0: pciback not responding!!! irq:31 irq_flags:ffff880019ec0028 ns: 1431641993027087000 ns_timeout: 1431641993027086000 evtchn:0 gnt_ref:0
[ 10.765701] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
[ 10.765701] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
[ 10.765701] pcifront pci-0: other err read got back err: ffffffff value: 0
[ 12.762472] pcifront pci-0: read dev=0000:00:06.0 - offset 0 size 4

So somehow in the non-working situation, pdev->evtchn and pdev->gnt_ref are 0 in
xen-pcifront.c:do_pci_op(), so no wonder it's not getting a response back ...

Question is .. why ?

--
Sander

2015-05-22 08:11:23

by Sander Eikelenboom

[permalink] [raw]

Subject: Re: Regression due to "device property: Make it possible to use secondary firmware nodes" Re: Xen-unstable + linux 4.1-mergewindow: problems with PV guest pci passthrough: pcifront pci-0: pciback not responding!!!

Hello Sander,

Friday, May 15, 2015, 12:47:27 AM, you wrote:

> Sorry for the resend, i messed up the to's en from's.

> Hi Konrad / David,

> One big snip on this thread, got some more debug info, hopefully this will
> lead to something:

> On a working kernel (with the two seemingly non related patches reverted) i get:

> [ 0.717796] pcifront pci-0: Allocated pdev @ 0xffff880019e11780 pdev->sh_info @ 0xffff880018f58000
> [ 0.717848] pcifront pci-0: ?!?!? before alloc gntref: 0
> [ 0.717871] pcifront pci-0: ?!?!? after alloc gntref: 8
> [ 0.717892] pcifront pci-0: ?!?!? before alloc evtchn: -1
> [ 0.717915] pcifront pci-0: ?!?!? after alloc evtchn: 17
> [ 0.717984] pcifront pci-0: ?!?!? bound evtchn:17 to irqhandler:-1 err:31
> [ 0.721640] pcifront pci-0: publishing successful!
> [ 0.723684] usbcore: registered new interface driver udlfb
> [ 0.724664] xen:xen_evtchn: Event-channel device installed
> [ 0.726597] pcifront pci-0: Installing PCI frontend
> [ 0.726853] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
> [ 0.727059] pcifront pci-0: Creating PCI Frontend Bus 0000:00
> [ 0.727363] pcifront pci-0: PCI host bridge to bus 0000:00
> [ 0.727391] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
> [ 0.727417] pci_bus 0000:00: root bus resource [mem 0x00000000-0xffffffffffff]
> [ 0.727452] pci_bus 0000:00: root bus resource [bus 00-ff]
> [ 0.727475] pci_bus 0000:00: scanning bus
> [ 0.727503] pcifront pci-0: read dev=0000:00:00.0 - offset 0 size 4
> [ 0.728253] Linux agpgart interface v0.103
> [ 0.728387] Hangcheck: starting hangcheck timer 0.9.1 (tick is 180 seconds, margin is 60 seconds).
> [ 0.728474] [drm] Initialized drm 1.1.0 20060810
> [ 0.728551] [drm] radeon kernel modesetting enabled.
> [ 0.730319] pcifront pci-0: ?!?!? pciback responded !!! irq:31 irq_flags:ffff880019e100a8 ns: 1431641785551700000 ns_timeout: 1431641787541235000 evtchn:17 gnt_ref:8
> [ 0.730319] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
> [ 0.730319] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
> [ 0.730319] pcifront pci-0: read got back value 11113f6
> [ 0.738845] pcifront pci-0: read dev=0000:00:00.0 - offset e size 1
> [ 0.744976] brd: module loaded
> [ 0.745204] pcifront pci-0: ?!?!? pciback responded !!! irq:31 irq_flags:ffff880019e100a8 ns: 1431641785562852000 ns_timeout: 1431641787552580000 evtchn:17 gnt_ref:8
> [ 0.745204] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:14 size:1
> [ 0.745204] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:14 size:1
> [ 0.745204] pcifront pci-0: read got back value 0
> [ 0.749204] pcifront pci-0: read dev=0000:00:00.0 - offset 6 size 2
> [ 0.750155] loop: module loaded
> [ 0.752527] pcifront pci-0: ?!?!? pciback responded !!! irq:31 irq_flags:ffff880019e100a8 ns: 1431641785570841000 ns_timeout: 1431641787562917000 evtchn:17 gnt_ref:8
> [ 0.752527] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:6 size:2
> [ 0.752527] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:6 size:2
> [ 0.752527] pcifront pci-0: read got back value 210
> [ 0.757187] pcifront pci-0: read dev=0000:00:00.0 - offset 34 size 1

> Were as in the non-working situation i get:

> [ 0.751244] pcifront pci-0: Allocated pdev @ 0xffff880019ec2e00 pdev->sh_info @ 0xffff88001aa51000
> [ 0.751295] pcifront pci-0: ?!?!? before alloc gntref: 0
> [ 0.751315] pcifront pci-0: ?!?!? after alloc gntref: 8
> [ 0.751334] pcifront pci-0: ?!?!? before alloc evtchn: -1
> [ 0.751355] pcifront pci-0: ?!?!? after alloc evtchn: 17
> [ 0.751422] pcifront pci-0: ?!?!? bound evtchn:17 to irqhandler:-1 err:31
> [ 0.755215] pcifront pci-0: publishing successful!
> [ 0.757341] usbcore: registered new interface driver udlfb
> [ 0.758365] xen:xen_evtchn: Event-channel device installed
> [ 0.760419] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
> [ 0.760819] pcifront pci-0: Installing PCI frontend
> [ 0.761518] pcifront pci-0: Creating PCI Frontend Bus 0000:00
> [ 0.761684] pcifront pci-0: PCI host bridge to bus 0000:00
> [ 0.761710] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
> [ 0.761733] pci_bus 0000:00: root bus resource [mem 0x00000000-0xffffffffffff]
> [ 0.761763] pci_bus 0000:00: root bus resource [bus 00-ff]
> [ 0.761783] pci_bus 0000:00: scanning bus
> [ 0.761805] pcifront pci-0: read dev=0000:00:00.0 - offset 0 size 4
> [ 0.767207] Linux agpgart interface v0.103
> [ 0.767362] Hangcheck: starting hangcheck timer 0.9.1 (tick is 180 seconds, margin is 60 seconds).
> [ 0.767439] [drm] Initialized drm 1.1.0 20060810
> [ 0.767515] [drm] radeon kernel modesetting enabled.
> [ 0.766948] pcifront pci-0: pciback not responding!!! irq:31 irq_flags:ffff880019ec0028 ns: 1431641983026498000 ns_timeout: 1431641983026497000 evtchn:0 gnt_ref:0
> [ 0.766948] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
> [ 0.766948] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
> [ 0.766948] pcifront pci-0: other err read got back err: ffffffff value: 0
> [ 2.762062] pcifront pci-0: read dev=0000:00:01.0 - offset 0 size 4
> [ 2.765203] pcifront pci-0: pciback not responding!!! irq:31 irq_flags:ffff880019ec0028 ns: 1431641985026742000 ns_timeout: 1431641985026741000 evtchn:0 gnt_ref:0
> [ 2.765203] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
> [ 2.765203] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
> [ 2.765203] pcifront pci-0: other err read got back err: ffffffff value: 0
> [ 4.762172] pcifront pci-0: read dev=0000:00:02.0 - offset 0 size 4
> [ 4.764231] brd: module loaded
> [ 4.765508] loop: module loaded
> [ 4.766748] pcifront pci-0: pciback not responding!!! irq:31 irq_flags:ffff880019ec0028 ns: 1431641987026850000 ns_timeout: 1431641987026849000 evtchn:0 gnt_ref:0
> [ 4.766748] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
> [ 4.766748] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
> [ 4.766748] pcifront pci-0: other err read got back err: ffffffff value: 0
> [ 6.762248] pcifront pci-0: read dev=0000:00:03.0 - offset 0 size 4
> [ 6.765545] pcifront pci-0: pciback not responding!!! irq:31 irq_flags:ffff880019ec0028 ns: 1431641989026930000 ns_timeout: 1431641989026929000 evtchn:0 gnt_ref:0
> [ 6.765545] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
> [ 6.765545] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
> [ 6.765545] pcifront pci-0: other err read got back err: ffffffff value: 0
> [ 8.762329] pcifront pci-0: read dev=0000:00:04.0 - offset 0 size 4
> [ 8.765626] pcifront pci-0: pciback not responding!!! irq:31 irq_flags:ffff880019ec0028 ns: 1431641991027006000 ns_timeout: 1431641991027005000 evtchn:0 gnt_ref:0
> [ 8.765626] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
> [ 8.765626] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
> [ 8.765626] pcifront pci-0: other err read got back err: ffffffff value: 0
> [ 10.762410] pcifront pci-0: read dev=0000:00:05.0 - offset 0 size 4
> [ 10.765701] pcifront pci-0: pciback not responding!!! irq:31 irq_flags:ffff880019ec0028 ns: 1431641993027087000 ns_timeout: 1431641993027086000 evtchn:0 gnt_ref:0
> [ 10.765701] pcifront pci-0: ?!?!? op cmd:0 err:0 info:0 offset:0 size:4
> [ 10.765701] pcifront pci-0: ?!?!? active_op cmd:0 err:0 info:0 offset:0 size:4
> [ 10.765701] pcifront pci-0: other err read got back err: ffffffff value: 0
> [ 12.762472] pcifront pci-0: read dev=0000:00:06.0 - offset 0 size 4

> So somehow in the non-working situation, pdev->evtchn and pdev->gnt_ref are 0 in
> xen-pcifront.c:do_pci_op(), so no wonder it's not getting a response back ...

> Question is .. why ?

> --
> Sander

Ping ?

David / Boris,

Any idea, since Konrad seems to be off for 2 weeks and we are at rc4 now.

--
Sander