[Qemu-devel] q35, usb-ehci1, and Mac OS X boot problems

[Qemu-devel] q35, usb-ehci1, and Mac OS X boot problems

[Gabriel L. Somlo]

Hi,

I'm testing OS X on the q35 tree, and it seems to work quite nicely
so far.

However, with the addition of "usb-ehci1" in the latest round of
updates, I've started experiencing hangs during OS X boot.

First, what works:

With the following command line (usb items on the last line):

bin/qemu-system-x86_64 -enable-kvm -m 2048 -cpu core2duo \
  -M q35 -L q35-seabios/out -monitor stdio \
  -device isa-applesmc,osk="our...<magic apple smc key>...Inc" \
  -kernel ./Chameleon_RC5_Trunk_Binaries_r668/i386/boot \
  -netdev user,id=hub0port0 -device e1000,netdev=hub0port0,id=eth0 \
  -device ide-drive,bus=ide.0,drive=MacHDD \
  -drive id=MacHDD,if=none,snapshot=on,file=./mac_10.6.img \
  -device ich9-usb-uhci1 -device usb-kbd -device usb-mouse

I get a working OS X guest, with the following USB related bits in
'info qtree':

...
  dev: gmch-pcihost, id ""
    MCFG = 2952790016
    irq 0
    bus: pcie.0
      type PCI
      dev: ich9-usb-uhci1, id ""
        masterbus = <null>
        firstport = 0
        bandwidth = 1280
        addr = 03.0
        romfile = <null>
        rombar = 1
        multifunction = off
        command_serr_enable = on
        class USB controller, addr 00:03.0, pci id 8086:2934 (sub 1af4:1100)
        bar 4: i/o at 0xc040 [0xc05f]
        bus: usb-bus.0
          type usb-bus
          dev: usb-hub, id ""
            port = <null>
            full-path = on
            addr 0.3, port 2, speed 12, name QEMU USB Hub, attached
          dev: usb-mouse, id ""
            port = <null>
            full-path = on
            addr 0.4, port 2.1, speed 12, name QEMU USB Mouse, attached
          dev: usb-kbd, id ""
            port = <null>
            full-path = on
            addr 0.2, port 1, speed 12, name QEMU USB Keyboard, attached
...

If I replace:

  -device ich9-usb-uhci1 -device usb-kbd -device usb-mouse

with the generic default:

  -usb -device usb-kbd -device usb-mouse

I get a hang at boot time. OS X (SnowLeopard) prints the following
USB-related warning/error to its console:

USBF: 2.557 AppleUSBEHCI[0xffffff80056c5000]::CheckSleepCapability - controller will be unloaded across sleep

The following USB bits show up in 'info qtree':

...
  dev: gmch-pcihost, id ""
    MCFG = 2952790016
    irq 0
    bus: pcie.0
      type PCI
      ...
      dev: ich9-usb-uhci3, id ""
        masterbus = "usb-bus.0"
        firstport = 4
        bandwidth = 1280
        addr = 1d.2
        romfile = <null>
        rombar = 1
        multifunction = on
        command_serr_enable = on
        class USB controller, addr 00:1d.2, pci id 8086:2936 (sub 1af4:1100)
        bar 4: i/o at 0xc080 [0xc09f]
      dev: ich9-usb-uhci2, id ""
        masterbus = "usb-bus.0"
        firstport = 2
        bandwidth = 1280
        addr = 1d.1
        romfile = <null>
        rombar = 1
        multifunction = on
        command_serr_enable = on
        class USB controller, addr 00:1d.1, pci id 8086:2935 (sub 1af4:1100)
        bar 4: i/o at 0xc060 [0xc07f]
      dev: ich9-usb-uhci1, id ""
        masterbus = "usb-bus.0"
        firstport = 0
        bandwidth = 1280
        addr = 1d.0
        romfile = <null>
        rombar = 1
        multifunction = on
        command_serr_enable = on
        class USB controller, addr 00:1d.0, pci id 8086:2934 (sub 1af4:1100)
        bar 4: i/o at 0xc040 [0xc05f]
      dev: ich9-usb-ehci1, id ""
        maxframes = 128
        addr = 1d.7
        romfile = <null>
        rombar = 1
        multifunction = on
        command_serr_enable = on
        class USB controller, addr 00:1d.7, pci id 8086:293a (sub 1af4:1100)
        bar 0: mem at 0xfebf1000 [0xfebf1fff]
        bus: usb-bus.0
          type usb-bus
          dev: usb-mouse, id ""
            port = <null>
            full-path = on
            addr 0.0, port 2, speed 12, name QEMU USB Mouse, attached
          dev: usb-kbd, id ""
            port = <null>
            full-path = on
            addr 0.0, port 1, speed 12, name QEMU USB Keyboard, attached

Note how both the keyboard and mouse are now under 'ehci1', rather than
under one of the 'uhci' entries, e.g. uhci1 like in the working example
earlier on.

