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

["Gabriel L. Somlo" <gsomlo@gmail.com>]

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