xhci hang on boot

["Gary Duzan" <gary%duzan.org@localhost>]

   As has been mentioned earlier, the xhci driver causes the boot
process to hang on some machines, including mine. However, it turns
out that a single keystroke on the PS/2 keyboard (the USB one had
not been probed yet) allowed the boot to continue, and I successfully
accessed a USB2 flash drive connected to one of my USB3 ports. I'm
guessing then that there is an interrupt being lost somewhere, or
perhaps a missing timeout. The hang was occurring shortly after
attaching uhub0, as indicated in the dmesg.boot below, and you can
see the umass0 device attaching to it afterwards.

                                Gary Duzan



p.s. In the unlikely event that it matters, the kernel is GENERIC,
     but with IPSEC and IPSEC_ESP enabled in GENERIC.local.
===
Copyright (c) 1996, 1997, 1998, 1999, 2000, 2001, 2002, 2003, 2004, 2005,
    2006, 2007, 2008, 2009, 2010, 2011, 2012, 2013
    The NetBSD Foundation, Inc.  All rights reserved.
Copyright (c) 1982, 1986, 1989, 1991, 1993
    The Regents of the University of California.  All rights reserved.

NetBSD 6.99.25 (GENERIC) #3: Sat Nov  9 11:08:52 EST 2013
        