When I try to start with ehci1 only, with the following USB command line
items:

  -device ich9-usb-ehci1 -device usb-kbd -device usb-mouse

I get an error from qemu:

speed mismatch trying to attach usb device QEMU USB Keyboard to bus usb-bus.0

The simple presence of EHCI1 as configured by "-device ich9-usb-ehci1"
will prevent OS X from booting (with the above-mentioned "controller will be
unloaded across sleep" warning). If added all by itself, it looks like
this in qtree:

...
  dev: gmch-pcihost, id ""
    MCFG = 2952790016
    irq 0
    bus: pcie.0
      type PCI
      dev: ich9-usb-ehci1, id ""
        maxframes = 128
        addr = 03.0
        romfile = <null>
        rombar = 1
        multifunction = off
        command_serr_enable = on
        class USB controller, addr 00:03.0, pci id 8086:293a (sub 1af4:1100)
        bar 0: mem at 0xfebf1000 [0xfebf1fff]
        bus: usb-bus.0
          type usb-bus

...

I don't know if/how I can tell '-device usb-kbd' to connect under usb-uhci1
specifically (in the case where both ehci1 and uhci[1-3] are present), so I
did not have a chance to try that.

I wonder what specifically about the way ehci1 is added to the device tree
make it not work properly on OS X -- any ideas for what may be wrong, or
what else I may try, would be much appreciated !

Thanks,
--Gabriel

PS. For comparison with some real Apple hardware, here are the usb bits from
lspci on an old first-generation MacBookPro from 2006:


00:1d.0 USB Controller: Intel Corporation 82801G (ICH7 Family) USB UHCI Controller #1 (rev 02) (prog-if 00 [UHCI])
	Subsystem: Intel Corporation Device 7270
	Control: I/O+ Mem- BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
	Status: Cap- 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
	Latency: 0
	Interrupt: pin A routed to IRQ 23
	Region 4: I/O ports at 40a0 [size=32]
	Kernel driver in use: uhci_hcd

00:1d.1 USB Controller: Intel Corporation 82801G (ICH7 Family) USB UHCI Controller #2 (rev 02) (prog-if 00 [UHCI])
	Subsystem: Intel Corporation Device 7270
	Control: I/O+ Mem- BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
	Status: Cap- 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
	Latency: 0
	Interrupt: pin B routed to IRQ 19
	Region 4: I/O ports at 4080 [size=32]
	Kernel driver in use: uhci_hcd

00:1d.2 USB Controller: Intel Corporation 82801G (ICH7 Family) USB UHCI Controller #3 (rev 02) (prog-if 00 [UHCI])
	Subsystem: Intel Corporation Device 7270
	Control: I/O+ Mem- BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
	Status: Cap- 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
	Latency: 0
	Interrupt: pin C routed to IRQ 18
	Region 4: I/O ports at 4060 [size=32]
	Kernel driver in use: uhci_hcd

00:1d.3 USB Controller: Intel Corporation 82801G (ICH7 Family) USB UHCI Controller #4 (rev 02) (prog-if 00 [UHCI])
	Subsystem: Intel Corporation Device 7270
	Control: I/O+ Mem- BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
	Status: Cap- 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
	Latency: 0
	Interrupt: pin D routed to IRQ 16
	Region 4: I/O ports at 4040 [size=32]
	Kernel driver in use: uhci_hcd

00:1d.7 USB Controller: Intel Corporation 82801G (ICH7 Family) USB2 EHCI Controller (rev 02) (prog-if 20 [EHCI])
	Subsystem: Intel Corporation Device 7270
	Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
	Status: Cap+ 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
	Latency: 0
	Interrupt: pin A routed to IRQ 23
	Region 0: Memory at 98405400 (32-bit, non-prefetchable) [size=1K]
	Capabilities: [50] Power Management version 2
		Flags: PMEClk- DSI- D1- D2- AuxCurrent=375mA PME(D0+,D1-,D2-,D3hot+,D3cold+)
		Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=0 PME-
	Capabilities: [58] Debug port: BAR=1 offset=00a0
	Kernel driver in use: ehci_hcd


Also, on my 2010 MacPro5,1 (now with twice the USB hardware :) :


00:1a.0 USB Controller: Intel Corporation 82801JI (ICH10 Family) USB UHCI Controller #4 (prog-if 00 [UHCI])
        Subsystem: Intel Corporation Device 7270
        Control: I/O+ Mem- BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
        Status: Cap+ 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
        Latency: 0
        Interrupt: pin A routed to IRQ 16
        Region 4: I/O ports at 40e0 [size=32]
        Capabilities: [50] PCI Advanced Features
                AFCap: TP+ FLR+
                AFCtrl: FLR-
                AFStatus: TP-
        Kernel driver in use: uhci_hcd

00:1a.1 USB Controller: Intel Corporation 82801JI (ICH10 Family) USB UHCI Controller #5 (prog-if 00 [UHCI])
        Subsystem: Intel Corporation Device 7270
        Control: I/O+ Mem- BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
        Status: Cap+ 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
        Latency: 0
        Interrupt: pin B routed to IRQ 21
        Region 4: I/O ports at 40c0 [size=32]
        Capabilities: [50] PCI Advanced Features
                AFCap: TP+ FLR+
                AFCtrl: FLR-
                AFStatus: TP-
        Kernel driver in use: uhci_hcd

00:1a.2 USB Controller: Intel Corporation 82801JI (ICH10 Family) USB UHCI Controller #6 (prog-if 00 [UHCI])
        Subsystem: Intel Corporation Device 7270
        Control: I/O+ Mem- BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
        Status: Cap+ 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
        Latency: 0
        Interrupt: pin D routed to IRQ 19
        Region 4: I/O ports at 40a0 [size=32]
        Capabilities: [50] PCI Advanced Features
                AFCap: TP+ FLR+
                AFCtrl: FLR-
                AFStatus: TP-
        Kernel driver in use: uhci_hcd

00:1a.7 USB Controller: Intel Corporation 82801JI (ICH10 Family) USB2 EHCI Controller #2 (prog-if 20 [EHCI])
        Subsystem: Intel Corporation Device 7270
        Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
        Status: Cap+ 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
        Latency: 0
        Interrupt: pin C routed to IRQ 18
        Region 0: Memory at a0526000 (32-bit, non-prefetchable) [size=1K]
        Capabilities: [50] Power Management version 2
                Flags: PMEClk- DSI- D1- D2- AuxCurrent=375mA PME(D0+,D1-,D2-,D3hot+,D3cold+)
                Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=0 PME-
        Capabilities: [58] Debug port: BAR=1 offset=00a0
        Capabilities: [98] PCI Advanced Features
                AFCap: TP+ FLR+
                AFCtrl: FLR-
                AFStatus: TP-
        Kernel driver in use: ehci_hcd
...
00:1d.0 USB Controller: Intel Corporation 82801JI (ICH10 Family) USB UHCI Controller #1 (prog-if 00 [UHCI])
        Subsystem: Intel Corporation Device 7270
        Control: I/O+ Mem- BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
        Status: Cap+ 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
        Latency: 0
        Interrupt: pin A routed to IRQ 23
        Region 4: I/O ports at 4080 [size=32]
        Capabilities: [50] PCI Advanced Features
                AFCap: TP+ FLR+
                AFCtrl: FLR-
                AFStatus: TP-
        Kernel driver in use: uhci_hcd

00:1d.1 USB Controller: Intel Corporation 82801JI (ICH10 Family) USB UHCI Controller #2 (prog-if 00 [UHCI])
        Subsystem: Intel Corporation Device 7270
        Control: I/O+ Mem- BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
        Status: Cap+ 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
        Latency: 0
        Interrupt: pin B routed to IRQ 19
        Region 4: I/O ports at 4060 [size=32]
        Capabilities: [50] PCI Advanced Features
                AFCap: TP+ FLR+
                AFCtrl: FLR-
                AFStatus: TP-
        Kernel driver in use: uhci_hcd

00:1d.2 USB Controller: Intel Corporation 82801JI (ICH10 Family) USB UHCI Controller #3 (prog-if 00 [UHCI])
        Subsystem: Intel Corporation Device 7270
        Control: I/O+ Mem- BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
        Status: Cap+ 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
        Latency: 0
        Interrupt: pin C routed to IRQ 18
        Region 4: I/O ports at 4040 [size=32]
        Capabilities: [50] PCI Advanced Features
                AFCap: TP+ FLR+
                AFCtrl: FLR-
                AFStatus: TP-
        Kernel driver in use: uhci_hcd

00:1d.7 USB Controller: Intel Corporation 82801JI (ICH10 Family) USB2 EHCI Controller #1 (prog-if 20 [EHCI])
        Subsystem: Intel Corporation Device 7270
        Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
        Status: Cap+ 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
        Latency: 0
        Interrupt: pin D routed to IRQ 16
        Region 0: Memory at a0525000 (32-bit, non-prefetchable) [size=1K]
        Capabilities: [50] Power Management version 2
                Flags: PMEClk- DSI- D1- D2- AuxCurrent=375mA PME(D0+,D1-,D2-,D3hot+,D3cold+)
                Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=0 PME-
        Capabilities: [58] Debug port: BAR=1 offset=00a0
        Capabilities: [98] PCI Advanced Features
                AFCap: TP+ FLR+
                AFCtrl: FLR-
                AFStatus: TP-
        Kernel driver in use: ehci_hcd

Re: [Qemu-devel] q35, usb-ehci1, and Mac OS X boot problems

[Gerd Hoffmann]

  Hi,

> First, what works:
> 
> With the following command line (usb items on the last line):
> 
> bin/qemu-system-x86_64 -enable-kvm -m 2048 -cpu core2duo \

>   -device ich9-usb-uhci1 -device usb-kbd -device usb-mouse

Just uhci.  Ok.

> If I replace:
> 
>   -device ich9-usb-uhci1 -device usb-kbd -device usb-mouse
> 
> with the generic default:
> 
>   -usb -device usb-kbd -device usb-mouse
> 
> I get a hang at boot time. OS X (SnowLeopard) prints the following
> USB-related warning/error to its console:
> 
> USBF: 2.557 AppleUSBEHCI[0xffffff80056c5000]::CheckSleepCapability - controller will be unloaded across sleep

Seems macos doesn't like something in our ehci emulation ...

Can you send a trace with all ehci tracepoints enabled?

> Note how both the keyboard and mouse are now under 'ehci1', rather than
> under one of the 'uhci' entries, e.g. uhci1 like in the working example
> earlier on.

That is normal for a companion controller setup.  For the guest usb 1.1
devices will show up at one of the uhci companion controllers
nevertheless (lsusb in linux guests will show that).

cheers,
  Gerd

[Qemu-devel] [PATCH] ehci: fix compile error with EHCI_DEBUG enabled

[Gabriel L. Somlo]

This patch fixes a few debugging print statements whose arguments fell
out of sync over time with changes being made to the active code base.

Signed-off-by: Gabriel Somlo <somlo@cmu.edu>
---

On Mon, Nov 12, 2012 at 11:26:18AM +0100, Gerd Hoffmann wrote:
> Seems macos doesn't like something in our ehci emulation ...
> Can you send a trace with all ehci tracepoints enabled?

Turning EHCI_DEBUG on gave me compile errors. This is my best guess
as to what the DPRINTF arguments *should* be, hope I guessed right :)

