Hi,
Just to notify you all, i have tested the same scenario, on the latest
xen-unstable, and i got the same result - the machine hangs. It looks
like a major bug.
Can someone please help me with this?
Tom
---------- Forwarded message ----------
From: Tom Rotenberg <tom.rotenberg@xxxxxxxxx>
Date: Wed, Jul 22, 2009 at 12:17 PM
Subject: Machine hangs when doing pass-through of all the USB devices
on a Lenovo T400
To: Simon Horman <horms@xxxxxxxxxxxx>, xen-devel@xxxxxxxxxxxxxxxxxxx
Hi,
First, i must say that i have seen this bug on Simon's Xen 3.4
multi-function pass-through tree, but i think that this problem isn't
specific for Xen 3.4, but a major problem which will happen on
xen-unstable too.
(I'm using Lenovo T400 for my tests)
What i did:
1. Used Simon's Xen 3.4 multi-function pass-through tree
2. Did pass-through for all the USB devices in the system, using the command:
xm create /etc/xen/hvm pci='00:1a.*' pci='00:1d.*'
3. After this, the guest Windows booted ok, but a little bit after
this, the whole machine got stuck (including dom0), and the errors in
the UART were:
[ 287.624198] ACPI: EC: missing write data confirmation, don't expect
it any longer.
[ 293.748242] ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
[ 293.748353] ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
[ 293.748354] cdb 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 293.748354] res 40/00:03:00:00:00/00:00:00:00:00/a0 Emask
0x4 (timeout)
[ 293.748658] ata2.00: status: { DRDY }
which looks like the SATA in dom0 is dead...
I suspect that this is because of some problem in the
interrupts-sharing between the USB device which is in pass-through to
the HVM, and between the SATA in dom0 (they share the same interrupt).
I have also made a test, which i pass-through only the '00:1a.*'
devices, and saw that doesn't happen (probably, because the interrupt
isn't shared). You can see in the logs that follow that interrupt 17
is shared between the AHCI (the HD), and one of the USB devices.
Could it be that there is problem when doing interrupt sharing between
PT device in a domU, and between a device in dom0? Will this happen
without the multi-function PT too?
Any ideas?
-----------
Logs:
----------
_______________________________________________
The interrupts of the machine (as reported by dom0):
_______________________________________________
t500-testing:~# cat /proc/interrupts
CPU0 CPU1
1: 8 0 Phys-irq-level i8042
3: 1 0 Phys-irq-level
5: 1 0 Phys-irq-level
7: 1 0 Phys-irq-level parport0
8: 0 0 Phys-irq-level rtc
9: 333 0 Phys-irq-level acpi
10: 1 0 Phys-irq-level
11: 1 0 Phys-irq-level
12: 2332 0 Phys-irq-level i8042
16: 2718 0 Phys-irq-level uhci_hcd:usb4, ahci, yenta
17: 93 0 Phys-irq-level uhci_hcd:usb5,
ohci1394, HDA Intel
18: 35 0 Phys-irq-level uhci_hcd:usb6, sdhci:slot0
19: 2 0 Phys-irq-level ehci_hcd:usb8
20: 249 0 Phys-irq-level uhci_hcd:usb1, peth0
21: 54 0 Phys-irq-level uhci_hcd:usb2
22: 0 0 Phys-irq-level uhci_hcd:usb3
23: 26 0 Phys-irq-level ehci_hcd:usb7
256: 13683 0 Dynamic-irq-level timer0
257: 1180 0 Dynamic-irq-level resched0
258: 27 0 Dynamic-irq-level callfunc0
259: 0 2027 Dynamic-irq-level resched1
260: 0 64 Dynamic-irq-level callfunc1
261: 0 13348 Dynamic-irq-level timer1
262: 77 0 Dynamic-irq-level xenbus
263: 0 0 Dynamic-irq-level console
NMI: 0 0 Non-maskable interrupts
RES: 1180 2027 Rescheduling interrupts
CAL: 27 64 function call interrupts
_______________________________________________
Full UART Log (from the relevant part):
_______________________________________________
[ 28.652292] Setting mem allocation to 1913836 kiB
[ 214.320871] uhci_hcd 0000:00:1a.0: remove, state 4
[ 214.320983] usb usb1: USB disconnect, address 1
[ 214.322560] uhci_hcd 0000:00:1a.0: USB bus 1 deregistered
[ 214.322694] ACPI: PCI interrupt for device 0000:00:1a.0 disabled
[ 214.608987] pciback 0000:00:1a.0: seizing device
[ 214.609184] ACPI: PCI Interrupt 0000:00:1a.0[A] -> GSI 20 (level,
low) -> IRQ 20
[ 214.609364] ACPI: PCI interrupt for device 0000:00:1a.0 disabled
[ 214.334168] uhci_hcd 0000:00:1a.1: remove, state 1
[ 214.334270] usb usb2: USB disconnect, address 1
[ 214.334362] usb 2-1: USB disconnect, address 3
[ 214.334803] uhci_hcd 0000:00:1a.1: USB bus 2 deregistered
[ 214.334971] ACPI: PCI interrupt for device 0000:00:1a.1 disabled
[ 214.621835] pciback 0000:00:1a.1: seizing device
[ 214.622056] ACPI: PCI Interrupt 0000:00:1a.1[B] -> GSI 21 (level,
low) -> IRQ 21
[ 214.622258] ACPI: PCI interrupt for device 0000:00:1a.1 disabled
[ 214.627337] uhci_hcd 0000:00:1a.2: remove, state 4
[ 214.627545] usb usb3: USB disconnect, address 1
[ 214.627932] uhci_hcd 0000:00:1a.2: USB bus 3 deregistered
[ 214.628152] ACPI: PCI interrupt for device 0000:00:1a.2 disabled
[ 214.635694] pciback 0000:00:1a.2: seizing device
[ 214.636000] ACPI: PCI Interrupt 0000:00:1a.2[C] -> GSI 22 (level,
low) -> IRQ 22
[ 214.636186] ACPI: PCI interrupt for device 0000:00:1a.2 disabled
[ 214.360823] ehci_hcd 0000:00:1a.7: remove, state 4
[ 214.360925] usb usb7: USB disconnect, address 1
[ 214.361017] usb 7-5: USB disconnect, address 3
[ 214.365340] ehci_hcd 0000:00:1a.7: USB bus 7 deregistered
[ 214.365506] ACPI: PCI interrupt for device 0000:00:1a.7 disabled
[ 214.371946] pciback 0000:00:1a.7: seizing device
[ 214.372390] ACPI: PCI Interrupt 0000:00:1a.7[D] -> GSI 23 (level,
low) -> IRQ 23
[ 214.372583] ACPI: PCI interrupt for device 0000:00:1a.7 disabled
[ 214.376078] uhci_hcd 0000:00:1d.0: remove, state 4
[ 214.376303] usb usb4: USB disconnect, address 1
[ 214.376742] uhci_hcd 0000:00:1d.0: USB bus 4 deregistered
[ 214.376938] ACPI: PCI interrupt for device 0000:00:1d.0 disabled
[ 214.383475] pciback 0000:00:1d.0: seizing device
[ 214.383786] ACPI: PCI Interrupt 0000:00:1d.0[A] -> GSI 16 (level,
low) -> IRQ 16
[ 214.383978] ACPI: PCI interrupt for device 0000:00:1d.0 disabled
[ 214.387654] uhci_hcd 0000:00:1d.1: remove, state 4
[ 214.387857] usb usb5: USB disconnect, address 1
[ 214.388220] uhci_hcd 0000:00:1d.1: USB bus 5 deregistered
[ 214.388417] ACPI: PCI interrupt for device 0000:00:1d.1 disabled
[ 214.394899] pciback 0000:00:1d.1: seizing device
[ 214.395212] ACPI: PCI Interrupt 0000:00:1d.1[B] -> GSI 17 (level,
low) -> IRQ 17
[ 214.395398] ACPI: PCI interrupt for device 0000:00:1d.1 disabled
[ 214.677786] uhci_hcd 0000:00:1d.2: remove, state 1
[ 214.677890] usb usb6: USB disconnect, address 1
[ 214.677982] usb 6-2: USB disconnect, address 2
[ 214.678444] uhci_hcd 0000:00:1d.2: USB bus 6 deregistered
[ 214.678574] ACPI: PCI interrupt for device 0000:00:1d.2 disabled
[ 214.406336] pciback 0000:00:1d.2: seizing device
[ 214.406537] ACPI: PCI Interrupt 0000:00:1d.2[C] -> GSI 18 (level,
low) -> IRQ 18
[ 214.406725] ACPI: PCI interrupt for device 0000:00:1d.2 disabled
[ 214.410481] ehci_hcd 0000:00:1d.7: remove, state 4
[ 214.410691] usb usb8: USB disconnect, address 1
[ 214.414959] ehci_hcd 0000:00:1d.7: USB bus 8 deregistered
[ 214.415200] ACPI: PCI interrupt for device 0000:00:1d.7 disabled
[ 214.421670] pciback 0000:00:1d.7: seizing device
[ 214.422214] ACPI: PCI Interrupt 0000:00:1d.7[D] -> GSI 19 (level,
low) -> IRQ 19
[ 214.422407] ACPI: PCI interrupt for device 0000:00:1d.7 disabled
[ 231.366540] Setting mem allocation to 973824 kiB
(XEN) memory.c:128:d0 Could not allocate order=9 extent: id=1
memflags=0 (2 of 4)
(XEN) memory.c:128:d0 Could not allocate order=9 extent: id=1
memflags=0 (0 of 3)
[ 232.398469] pciback: vpci: 0000:00:1a.7: assign to virtual slot 0
[ 232.398776] pciback: vpci: 0000:00:1a.2: assign to virtual slot 0 func 2
[ 232.398973] pciback: vpci: 0000:00:1a.1: assign to virtual slot 0 func 1
[ 232.399171] pciback: vpci: 0000:00:1a.0: assign to virtual slot 0 func 0
[ 232.399318] pciback: vpci: 0000:00:1d.7: assign to virtual slot 1
[ 232.399509] pciback: vpci: 0000:00:1d.2: assign to virtual slot 1 func 2
[ 232.399717] pciback: vpci: 0000:00:1d.1: assign to virtual slot 1 func 1
[ 232.399946] pciback: vpci: 0000:00:1d.0: assign to virtual slot 1 func 0
(XEN) [VT-D]iommu.c:1364:d0 domain_context_unmap:PCI: bdf = 0:1a.0
(XEN) [VT-D]iommu.c:1252:d0 domain_context_mapping:PCI: bdf = 0:1a.0
(XEN) [VT-D]io.c:251:d0 VT-d irq bind: m_irq = 14 device = 1a intx = 0
(XEN) [VT-D]iommu.c:1364:d0 domain_context_unmap:PCI: bdf = 0:1a.7
(XEN) [VT-D]iommu.c:1252:d0 domain_context_mapping:PCI: bdf = 0:1a.7
(XEN) [VT-D]io.c:251:d0 VT-d irq bind: m_irq = 17 device = 1a intx = 3
(XEN) [VT-D]iommu.c:1364:d0 domain_context_unmap:PCI: bdf = 0:1a.2
(XEN) [VT-D]iommu.c:1252:d0 domain_context_mapping:PCI: bdf = 0:1a.2
(XEN) [VT-D]io.c:251:d0 VT-d irq bind: m_irq = 16 device = 1a intx = 2
(XEN) [VT-D]iommu.c:1364:d0 domain_context_unmap:PCI: bdf = 0:1a.1
(XEN) [VT-D]iommu.c:1252:d0 domain_context_mapping:PCI: bdf = 0:1a.1
(XEN) [VT-D]io.c:251:d0 VT-d irq bind: m_irq = 15 device = 1a intx = 1
(XEN) [VT-D]iommu.c:1364:d0 domain_context_unmap:PCI: bdf = 0:1d.0
(XEN) [VT-D]iommu.c:1252:d0 domain_context_mapping:PCI: bdf = 0:1d.0
(XEN) [VT-D]io.c:251:d0 VT-d irq bind: m_irq = 10 device = 1d intx = 0
(XEN) [VT-D]iommu.c:1364:d0 domain_context_unmap:PCI: bdf = 0:1d.7
(XEN) [VT-D]iommu.c:1252:d0 domain_context_mapping:PCI: bdf = 0:1d.7
(XEN) [VT-D]io.c:251:d0 VT-d irq bind: m_irq = 13 device = 1d intx = 3
(XEN) [VT-D]iommu.c:1364:d0 domain_context_unmap:PCI: bdf = 0:1d.2
(XEN) [VT-D]iommu.c:1252:d0 domain_context_mapping:PCI: bdf = 0:1d.2
(XEN) [VT-D]io.c:251:d0 VT-d irq bind: m_irq = 12 device = 1d intx = 2
(XEN) [VT-D]iommu.c:1364:d0 domain_context_unmap:PCI: bdf = 0:1d.1
(XEN) [VT-D]iommu.c:1252:d0 domain_context_mapping:PCI: bdf = 0:1d.1
(XEN) [VT-D]io.c:251:d0 VT-d irq bind: m_irq = 11 device = 1d intx = 1
(XEN) HVM1: HVM Loader
(XEN) HVM1: Detected Xen v3.4.1-rc7
(XEN) HVM1: CPU speed is 2394 MHz
(XEN) irq.c:243: Dom1 PCI link 0 changed 0 -> 5
(XEN) HVM1: PCI-ISA link 0 routed to IRQ5
(XEN) irq.c:243: Dom1 PCI link 1 changed 0 -> 10
(XEN) HVM1: PCI-ISA link 1 routed to IRQ10
(XEN) irq.c:243: Dom1 PCI link 2 changed 0 -> 11
(XEN) HVM1: PCI-ISA link 2 routed to IRQ11
(XEN) irq.c:243: Dom1 PCI link 3 changed 0 -> 5
(XEN) HVM1: PCI-ISA link 3 routed to IRQ5
(XEN) HVM1: pci dev 01:3 INTA->IRQ10
(XEN) HVM1: pci dev 03:0 INTA->IRQ5
(XEN) HVM1: pci dev 02:0 bar 10 size 02000000: f0000008
(XEN) HVM1: pci dev 03:0 bar 14 size 01000000: f2000008
(XEN) HVM1: pci dev 02:0 bar 14 size 00001000: f3000000
(XEN) HVM1: pci dev 03:0 bar 10 size 00000100: 0000c001
(XEN) HVM1: pci dev 01:1 bar 20 size 00000010: 0000c101
(XEN) HVM1: Multiprocessor initialisation:
(XEN) HVM1: - CPU0 ... 36-bit phys ... fixed MTRRs ... var MTRRs
[2/8] ... done.
(XEN) HVM1: Writing SMBIOS tables ...
(XEN) HVM1: Loading ROMBIOS ...
(XEN) HVM1: 10940 bytes of ROMBIOS high-memory extensions:
(XEN) HVM1: Relocating to 0xfc000000-0xfc002abc ... done
(XEN) HVM1: Creating MP tables ...
(XEN) HVM1: Loading Cirrus VGABIOS ...
(XEN) HVM1: Loading ACPI ...
(XEN) HVM1: - Lo data: 000ea020-000ea04f
(XEN) HVM1: - Hi data: fc002c00-fc0121cf
(XEN) HVM1: vm86 TSS at fc012400
(XEN) HVM1: BIOS map:
(XEN) HVM1: c0000-c8fff: VGA BIOS
(XEN) HVM1: eb000-eb148: SMBIOS tables
(XEN) HVM1: f0000-fffff: Main BIOS
(XEN) HVM1: Invoking ROMBIOS ...
(XEN) HVM1: $Revision: 1.221 $ $Date: 2008/12/07 17:32:29 $
(XEN) stdvga.c:147:d1 entering stdvga and caching modes
(XEN) HVM1: VGABios $Id: vgabios.c,v 1.67 2008/01/27 09:44:12 vruppert Exp $
(XEN) HVM1: Bochs BIOS - build: 06/23/99
(XEN) HVM1: $Revision: 1.221 $ $Date: 2008/12/07 17:32:29 $
(XEN) HVM1: Options: apmbios pcibios eltorito PMM
(XEN) HVM1:
(XEN) HVM1: ata0-0: PCHS=12483/16/63 translation=lba LCHS=783/255/63
(XEN) HVM1: ata0 master: QEMU HARDDISK ATA-7 Hard-Disk (6144 MBytes)
(XEN) HVM1: IDE time out
(XEN) HVM1:
(XEN) HVM1:
(XEN) HVM1:
(XEN) HVM1: Press F12 for boot menu.
(XEN) HVM1:
(XEN) HVM1: Booting from Hard Disk...
(XEN) HVM1: Booting from 0000:7c00
(XEN) HVM1: int13_harddisk: function 15, unmapped device for ELDL=81
(XEN) HVM1: *** int 15h function AX=e980, BX=006e not yet supported!
(XEN) common.c:3623:d0 tracking VRAM f0000 - f0026
(XEN) irq.c:243: Dom1 PCI link 0 changed 5 -> 0
(XEN) irq.c:243: Dom1 PCI link 1 changed 10 -> 0
(XEN) irq.c:243: Dom1 PCI link 2 changed 11 -> 0
(XEN) irq.c:243: Dom1 PCI link 3 changed 5 -> 0
(XEN) domctl.c:835:d0 memory_map:add: gfn=fbfff mfn=80101 nr_mfns=1
(XEN) domctl.c:886:d0 ioport_map:add f_gport=ffe0 f_mport=1c00 np=20
(XEN) domctl.c:886:d0 ioport_map:add f_gport=ffc0 f_mport=1860 np=20
(XEN) domctl.c:886:d0 ioport_map:add f_gport=ffa0 f_mport=18e0 np=20
(XEN) domctl.c:886:d0 ioport_map:add f_gport=ff80 f_mport=1880 np=20
(XEN) domctl.c:886:d0 ioport_map:add f_gport=ff60 f_mport=18c0 np=20
(XEN) domctl.c:886:d0 ioport_map:add f_gport=ff40 f_mport=18a0 np=20
(XEN) domctl.c:835:d0 memory_map:add: gfn=fbffe mfn=80100 nr_mfns=1
[ 287.624198] ACPI: EC: missing write data confirmation, don't expect
it any longer.
[ 293.748242] ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
[ 293.748353] ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
[ 293.748354] cdb 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 293.748354] res 40/00:03:00:00:00/00:00:00:00:00/a0 Emask
0x4 (timeout)
[ 293.748658] ata2.00: status: { DRDY }
[ 294.060173] ata2: soft resetting link
[ 294.224137] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[ 297.579229] ata1.00: exception Emask 0x0 SAct 0xffff SErr 0x0
action 0x2 frozen
[ 297.579344] ata1.00: cmd 61/10:00:f7:9e:ed/00:00:00:00:00/40 tag 0
ncq 8192 out
[ 297.579345] res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 297.579570] ata1.00: status: { DRDY }
[ 297.579657] ata1.00: cmd 61/18:08:6f:bc:65/00:00:00:00:00/40 tag 1
ncq 12288 out
[ 297.579658] res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 297.579849] ata1.00: status: { DRDY }
[ 297.579936] ata1.00: cmd 61/10:10:3f:1c:67/00:00:00:00:00/40 tag 2
ncq 8192 out
[ 297.579937] res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 297.580127] ata1.00: status: { DRDY }
[ 297.580215] ata1.00: cmd 61/08:18:27:26:67/00:00:00:00:00/40 tag 3
ncq 4096 out
[ 297.580216] res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 297.580406] ata1.00: status: { DRDY }
[ 297.580494] ata1.00: cmd 61/08:20:2f:26:67/00:00:00:00:00/40 tag 4
ncq 4096 out
[ 297.580494] res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 297.580684] ata1.00: status: { DRDY }
[ 297.580795] ata1.00: cmd 61/20:28:6f:27:67/00:00:00:00:00/40 tag 5
ncq 16384 out
[ 297.580796] res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 297.580999] ata1.00: status: { DRDY }
[ 297.581088] ata1.00: cmd 61/08:30:0f:33:67/00:00:00:00:00/40 tag 6
ncq 4096 out
[ 297.581089] res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 297.581281] ata1.00: status: { DRDY }
[ 297.581369] ata1.00: cmd 61/10:38:1f:9f:ed/00:00:00:00:00/40 tag 7
ncq 8192 out
[ 297.581370] res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 297.581563] ata1.00: status: { DRDY }
[ 297.581652] ata1.00: cmd 61/08:40:17:33:67/00:00:00:00:00/40 tag 8
ncq 4096 out
[ 297.581653] res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 297.582447] ata1.00: status: { DRDY }
[ 297.582536] ata1.00: cmd 61/50:48:c7:35:67/00:00:00:00:00/40 tag 9
ncq 40960 out
[ 297.582537] res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 297.582728] ata1.00: status: { DRDY }
[ 297.582817] ata1.00: cmd 61/10:50:b7:36:67/00:00:00:00:00/40 tag 10
ncq 8192 out
[ 297.582818] res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 297.583009] ata1.00: status: { DRDY }
[ 297.583097] ata1.00: cmd 61/08:58:3f:3a:67/00:00:00:00:00/40 tag 11
ncq 4096 out
[ 297.583098] res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 297.583293] ata1.00: status: { DRDY }
[ 297.583383] ata1.00: cmd 61/10:60:47:3a:67/00:00:00:00:00/40 tag 12
ncq 8192 out
[ 297.583384] res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 297.583613] ata1.00: status: { DRDY }
[ 297.583701] ata1.00: cmd 61/10:68:87:3b:67/00:00:00:00:00/40 tag 13
ncq 8192 out
[ 297.583702] res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 297.583894] ata1.00: status: { DRDY }
[ 297.583983] ata1.00: cmd 61/10:70:8f:3f:67/00:00:00:00:00/40 tag 14
ncq 8192 out
[ 297.583983] res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 297.584174] ata1.00: status: { DRDY }
[ 297.584262] ata1.00: cmd 61/08:78:27:41:67/00:00:00:00:00/40 tag 15
ncq 4096 out
[ 297.584263] res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 297.584458] ata1.00: status: { DRDY }
[ 297.266871] ata1: soft resetting link
[ 297.430863] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Tom
_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxxxxxxxx
http://lists.xensource.com/xen-devel
|
Home