Re: [Xen-devel] [Xen-users] substantial shutdown delay for PV guests with PCI -passthrough

[Atom2 <ariel.atom2@xxxxxxxxxx>]

Am 18.03.14 11:15, schrieb Ian Campbell:
> Adding xen-devel. Full thread starts at
> http://lists.xen.org/archives/html/xen-users/2014-03/msg00102.html
>
> On Mon, 2014-03-17 at 19:13 +0100, Atom2 wrote:
>
> > > Any chance you could try 4.3.2, or even 4.4.0?
> > Unfortunately neither of these versions are currently available as
> > stable ebuilds for my distribution, but I assume it shouldn't be long
> > before there's some movement.
> Looking at the diff to tools/libxl/libxl_pci.c I don't see any pertinent
> looking fixes so it seems probably this issue still exists.
>
> > > > The system is capable of vt-d and uses a Xeon E3-1260L processor.
> > > >
> > > > Do these observations ring a bell with anybody or is this even expected
> > > > behaviour. If this is not normal - which I would expect as I have not
> > > > been able to find any information relating to substantial delays during
> > > > shutdown - how would I go about getting to the grounds of this?
> > > My guess would be that xl process which is managing the domain destroy
> > > is waiting for something (perhaps pciback) to confirm shutdown for each
> > > device and this is timing out in series, leading to the delays. You
> > > might find something in the logs /var/log/xen pointing to something like
> > > this.
> > >
> > > If not then if you start the guest with "xl -vvv create -F <cfg>" then
> > > the xl process which is monitoring the domain will stay in the
> > > foreground and be logging to stdout (I think). If you then issue the
> > > shutdown from another shell perhaps there will be some obvious gaps in
> > > the logs as things shutdown which might help.
> > That worked and there also was some output - please find the log from
> > start to finnish attached to this mail. I have marked various points in
> > the log: First the point where the startup was done and the domU was
> > live and secondly those 4 points in time (or rather output) where the
> > 10s delay occured.
> Quoting the relevant bit for -devel, full log is at
> http://lists.xen.org/archives/html/xen-users/2014-03/txtl6VscE4NMf.txt:
>
>          Domain 3 has shut down, reason code 0 0x0
>          Action for shutdown reason code 0 is destroy
>          Domain 3 needs to be cleaned up: destroying the domain
>          libxl: debug: libxl.c:1252:libxl_domain_destroy: ao 0x7f1dddf2b850: 
> create: how=(nil) callback=(nil) poller=0x7f1dddf2cd70
>          libxl: error: libxl_pci.c:1248:do_pci_remove: xc_domain_irq_permission 
> irq=17
>
>          <NOTE: at this point a 10s pause happens>
>
>          libxl: error: libxl_device.c:1127:libxl__wait_for_backend: Backend 
> /local/domain/0/backend/pci/3/0 not ready
>          libxl: debug: libxl_pci.c:173:libxl__device_pci_remove_xenstore: pci 
> backend at /local/domain/0/backend/pci/3/0 is not ready
>          libxl: error: libxl_pci.c:1248:do_pci_remove: xc_domain_irq_permission 
> irq=16
>
>          <NOTE: at this point a 10s pause happens>
>
>          libxl: error: libxl_device.c:1127:libxl__wait_for_backend: Backend 
> /local/domain/0/backend/pci/3/0 not ready
>          libxl: debug: libxl_pci.c:173:libxl__device_pci_remove_xenstore: pci 
> backend at /local/domain/0/backend/pci/3/0 is not ready
>          [repeat for more devices]
>
> Do you get anything in "xl dmesg" or dom0's "dmesg" corresponding to
> these events?
xl dmesg:
There is no additional output in dom0's 'xl dmesg' after creation of the 
domain with xl create -c
There are however two additional lines in dom0's 'xl dmesg' output after 
I have executed 'shutdown -h now' from the domU's command line following 
a login as follows:
==============
(XEN) irq.c:2028: dom3: forcing unbind of pirq 23
(XEN) tmem: flushing tmem pools for domid=3
==============

dmesg:
Additional output of dmesg  in dom0 after creating the the domain with 
xl create -c is as follows:
==============
[  322.225345] device vif3.0 entered promiscuous mode
[  322.828304] xen_pciback: vpci: 0000:03:00.0: assign to virtual slot 0
[  322.829486] xen_pciback: vpci: 0000:06:00.0: assign to virtual slot 1
[  322.840174] xen_pciback: vpci: 0000:09:02.0: assign to virtual slot 2
[  322.841134] xen_pciback: vpci: 0000:00:1d.0: assign to virtual slot 3
[  322.937946] xen-blkback:ring-ref 2047, event-channel 4, protocol 1 
(x86_64-abi)
[  322.947106] xen-blkback:ring-ref 2046, event-channel 5, protocol 1 
(x86_64-abi)
[  322.955840] xen-blkback:ring-ref 2045, event-channel 6, protocol 1 
(x86_64-abi)
[  327.171287] xen-blkback:backend/vbd/3/51713: prepare for reconnect
[  327.194441] xen-blkback:backend/vbd/3/51714: prepare for reconnect
[  327.198687] xen-blkback:backend/vbd/3/51715: prepare for reconnect
[  327.925926] pciback 0000:00:1d.0: enabling device (0000 -> 0002)
[  327.926053] xen: registering gsi 23 triggering 0 polarity 1
[  327.926059] Already setup the GSI :23
[  327.926219] pciback 0000:00:1d.0: Driver tried to write to a 
read-only configuration space field at offset 0x6c, size 4. This may
 be harmless, but if you have problems with your device:
1) see permissive attribute in sysfs
2) report problems to the xen-devel mailing list along with details of 
your device obtained from lspci.
[  327.932217] xen-blkback:ring-ref 9, event-channel 18, protocol 1 
(x86_64-abi) persistent grants
[  327.938142] xen-blkback:ring-ref 10, event-channel 19, protocol 1 
(x86_64-abi) persistent grants
[  327.943674] xen-blkback:ring-ref 11, event-channel 20, protocol 1 
(x86_64-abi) persistent grants
[  328.965061] xenbr0: port 4(vif3.0) entered forwarding state
[  328.965067] xenbr0: port 4(vif3.0) entered forwarding state
[  330.716771] pciback 0000:00:1d.0: setting latency timer to 64
[  335.728218] pciback 0000:06:00.0: enabling device (0000 -> 0002)
[  335.728286] xen: registering gsi 16 triggering 0 polarity 1
[  335.728290] Already setup the GSI :16
[  343.992293] xenbr0: port 4(vif3.0) entered forwarding state
==============
FYI: The 0000:00:1d.0 device is the USB host controller being passed 
through (Intel Sandybridge, C206 chipset); output of lspci:
00:1d.0 USB controller: Intel Corporation 6 Series/C200 Series Chipset 
Family USB Enhanced Host Controller #1 (rev 05)
Howvere currently there seems to be no issue with the USB host 
controller in domU: There are two USB bluetooth dongles attached and 
they do work (they connect to mobile phones). I'm more than happy to 
provide more info should this be required.
Further output of dmesg in dom0 after I have executed 'shutdown -h now' 
from the domU's command line following a login is follows:
==============
[  556.864398] xenbr0: port 4(vif3.0) entered disabled state
[  597.584588] xenbr0: port 4(vif3.0) entered disabled state
[  597.584663] device vif3.0 left promiscuous mode
[  597.584668] xenbr0: port 4(vif3.0) entered disabled state
==============

So I guess probably not too much of value ...

> Looking at do_pci_remove after the call to xc_domain_irq_permission
> (which fails, but I don't think that relates to the delay) we then call
> (conditionally) libxl__device_pci_reset, xc_deassign_device,
> libxl__device_pci_remove_common and libxl__device_pci_remove_xenstore,
> with no logging to indicate which we are calling (not helpful!).
>
> The "is not ready" message comes from libxl__device_pci_remove_xenstore
> which calls libxl__wait_for_backend. The latter has been rewritten a bit
> since 4.3.1 but not in a way which I think would affect this case.
> libxl__wait_for_backend does have a usleep(10000) in it -- which is
> certainly the source of the delay, but I'd like to explain how we got to
> waiting like that anyway (IanJ: do you have PCI on your hitlist for
> asyncing up?)
>
> This thing about pciback not being ready rings a bell. I've cc'd a few
> folks who I think might remember more.
>
> While the domain is happily running can you provide the output of
> "xenstore-ls -fp" -- I'm curious what state pciback is in. It should be
> 4, if not then that would be the problem.
Full output of xenstore-ls -fp (from dom0) is attached as it is 627 
lines long and I am not quiet sure what you are actually after): There's 
nothing in it that reads pciback; there are however a few entries named
        /local/domain/0/backend/pci
and for one of the subentries named 3/0/state (3 is the domain-id)
the value seems to be 4:
        /local/domain/0/backend/pci/3/0/state = "4"   (n0,r3)
But then there is also another entry further down named
        /local/domain/3/device/pci/0/state = "4"   (n3,r0)
But I am speculating here and I guess it's better to leave the 
interpretation to your expertise ...
> > BTW: I don't know whether it makes any difference, but I am only using
> > xen-pciback.hide=(bb:dd.f)(...) on the grub command line for a number of
> > devices including those that I pass through to this domU - there's
> > nothing else happening in the dom0 with those devices priot to starting
> > the domU and there are also no driver modules available for any of the
> > hidden hardware (except for one of the hidden USB Controllers of the
> > motherboard which is also passed through) in dom0.
> I don't think that should matter here.
>
> Ian.

Attachment: xenstore
Description: Text document

_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxx
http://lists.xen.org/xen-devel