This patch works against both master and the q35 branch, BTW.

I'll reply to your email again with the debug output, figured I'd get
this out of the way first...

Thanks,
  Gabriel

 hw/usb/hcd-ehci.c |    6 +++---
 1 files changed, 3 insertions(+), 3 deletions(-)

diff --git a/hw/usb/hcd-ehci.c b/hw/usb/hcd-ehci.c
index d9dc576..e3ccb59 100644
--- a/hw/usb/hcd-ehci.c
+++ b/hw/usb/hcd-ehci.c
@@ -1188,7 +1188,7 @@ static void ehci_execute_complete(EHCIQueue *q)
            p->async == EHCI_ASYNC_FINISHED);
 
     DPRINTF("execute_complete: qhaddr 0x%x, next %x, qtdaddr 0x%x, status %d\n",
-            q->qhaddr, q->qh.next, q->qtdaddr, q->usb_status);
+            q->qhaddr, q->qh.next, q->qtdaddr, p->usb_status);
 
     if (p->usb_status < 0) {
         switch (p->usb_status) {
@@ -1305,8 +1305,8 @@ static int ehci_execute(EHCIPacket *p, const char *action)
     trace_usb_ehci_packet_action(p->queue, p, action);
     ret = usb_handle_packet(p->queue->dev, &p->packet);
     DPRINTF("submit: qh %x next %x qtd %x pid %x len %zd endp %x ret %d\n",
-            q->qhaddr, q->qh.next, q->qtdaddr, q->pid,
-            q->packet.iov.size, endp, ret);
+            p->queue->qhaddr, p->queue->qh.next, p->queue->qtdaddr, p->pid,
+            p->packet.iov.size, endp, ret);
 
     if (ret > BUFF_SIZE) {
         fprintf(stderr, "ret from usb_handle_packet > BUFF_SIZE\n");
-- 
1.7.7.6

Re: [Qemu-devel] q35, usb-ehci1, and Mac OS X boot problems

[Gabriel L. Somlo]

Gerd,

On Mon, Nov 12, 2012 at 11:26:18AM +0100, Gerd Hoffmann wrote:
> Seems macos doesn't like something in our ehci emulation ...
> Can you send a trace with all ehci tracepoints enabled?

For brevity, I replaced each cluster of six "Port X not enabled"
lines with one "Port 0..5 not enabled", but otherwise the output
below is what I got running the "-usb -device usb-kbd -device usb-mouse"
command line with EHCI_DEBUG set to 1.

Thanks,
--Gabriel


Port 0 not enabled
Port 1 not enabled
Port 2 not enabled
Port 3 not enabled
Port 4 not enabled
Port 5 not enabled
PERIODIC state adv fr=1.  [7FFFB004] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
PERIODIC state adv fr=2.  [7FFFB008] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=3.  [7FFFB00C] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=4.  [7FFFB010] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=5.  [7FFFB014] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=6.  [7FFFB018] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=7.  [7FFFB01C] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=8.  [7FFFB020] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=9.  [7FFFB024] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
PERIODIC state adv fr=10.  [7FFFB028] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
PERIODIC state adv fr=11.  [7FFFB02C] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
PERIODIC state adv fr=12.  [7FFFB030] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
PERIODIC state adv fr=13.  [7FFFB034] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=14.  [7FFFB038] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=15.  [7FFFB03C] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=16.  [7FFFB040] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=17.  [7FFFB044] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=18.  [7FFFB048] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=19.  [7FFFB04C] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=20.  [7FFFB050] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=21.  [7FFFB054] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=22.  [7FFFB058] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=23.  [7FFFB05C] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=24.  [7FFFB060] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=25.  [7FFFB064] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=26.  [7FFFB068] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=27.  [7FFFB06C] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=28.  [7FFFB070] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=29.  [7FFFB074] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=30.  [7FFFB078] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=31.  [7FFFB07C] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=32.  [7FFFB080] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=33.  [7FFFB084] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
PERIODIC state adv fr=34.  [7FFFB088] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=35.  [7FFFB08C] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=36.  [7FFFB090] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=37.  [7FFFB094] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=38.  [7FFFB098] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=39.  [7FFFB09C] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=40.  [7FFFB0A0] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=41.  [7FFFB0A4] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=42.  [7FFFB0A8] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=43.  [7FFFB0AC] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=44.  [7FFFB0B0] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=45.  [7FFFB0B4] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=46.  [7FFFB0B8] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=47.  [7FFFB0BC] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=48.  [7FFFB0C0] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=49.  [7FFFB0C4] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=50.  [7FFFB0C8] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=51.  [7FFFB0CC] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=52.  [7FFFB0D0] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=53.  [7FFFB0D4] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=54.  [7FFFB0D8] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=55.  [7FFFB0DC] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
PERIODIC state adv fr=56.  [7FFFB0E0] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=57.  [7FFFB0E4] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=58.  [7FFFB0E8] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=59.  [7FFFB0EC] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=60.  [7FFFB0F0] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=61.  [7FFFB0F4] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=62.  [7FFFB0F8] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=63.  [7FFFB0FC] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=64.  [7FFFB100] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=65.  [7FFFB104] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=66.  [7FFFB108] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=67.  [7FFFB10C] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=68.  [7FFFB110] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=69.  [7FFFB114] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=70.  [7FFFB118] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=71.  [7FFFB11C] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=72.  [7FFFB120] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
PERIODIC state adv fr=73.  [7FFFB124] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=74.  [7FFFB128] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=75.  [7FFFB12C] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=76.  [7FFFB130] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
PERIODIC state adv fr=77.  [7FFFB134] -> 7FFFC902
Port 0..5 not enabled
FETCHQH:  QH 0x7fffc902 (h 0 halt 40 active 0) next 0x00000001
Port 0..5 not enabled
Port 0..5 not enabled

Re: [Qemu-devel] q35, usb-ehci1, and Mac OS X boot problems

[Gerd Hoffmann]

On 11/12/12 16:17, Gabriel L. Somlo wrote:
> Gerd,
> 
> On Mon, Nov 12, 2012 at 11:26:18AM +0100, Gerd Hoffmann wrote:
>> Seems macos doesn't like something in our ehci emulation ...
>> Can you send a trace with all ehci tracepoints enabled?
> 
> For brevity, I replaced each cluster of six "Port X not enabled"
> lines with one "Port 0..5 not enabled", but otherwise the output
> below is what I got running the "-usb -device usb-kbd -device usb-mouse"
> command line with EHCI_DEBUG set to 1.

This isn't what I ment.  See docs/tracing.txt for how tracepoint work.
Wildcards (i.e. 'ehci_*') work on tracepoints.

cheers,
  Gerd

Re: [Qemu-devel] q35, usb-ehci1, and Mac OS X boot problems

[Gabriel L. Somlo]

Gerd,

On Tue, Nov 13, 2012 at 09:48:10AM +0100, Gerd Hoffmann wrote:
> > below is what I got running the "-usb -device usb-kbd -device usb-mouse"
> > command line with EHCI_DEBUG set to 1.
> 
> This isn't what I ment.  See docs/tracing.txt for how tracepoint work.
> Wildcards (i.e. 'ehci_*') work on tracepoints.

Below are the first 100 (of 6516784) ascii lines from the ehci_* trace
file I collected in the cca. 30 seconds it took to get to the point
where it's clear OS X boot is stuck and won't be making any further
progress.

In case you need it, the full (11M xz-compressed) trace file is at
http://www.contrib.andrew.cmu.edu/~somlo/OSXKVM/ehci_trace.xz

Thanks,
--Gabriel

usb_ehci_port_attach 0.000 port=0x0 owner=comp device=QEMU USB Keyboard
usb_ehci_port_attach 31.297 port=0x1 owner=comp device=QEMU USB Mouse
usb_ehci_reset 153537.179
usb_ehci_port_detach 1.689 port=0x0 owner=comp
usb_ehci_port_detach 1.527 port=0x1 owner=comp
usb_ehci_port_attach 1.311 port=0x0 owner=comp device=QEMU USB Keyboard
usb_ehci_port_attach 2.506 port=0x1 owner=comp device=QEMU USB Mouse
usb_ehci_opreg_read 338333.341 addr=0x20 str=USBCMD val=0x80000
usb_ehci_opreg_write 13.640 addr=0x20 str=USBCMD val=0x80002
usb_ehci_reset 1.018
usb_ehci_port_detach 1.546 port=0x0 owner=comp
usb_ehci_port_detach 1.203 port=0x1 owner=comp
usb_ehci_port_attach 1.669 port=0x0 owner=comp device=QEMU USB Keyboard
usb_ehci_port_attach 3.504 port=0x1 owner=comp device=QEMU USB Mouse
usb_ehci_opreg_change 2.038 addr=0x20 str=USBCMD new=0x80000 old=0x80000
usb_ehci_opreg_read 7.118 addr=0x20 str=USBCMD val=0x80000
usb_ehci_opreg_write 7.322 addr=0x28 str=USBINTR val=0x0
usb_ehci_opreg_change 0.699 addr=0x28 str=USBINTR new=0x0 old=0x0
usb_ehci_opreg_write 8.577 addr=0x34 str=P-LIST BASE val=0x7fffb000
usb_ehci_opreg_change 0.636 addr=0x34 str=P-LIST BASE new=0x7fffb000 old=0x0
usb_ehci_opreg_write 6.342 addr=0x38 str=A-LIST ADDR val=0x7fffc880
usb_ehci_opreg_change 0.498 addr=0x38 str=A-LIST ADDR new=0x7fffc880 old=0x0
usb_ehci_opreg_write 6.068 addr=0x20 str=USBCMD val=0x80031
usb_ehci_usbsts 4.793 sts=HALT state=0x0
usb_ehci_opreg_change 4.707 addr=0x20 str=USBCMD new=0x80031 old=0x80000
usb_ehci_opreg_write 53.414 addr=0x60 str=CONFIGFLAG val=0x1
usb_ehci_port_detach 1.060 port=0x0 owner=comp
usb_ehci_port_attach 0.654 port=0x0 owner=ehci device=QEMU USB Keyboard
usb_ehci_irq 0.654 level=0x0 frindex=0x0 sts=0x4 mask=0x0
usb_ehci_port_detach 0.965 port=0x1 owner=comp
usb_ehci_port_attach 0.411 port=0x1 owner=ehci device=QEMU USB Mouse
usb_ehci_irq 0.424 level=0x0 frindex=0x0 sts=0x4 mask=0x0
usb_ehci_opreg_change 0.664 addr=0x60 str=CONFIGFLAG new=0x1 old=0x0
usb_ehci_state 16.577 schedule=async state=ACTIVE
usb_ehci_usbsts 1.527 sts=ASS state=0x1
usb_ehci_state 0.982 schedule=async state=WAITLISTHEAD
usb_ehci_usbsts 1.143 sts=REC state=0x1
usb_ehci_qh_ptrs 5.108 q=0x0 addr=0x7fffc880 nxt=0x7fffc882 c_qtd=0x0 n_qtd=0x1 a_qtd=0x1
usb_ehci_qh_fields 0.599 addr=0x7fffc880 rl=0x0 mplen=0x0 eps=0x0 ep=0x0 devaddr=0x0
usb_ehci_qh_bits 0.607 addr=0x7fffc880 c=0x0 h=0x1 dtc=0x0 i=0x0
usb_ehci_state 0.792 schedule=async state=FETCH ENTRY
usb_ehci_state 0.732 schedule=async state=FETCH QH
usb_ehci_queue_action 4.098 q=0x7f358b3b0bd0 action=alloc
usb_ehci_qh_ptrs 1.469 q=0x7f358b3b0bd0 addr=0x7fffc880 nxt=0x7fffc882 c_qtd=0x0 n_qtd=0x1 a_qtd=0x1
usb_ehci_qh_fields 0.531 addr=0x7fffc880 rl=0x0 mplen=0x0 eps=0x0 ep=0x0 devaddr=0x0
usb_ehci_qh_bits 0.494 addr=0x7fffc880 c=0x0 h=0x1 dtc=0x0 i=0x0
usb_ehci_queue_action 1.165 q=0x7f358b3b0bd0 action=reset
usb_ehci_usbsts 0.933 sts=REC state=0x0
usb_ehci_state 0.579 schedule=async state=HORIZONTALQH
usb_ehci_state 0.516 schedule=async state=ACTIVE
usb_ehci_portsc_read 77.999 addr=0x44 port=0x0 val=0x1003
usb_ehci_portsc_read 24.851 addr=0x48 port=0x1 val=0x1003
usb_ehci_portsc_read 13.452 addr=0x4c port=0x2 val=0x1000
usb_ehci_portsc_read 9.878 addr=0x50 port=0x3 val=0x1000
usb_ehci_portsc_read 8.800 addr=0x54 port=0x4 val=0x1000
usb_ehci_portsc_read 8.715 addr=0x58 port=0x5 val=0x1000
usb_ehci_state 1799.380 schedule=periodic state=ACTIVE
usb_ehci_usbsts 1.002 sts=PSS state=0x1
usb_ehci_state 2.575 schedule=periodic state=FETCH ENTRY
usb_ehci_state 0.914 schedule=periodic state=FETCH QH
usb_ehci_queue_action 2.116 q=0x7f358b3b0ed0 action=alloc
usb_ehci_qh_ptrs 1.651 q=0x7f358b3b0ed0 addr=0x7fffc900 nxt=0x1 c_qtd=0x0 n_qtd=0x1 a_qtd=0x1
usb_ehci_qh_fields 0.612 addr=0x7fffc900 rl=0x0 mplen=0x0 eps=0x0 ep=0x0 devaddr=0x0
usb_ehci_qh_bits 0.584 addr=0x7fffc900 c=0x0 h=0x0 dtc=0x0 i=0x0
usb_ehci_queue_action 0.882 q=0x7f358b3b0ed0 action=reset
usb_ehci_state 0.710 schedule=periodic state=HORIZONTALQH
usb_ehci_state 0.526 schedule=periodic state=FETCH ENTRY
usb_ehci_state 0.519 schedule=periodic state=ACTIVE
usb_ehci_state 0.694 schedule=periodic state=FETCH ENTRY
usb_ehci_state 0.441 schedule=periodic state=FETCH QH
usb_ehci_qh_ptrs 1.454 q=0x7f358b3b0ed0 addr=0x7fffc900 nxt=0x1 c_qtd=0x0 n_qtd=0x1 a_qtd=0x1
usb_ehci_qh_fields 0.544 addr=0x7fffc900 rl=0x0 mplen=0x0 eps=0x0 ep=0x0 devaddr=0x0
usb_ehci_qh_bits 0.504 addr=0x7fffc900 c=0x0 h=0x0 dtc=0x0 i=0x0
usb_ehci_state 0.579 schedule=periodic state=HORIZONTALQH
usb_ehci_state 0.408 schedule=periodic state=FETCH ENTRY
usb_ehci_state 0.424 schedule=periodic state=ACTIVE
usb_ehci_state 0.604 schedule=async state=WAITLISTHEAD
usb_ehci_usbsts 0.604 sts=REC state=0x1
usb_ehci_qh_ptrs 1.581 q=0x0 addr=0x7fffc880 nxt=0x7fffc882 c_qtd=0x0 n_qtd=0x1 a_qtd=0x1
usb_ehci_qh_fields 0.539 addr=0x7fffc880 rl=0x0 mplen=0x0 eps=0x0 ep=0x0 devaddr=0x0
usb_ehci_qh_bits 0.529 addr=0x7fffc880 c=0x0 h=0x1 dtc=0x0 i=0x0
usb_ehci_state 0.539 schedule=async state=FETCH ENTRY
usb_ehci_state 0.504 schedule=async state=FETCH QH
usb_ehci_qh_ptrs 1.591 q=0x7f358b3b0bd0 addr=0x7fffc880 nxt=0x7fffc882 c_qtd=0x0 n_qtd=0x1 a_qtd=0x1
usb_ehci_qh_fields 0.537 addr=0x7fffc880 rl=0x0 mplen=0x0 eps=0x0 ep=0x0 devaddr=0x0
usb_ehci_qh_bits 7.033 addr=0x7fffc880 c=0x0 h=0x1 dtc=0x0 i=0x0
usb_ehci_usbsts 0.714 sts=REC state=0x0
usb_ehci_state 0.358 schedule=async state=HORIZONTALQH
usb_ehci_state 0.509 schedule=async state=ACTIVE
usb_ehci_state 3983.812 schedule=periodic state=FETCH ENTRY
usb_ehci_state 1.120 schedule=periodic state=FETCH QH
usb_ehci_qh_ptrs 1.860 q=0x7f358b3b0ed0 addr=0x7fffc900 nxt=0x1 c_qtd=0x0 n_qtd=0x1 a_qtd=0x1
usb_ehci_qh_fields 0.752 addr=0x7fffc900 rl=0x0 mplen=0x0 eps=0x0 ep=0x0 devaddr=0x0
usb_ehci_qh_bits 0.614 addr=0x7fffc900 c=0x0 h=0x0 dtc=0x0 i=0x0
usb_ehci_state 0.985 schedule=periodic state=HORIZONTALQH
usb_ehci_state 0.514 schedule=periodic state=FETCH ENTRY
usb_ehci_state 0.569 schedule=periodic state=ACTIVE
usb_ehci_state 0.629 schedule=periodic state=FETCH ENTRY
usb_ehci_state 0.408 schedule=periodic state=FETCH QH
usb_ehci_qh_ptrs 1.424 q=0x7f358b3b0ed0 addr=0x7fffc900 nxt=0x1 c_qtd=0x0 n_qtd=0x1 a_qtd=0x1

Re: [Qemu-devel] q35, usb-ehci1, and Mac OS X boot problems

[Gerd Hoffmann]

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

On 11/13/12 16:48, Gabriel L. Somlo wrote:
> Gerd,
> 
> On Tue, Nov 13, 2012 at 09:48:10AM +0100, Gerd Hoffmann wrote:
>>> below is what I got running the "-usb -device usb-kbd -device usb-mouse"
>>> command line with EHCI_DEBUG set to 1.
>>
>> This isn't what I ment.  See docs/tracing.txt for how tracepoint work.
>> Wildcards (i.e. 'ehci_*') work on tracepoints.
> 
> Below are the first 100 (of 6516784) ascii lines from the ehci_* trace
> file I collected in the cca. 30 seconds it took to get to the point
> where it's clear OS X boot is stuck and won't be making any further
> progress.
>
> In case you need it, the full (11M xz-compressed) trace file is at
> http://www.contrib.andrew.cmu.edu/~somlo/OSXKVM/ehci_trace.xz

The last lines of the log are more useful, which is more than 6500000
lines like this:

usb_ehci_opreg_read 4.767 addr=0x2c str=FRINDEX val=0x0

So macos seems to expect the frame index updating, and probably frame
list rollover interrupts too.  ehci doesn't do that of there is nothing
else to do, to keep the wakeup rate down.

Does the attached patch change anything?

In case it doesn't:  Any change in behavior if you add a usb-storage device?

cheers,
  Gerd

[-- Attachment #2: 0001-ehci-keep-the-frame-timer-running-in-case-the-guest-.patch --]
[-- Type: text/plain, Size: 876 bytes --]

>From 822934d5118c18707a6781e006c35482186f2b12 Mon Sep 17 00:00:00 2001
From: Gerd Hoffmann <kraxel@redhat.com>
Date: Tue, 13 Nov 2012 17:20:05 +0100
Subject: [PATCH] ehci: keep the frame timer running in case the guest asked for frame list rollover interrupts

Signed-off-by: Gerd Hoffmann <kraxel@redhat.com>
---
 hw/usb/hcd-ehci.c |    4 ++++
 1 files changed, 4 insertions(+), 0 deletions(-)

diff --git a/hw/usb/hcd-ehci.c b/hw/usb/hcd-ehci.c
index ee6c9ae..20766d8 100644
--- a/hw/usb/hcd-ehci.c
+++ b/hw/usb/hcd-ehci.c
@@ -2209,6 +2209,10 @@ static void ehci_frame_timer(void *opaque)
         ehci->async_stepdown = 0;
     }
 
+    if (ehci->usbintr & USBSTS_FLR) {
+        need_timer++;
+    }
+
     if (need_timer) {
         /* If we've raised int, we speed up the timer, so that we quickly
          * notice any new packets queued up in response */
-- 
1.7.1

Re: [Qemu-devel] q35, usb-ehci1, and Mac OS X boot problems

[Gabriel L. Somlo]

On Tue, Nov 13, 2012 at 05:31:42PM +0100, Gerd Hoffmann wrote:
> The last lines of the log are more useful, which is more than 6500000
> lines like this:
> 
> usb_ehci_opreg_read 4.767 addr=0x2c str=FRINDEX val=0x0
> 
> So macos seems to expect the frame index updating, and probably frame
> list rollover interrupts too.  ehci doesn't do that of there is nothing
> else to do, to keep the wakeup rate down.
> 
> Does the attached patch change anything?

Sure does -- with the patch, OS X boots and runs just fine !

Thanks !
--Gabriel 

Re: [Qemu-devel] [PATCH] ehci: fix compile error with EHCI_DEBUG enabled

[Stefan Hajnoczi]

On Mon, Nov 12, 2012 at 09:49:19AM -0500, Gabriel L. Somlo wrote:
> This patch fixes a few debugging print statements whose arguments fell
> out of sync over time with changes being made to the active code base.
> 
> Signed-off-by: Gabriel Somlo <somlo@cmu.edu>
> ---
> 
> On Mon, Nov 12, 2012 at 11:26:18AM +0100, Gerd Hoffmann wrote:
> > Seems macos doesn't like something in our ehci emulation ...
> > Can you send a trace with all ehci tracepoints enabled?
> 
> Turning EHCI_DEBUG on gave me compile errors. This is my best guess
> as to what the DPRINTF arguments *should* be, hope I guessed right :)

In that case I'll let Gerd confirm whether or not the guesses are
correct.

Gerd: can you review and take this through the USB tree?

Thanks,
Stefan

Re: [Qemu-devel] [PATCH] ehci: fix compile error with EHCI_DEBUG enabled

[Gerd Hoffmann]

On 11/16/12 14:50, Stefan Hajnoczi wrote:
> On Mon, Nov 12, 2012 at 09:49:19AM -0500, Gabriel L. Somlo wrote:
>> Turning EHCI_DEBUG on gave me compile errors. This is my best guess
>> as to what the DPRINTF arguments *should* be, hope I guessed right :)
> 
> In that case I'll let Gerd confirm whether or not the guesses are
> correct.

Already fixed in master.

cheers,
  Gerd