root%nbsd.xnet.duzan.org@localhost:/usr/build/netbsd-current/obj/usr/build/netbsd-current/src/sys/arch/amd64/compile/GENERIC
total memory = 12028 MB
avail memory = 11663 MB
timecounter: Timecounters tick every 10.000 msec
timecounter: Timecounter "i8254" frequency 1193182 Hz quality 100
Gigabyte Technology Co., Ltd. GA-880GMA-UD2H ( )
mainbus0 (root)
cpu0 at mainbus0 apid 0: AMD Athlon(tm) II X4 640 Processor, id 0x100f53
cpu1 at mainbus0 apid 1: AMD Athlon(tm) II X4 640 Processor, id 0x100f53
cpu2 at mainbus0 apid 2: AMD Athlon(tm) II X4 640 Processor, id 0x100f53
cpu3 at mainbus0 apid 3: AMD Athlon(tm) II X4 640 Processor, id 0x100f53
ioapic0 at mainbus0 apid 2: pa 0xfec00000, version 0x21, 24 pins
acpi0 at mainbus0: Intel ACPICA 20110623
acpi0: X/RSDT: OemId <GBT   ,GBTUACPI,42302e31>, AslId <GBTU,01010101>
acpi0: SCI interrupting at int 9
timecounter: Timecounter "ACPI-Fast" frequency 3579545 Hz quality 1000
hpet0 at acpi0: high precision event timer (mem 0xfed00000-0xfed00400)
timecounter: Timecounter "hpet0" frequency 14318180 Hz quality 2000
acpibut0 at acpi0 (PWRB, PNP0C0C): ACPI Power Button
SYSR (PNP0C02) at acpi0 not configured
PMIO (PNP0C02) at acpi0 not configured
attimer1 at acpi0 (TMR, PNP0100): io 0x40-0x43 irq 0
pcppi1 at acpi0 (SPKR, PNP0800): io 0x61
midi0 at pcppi1: PC speaker
sysbeep0 at pcppi1
FDC0 (PNP0700) at acpi0 not configured
pckbc1 at acpi0 (PS2K, PNP0303) (kbd port): io 0x60,0x64 irq 1
EXPL (PNP0C02) at acpi0 not configured
MEM (PNP0C01) at acpi0 not configured
acpiwmi0 at acpi0 (AOD, PNP0C14-0): ACPI WMI Interface
acpiwmibus at acpiwmi0 not configured
attimer1: attached to pcppi1
pckbd0 at pckbc1 (kbd slot)
pckbc1: using irq 1 for kbd slot
wskbd0 at pckbd0: console keyboard
pci0 at mainbus0 bus 0: configuration mode 1
pci0: i/o space, memory space enabled, rd/line, rd/mult, wr/inv ok
pchb0 at pci0 dev 0 function 0: vendor 0x1022 product 0x9601 (rev. 0x00)
ppb0 at pci0 dev 1 function 0: vendor 0x1022 product 0x9602 (rev. 0x00)
pci1 at ppb0 bus 1
pci1: i/o space, memory space enabled
vga0 at pci1 dev 5 function 0: vendor 0x1002 product 0x9715 (rev. 0x00)
wsdisplay0 at vga0 kbdmux 1: console (80x25, vt100 emulation), using wskbd0
wsmux1: connecting to wsdisplay0
radeondrm0 at vga0: ATI Radeon HD 4250
radeondrm0: Initialized radeon 1.29.0 20080613
hdaudio0 at pci1 dev 5 function 1: HD Audio Controller
hdaudio0: interrupting at ioapic0 pin 19
hdafg0 at hdaudio0: ATI RS690/780 HDMI
hdafg0: HDMI00 2ch: Digital Out [Jack]
hdafg0: 2ch/0ch 44100Hz 48000Hz PCM16 AC3
ppb1 at pci0 dev 9 function 0: vendor 0x1022 product 0x9608 (rev. 0x00)
ppb1: PCI Express 2.0 <Root Port of PCI-E Root Complex> x1 @ 5.0Gb/s
pci2 at ppb1 bus 2
pci2: i/o space, memory space enabled, rd/line, wr/inv ok
xhci0 at pci2 dev 0 function 0: vendor 0x1033 product 0x0194 (rev. 0x03)
xhci0: interrupting at ioapic0 pin 17
xhci0: xHCI version 0.96
xhci0: ac64 1 ctxsz 32
xhci0: xECP 500
xhci0: ECR 500: 00000401
xhci0: ECR 510: 03000402
xhci0: SP: 03000402 20425355 00000201
xhci0: ECR 520: 02000002
xhci0: SP: 02000002 20425355 00000203
xhci0: PAGESIZE 0x00000001
xhci0: sc_pgsz 0x00001000
xhci0: sc_maxslots 0x00000020
xhci0: sc_maxspbuf 0
xhci0: eventst: NORMAL_COMPLETION 0000000115822fc0 0xffff8000d291bfc0 1000
xhci0: dcbaa: NORMAL_COMPLETION 0000000115823000 0xffff8000d291c000 1000
xhci0: USBCMD 00000005
usb0 at xhci0: USB revision 2.0
ppb2 at pci0 dev 10 function 0: vendor 0x1022 product 0x9609 (rev. 0x00)
ppb2: PCI Express 2.0 <Root Port of PCI-E Root Complex> x1 @ 5.0Gb/s
ppb2: link is x1 @ 2.5Gb/s
pci3 at ppb2 bus 3
pci3: i/o space, memory space enabled, rd/line, wr/inv ok
re0 at pci3 dev 0 function 0: RealTek 8168/8111 PCIe Gigabit Ethernet (rev. 
0x06)
re0: interrupting at ioapic0 pin 18
re0: Ethernet address xx:xx:xx:xx:xx:xx
re0: using 256 tx descriptors
rgephy0 at re0 phy 7: RTL8169S/8110S/8211 1000BASE-T media interface, rev. 4
rgephy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 
1000baseT-FDX, auto
ahcisata0 at pci0 dev 17 function 0: vendor 0x1002 product 0x4391 (rev. 0x40)
ahcisata0: interrupting at ioapic0 pin 19
ahcisata0: 64-bit DMA
ahcisata0: AHCI revision 1.20, 6 ports, 32 slots, CAP 
0xf732ff05<PSC,SSC,PMD,SPM,ISS=0x3=Gen3,SCLO,SAL,SALP,SMPS,SSNTF,SNCQ,S64A>
atabus0 at ahcisata0 channel 0
atabus1 at ahcisata0 channel 1
atabus2 at ahcisata0 channel 2
atabus3 at ahcisata0 channel 3
atabus4 at ahcisata0 channel 4
atabus5 at ahcisata0 channel 5
ohci0 at pci0 dev 18 function 0: vendor 0x1002 product 0x4397 (rev. 0x00)
ohci0: interrupting at ioapic0 pin 18
ohci0: OHCI version 1.0, legacy support
usb1 at ohci0: USB revision 1.0
ehci0 at pci0 dev 18 function 2: vendor 0x1002 product 0x4396 (rev. 0x00)
ehci0: interrupting at ioapic0 pin 17
ehci0: dropped intr workaround enabled
ehci0: EHCI version 1.0
ehci0: companion controller, 5 ports each: ohci0
usb2 at ehci0: USB revision 2.0
ohci1 at pci0 dev 19 function 0: vendor 0x1002 product 0x4397 (rev. 0x00)
ohci1: interrupting at ioapic0 pin 18
ohci1: OHCI version 1.0, legacy support
usb3 at ohci1: USB revision 1.0
ehci1 at pci0 dev 19 function 2: vendor 0x1002 product 0x4396 (rev. 0x00)
ehci1: interrupting at ioapic0 pin 17
ehci1: dropped intr workaround enabled
ehci1: EHCI version 1.0
ehci1: companion controller, 5 ports each: ohci1
usb4 at ehci1: USB revision 2.0
piixpm0 at pci0 dev 20 function 0: vendor 0x1002 product 0x4385 (rev. 0x42)
piixpm0: polling (SB800)
iic0 at piixpm0: I2C bus
iic1 at piixpm0: I2C bus
iic2 at piixpm0: I2C bus
iic3 at piixpm0: I2C bus
hdaudio1 at pci0 dev 20 function 2: HD Audio Controller
hdaudio1: interrupting at ioapic0 pin 16
hdafg1 at hdaudio1: Realtek ALC892
hdafg1: DAC00 8ch: Speaker [Jack]
hdafg1: DAC01 2ch: HP Out [Jack]
hdafg1: DIG02 2ch: SPDIF Out [Jack]
hdafg1: DIG03 2ch: SPDIF Out [Built-In]
hdafg1: ADC04 2ch: Line In [Jack], Mic In [Jack]
hdafg1: ADC05 2ch: Mic In [Jack]
hdafg1: DIG-In06 2ch: SPDIF In [Jack]
hdafg1: 8ch/2ch 32000Hz 44100Hz 48000Hz 88200Hz 96000Hz 192000Hz PCM16 PCM20 
PCM24 AC3
audio0 at hdafg1: full duplex, playback, capture, independent
pcib0 at pci0 dev 20 function 3: vendor 0x1002 product 0x439d (rev. 0x40)
ppb3 at pci0 dev 20 function 4: vendor 0x1002 product 0x4384 (rev. 0x40)
pci4 at ppb3 bus 4
pci4: i/o space, memory space enabled
fwohci0 at pci4 dev 14 function 0: vendor 0x104c product 0x8024 (rev. 0x00)
fwohci0: interrupting at ioapic0 pin 22
fwohci0: OHCI version 1.10 (ROM=0)
fwohci0: No. of Isochronous channels is 4.
fwohci0: EUI64 00:19:8f:c8:00:1c:6f:65
fwohci0: Phy 1394a available S400, 3 ports.
fwohci0: Link S400, max_rec 2048 bytes.
ieee1394if0 at fwohci0: IEEE1394 bus
fwip0 at ieee1394if0: IP over IEEE1394
fwohci0: Initiate bus reset
ohci2 at pci0 dev 20 function 5: vendor 0x1002 product 0x4399 (rev. 0x00)
ohci2: interrupting at ioapic0 pin 18
ohci2: OHCI version 1.0, legacy support
usb5 at ohci2: USB revision 1.0
ppb4 at pci0 dev 21 function 0: vendor 0x1002 product 0x43a0 (rev. 0x00)
ppb4: PCI Express 2.0 <Root Port of PCI-E Root Complex> x1 @ 2.5Gb/s
pci5 at ppb4 bus 5
pci5: i/o space, memory space enabled, rd/line, wr/inv ok
jmide0 at pci5 dev 0 function 0: vendor 0x197b product 0x2368 (rev. 0x00)
jmide0: 1 PATA port
jmide0: interrupting at ioapic0 pin 17
jmide0: PCI IDE interface used
jmide0: bus-master DMA support present
jmide0: primary channel wired to native-PCI mode
jmide0: primary channel is PATA
atabus6 at jmide0 channel 0
jmide0: secondary channel wired to native-PCI mode
jmide0: secondary channel is unused
ppb5 at pci0 dev 21 function 1: vendor 0x1002 product 0x43a1 (rev. 0x00)
ppb5: PCI Express 2.0 <Root Port of PCI-E Root Complex> x1 @ 2.5Gb/s
pci6 at ppb5 bus 6
pci6: i/o space, memory space enabled, rd/line, wr/inv ok
ohci3 at pci0 dev 22 function 0: vendor 0x1002 product 0x4397 (rev. 0x00)
ohci3: interrupting at ioapic0 pin 18
ohci3: OHCI version 1.0, legacy support
usb6 at ohci3: USB revision 1.0
ehci2 at pci0 dev 22 function 2: vendor 0x1002 product 0x4396 (rev. 0x00)
ehci2: interrupting at ioapic0 pin 17
ehci2: dropped intr workaround enabled
ehci2: EHCI version 1.0
ehci2: companion controller, 4 ports each: ohci3
usb7 at ehci2: USB revision 2.0
pchb1 at pci0 dev 24 function 0: vendor 0x1022 product 0x1200 (rev. 0x00)
pchb2 at pci0 dev 24 function 1: vendor 0x1022 product 0x1201 (rev. 0x00)
pchb3 at pci0 dev 24 function 2: vendor 0x1022 product 0x1202 (rev. 0x00)
amdnb_misc0 at pci0 dev 24 function 3: AMD NB Misc Configuration
amdtemp0 at amdnb_misc0: AMD CPU Temperature Sensors (Family10h)
pchb4 at pci0 dev 24 function 4: vendor 0x1022 product 0x1204 (rev. 0x00)
isa0 at pcib0
fdc0 at isa0 port 0x3f0-0x3f7 irq 6 drq 2
acpicpu0 at cpu0: ACPI CPU
acpicpu0: C1: HLT, lat   0 us, pow     0 mW
acpicpu0: P0: FFH, lat   4 us, pow 26460 mW, 3000 MHz
acpicpu0: P1: FFH, lat   4 us, pow 18590 mW, 2300 MHz
acpicpu0: P2: FFH, lat   4 us, pow 15360 mW, 1800 MHz
acpicpu0: P3: FFH, lat   4 us, pow  8715 mW,  800 MHz
acpicpu1 at cpu1: ACPI CPU
acpicpu2 at cpu2: ACPI CPU
acpicpu3 at cpu3: ACPI CPU
fwohci0: BUS reset
fwohci0: node_id=0xc800ffc0, gen=1, CYCLEMASTER mode
ieee1394if0: 1 nodes, maxhop <= 0 cable IRM irm(0) (me)
ieee1394if0: bus manager 0
xhci0: port 3 status change
timecounter: Timecounter "clockinterrupt" frequency 100 Hz quality 0
timecounter: Timecounter "TSC" frequency 3013945600 Hz quality 3000
xhci0: xhci_new_device up 0xfffffe811575c710 portno 0
xhci0: xhci_new_device hub 0xfffffe8115a5f008
xhci0: xhci_new_device hub 0x0
xhci0: xhci_new_device rhport 2
xhci0: xhci_open addr 0 depth 0 port 0 speed 3
uhub0 at usb0: NetBSD xHCI Root Hub, class 9/0, rev 2.00/1.00, addr 0
uhub0: 2 ports with 2 removable, self powered
xhci0: xhci_open addr 0 depth 0 port 0 speed 3
#
# Hang here until keypress
#
IPsec: Initialized Security Association Processing.
uhub1 at usb1: vendor 0x1002 OHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub1: 5 ports with 5 removable, self powered
uhub2 at usb2: vendor 0x1002 EHCI root hub, class 9/0, rev 2.00/1.00, addr 1
uhub2: 5 ports with 5 removable, self powered
uhub3 at usb3: vendor 0x1002 OHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub3: 5 ports with 5 removable, self powered
uhub4 at usb4: vendor 0x1002 EHCI root hub, class 9/0, rev 2.00/1.00, addr 1
uhub4: 5 ports with 5 removable, self powered
uhub5 at usb5: vendor 0x1002 OHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub5: 2 ports with 2 removable, self powered
uhub6 at usb6: vendor 0x1002 OHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub6: 4 ports with 4 removable, self powered
uhub7 at usb7: vendor 0x1002 EHCI root hub, class 9/0, rev 2.00/1.00, addr 1
uhub7: 4 ports with 4 removable, self powered
ahcisata0 port 0: device present, speed: 3.0Gb/s
ahcisata0 port 1: device present, speed: 1.5Gb/s
ahcisata0 port 4: device present, speed: 1.5Gb/s
xhci0: root_hub 0x0
fd0 at fdc0 drive 0: 1.44MB, 80 cyl, 2 head, 18 sec
xhci0: port 3 status change
xhci0: hs port 1 status change
ehci0: handing over full speed device on port 1 to ohci0
xhci0: xhci_new_device up 0xfffffe81157934c0 portno 1
xhci0: xhci_new_device hub 0xfffffe8115b81108
xhci0: xhci_new_device hub 0xfffffe8115a5f008
xhci0: xhci_new_device hub 0x0
xhci0: xhci_new_device rhport 3
xhci0: xhci_open addr 0 depth 1 port 1 speed 3
xhci0: xhci_do_command input: 0x0000000000000000 0x00000000 0x00002400
xhci0: xhci_do_command output: 0x0000000115818000 0x01000000 0x01008401
xhci0: dcbaa 0xffff8000d291c008 dc 0000000115c2c000 slot 1
xhci0: xhci_do_command input: 0x0000000115c2e000 0x00000000 0x01002c00
xhci0: xhci_do_command output: 0x0000000115818010 0x01000000 0x01008401
xhci0: xhci_new_device device address 1
wd0 at atabus0 drive 0
wd0: <WDC WD6401AALS-00J7B0>
wd0: drive supports 16-sector PIO transfers, LBA48 addressing
wd0: 596 GB, 1240341 cyl, 16 head, 63 sec, 512 bytes/sect x 1250263728 sectors
xhci0: xhci_new_device bMaxPacketSize 64
xhci0: xhci_update_ep0_mps
xhci0: xhci_do_command input: 0x0000000115c2e000 0x00000000 0x01003400
xhci0: xhci_do_command output: 0x0000000115818020 0x01000000 0x01008401
xhci0: xhci_open addr 1 depth 1 port 1 speed 3
umass0 at uhub0 port 1 configuration 1 interface 0
umass0: HP v125w, rev 2.00/1.00, addr 1
umass0: using SCSI over Bulk-Only
xhci0: xhci_open addr 1 depth 1 port 1 speed 3
xhci0: xhci_configure_endpoint dci 4 (0x2)
xhci0: xhci_do_command input: 0x0000000115c2e000 0x00000000 0x01003000
xhci0: xhci_do_command output: 0x0000000115818030 0x01000000 0x01008401
xhci0: xhci_open addr 1 depth 1 port 1 speed 3
xhci0: xhci_configure_endpoint dci 3 (0x81)
xhci0: xhci_do_command input: 0x0000000115c2e000 0x00000000 0x01003000
xhci0: xhci_do_command output: 0x0000000115818040 0x01000000 0x01008401
scsibus0 at umass0: 2 targets, 1 lun per target
sd0 at scsibus0 target 0 lun 0: <hp, v125w, 1.00> disk removable
wd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 6 (Ultra/133)
wd0(ahcisata0:0:0): using PIO mode 4, DMA mode 2, Ultra-DMA mode 6 (Ultra/133) 
(using DMA)
wd1 at atabus1 drive 0
sd0: fabricating a geometry
sd0: 3819 MB, 3819 cyl, 64 head, 32 sec, 512 bytes/sect x 7823296 sectors
sd0: fabricating a geometry
wd1: <HITACHI HTS722016K9SA00>
wd1: drive supports 16-sector PIO transfers, LBA48 addressing
wd1: 149 GB, 310101 cyl, 16 head, 63 sec, 512 bytes/sect x 312581808 sectors
wd1: GPT GUID: 15dc2ee4-a0ce-4749-a8b8-b12f351ace02
wd1: bad GPT partition array CRC
wd1: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 6 (Ultra/133)
wd1(ahcisata0:1:0): using PIO mode 4, DMA mode 2, Ultra-DMA mode 6 (Ultra/133) 
(using DMA)
atapibus0 at atabus4: 1 targets
cd0 at atapibus0 drive 0: <ASUS    DRW-24B1ST, , 1.01> cdrom removable
cd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 5 (Ultra/100)
cd0(ahcisata0:4:0): using PIO mode 4, DMA mode 2, Ultra-DMA mode 5 (Ultra/100) 
(using DMA)
ehci0: handing over full speed device on port 2 to ohci0
uhub8 at uhub4 port 1: vendor 0x05e3 USB2.0 Hub, class 9/0, rev 2.00/77.63, 
addr 2
uhub8: single transaction translator
uhub8: 4 ports with 4 removable, self powered
uscanner0 at uhub1 port 1
uscanner0: Hewlett-Packard HP ScanJet 5200C, rev 1.00/1.00, addr 2
uhub9 at uhub2 port 5: vendor 0x05e3 USB2.0 Hub, class 9/0, rev 2.00/7.02, addr 
2
uhub9: single transaction translator
uhub9: 4 ports with 4 removable, self powered
uhub10 at uhub8 port 4: vendor 0x05e3 USB2.0 Hub, class 9/0, rev 2.00/77.63, 
addr 3
uhub10: single transaction translator
uhub10: 4 ports with 4 removable, self powered
uhidev0 at uhub9 port 3 configuration 1 interface 0
uhidev0: vendor 0x0461 USB Optical Mouse, rev 2.00/2.00, addr 3, iclass 3/1
ums0 at uhidev0: 3 buttons, W and Z dirs
wsmouse0 at ums0 mux 0
umass1 at uhub10 port 1 configuration 1 interface 0
umass1: Kingston FCR-HS219/1 Mobile Reader, rev 2.00/97.38, addr 4
umass1: using SCSI over Bulk-Only
scsibus1 at umass1: 2 targets, 4 luns per target
sd1 at scsibus1 target 0 lun 0: <Kingston, FCR-HS219/1, 9738> disk removable
sd1: drive offline
sd2 at scsibus1 target 0 lun 1: <Kingston, FCR-HS219/1, 9738> disk removable
sd2: drive offline
sd3 at scsibus1 target 0 lun 2: <Kingston, FCR-HS219/1, 9738> disk removable
sd3: drive offline
sd4 at scsibus1 target 0 lun 3: <Kingston, FCR-HS219/1, 9738> disk removable
sd4: drive offline
uhidev1 at uhub9 port 4 configuration 1 interface 0
uhidev1: Unicomp Endura Keyboard, rev 1.10/2.0c, addr 4, iclass 3/1
ukbd0 at uhidev1: 8 modifier keys, 6 key codes
umass2 at uhub10 port 4 configuration 1 interface 0
umass2: Sunplus Innovation Technology. USB to Serial-ATA bridge, rev 2.00/1.0f, 
addr 5
umass2: using SCSI over Bulk-Only
scsibus2 at umass2: 2 targets, 1 lun per target
sd5 at scsibus2 target 0 lun 0: <SPIF301, USB2SATA Bridge, 0108> disk removable
sd5: drive offline
wskbd1 at ukbd0 mux 1
wskbd1: connecting to wsdisplay0
Kernelized RAIDframe activated
pad0: outputs: 44100Hz, 16-bit, stereo
audio1 at pad0: half duplex, playback, capture
boot device: wd1
root on wd1a dumps on wd1b
root file system type: ffs
wsdisplay0: screen 1 added (80x25, vt100 emulation)
wsdisplay0: screen 2 added (80x25, vt100 emulation)
wsdisplay0: screen 3 added (80x25, vt100 emulation)
wsdisplay0: screen 4 added (80x25, vt100 emulation)