Bug 208959 - UHCI interrupt storm with "uhci_interrupt: uhci_interrupt: host controller halted"
Summary: UHCI interrupt storm with "uhci_interrupt: uhci_interrupt: host controller ha...
Status: New
Alias: None
Product: Base System
Classification: Unclassified
Component: usb (show other bugs)
Version: 10.3-RELEASE
Hardware: amd64 Any
: --- Affects Only Me
Assignee: freebsd-usb (Nobody)
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2016-04-21 16:07 UTC by Jamie Ivanov
Modified: 2016-08-08 17:25 UTC (History)
1 user (show)

See Also:


Attachments
dmesg.today (12.89 KB, text/plain)
2016-04-21 16:07 UTC, Jamie Ivanov
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Jamie Ivanov 2016-04-21 16:07:43 UTC
Created attachment 169528 [details]
dmesg.today

After noticing unusual interrupt load, I did some investigating and ended up both confused and concerned. The only USB device plugged in to the server is a keyboard but it's plugged in to a different USB device than the one which is hogging the interrupts.

I will continue looking into this but otherwise feel free to chime in with any additional information you would like me to collect. 

$ uname -a
FreeBSD irony 10.3-RELEASE FreeBSD 10.3-RELEASE #0 r297264: Fri Mar 25 02:10:02 UTC 2016     root@releng1.nyi.freebsd.org:/usr/obj/usr/src/sys/GENERIC  amd64


$ vmstat -i
interrupt                          total       rate
irq1: atkbd0                           6          0
irq14: ata0                          175          0
irq17: uhci0 ehci0                    29          0
irq18: uhci2                 85293579481     263953
cpu0:timer                      14857259         45
irq256: em0                    210064444        650
irq258: mpt0                    20452356         63
cpu5:timer                      15795381         48
cpu7:timer                     364040490       1126
cpu1:timer                      27906242         86
cpu3:timer                       8760608         27
cpu2:timer                       7602596         23
cpu6:timer                      15839120         49
cpu4:timer                      15563089         48
Total                        85994461276     266122


$ systat -v
2 users    Load  0.62  0.60  0.53                  Apr 21 15:52

Mem:KB    REAL            VIRTUAL                       VN PAGER   SWAP PAGER
        Tot   Share      Tot    Share    Free           in   out     in   out
Act  193620   26768  2695468    71372  490820  count
All  213368   34804  2913604   205836          pages
Proc:                                                            Interrupts
  r   p   d   s   w   Csw  Trp  Sys  Int  Sof  Flt        ioflt  272k total
            127   3  534k 6826 3588 267k   64 2127        cow         atkbd0 1
                                                     2127 zfod        ata0 14
12.5%Sys   3.1%Intr  0.0%User  0.0%Nice 84.4%Idle         ozfod       uhci0 ehci
|    |    |    |    |    |    |    |    |    |           %ozfod  269k uhci2 18
======++                                                  daefr  1080 cpu0:timer
                                           dtbuf          prcfr   127 em0 256
Namei     Name-cache   Dir-cache    350179 desvn          totfr       mpt0 258
   Calls    hits   %    hits   %    122969 numvn          react    64 cpu5:timer
       8       8 100                 87543 frevn          pdwak  1175 cpu7:timer
                                                          pdpgs       cpu1:timer
Disks  ada0   da0   da1   da2   da3   da4   da5           intrn       cpu3:timer
KB/t   0.00  0.00  0.00  0.00  0.00  0.00  0.00  15174496 wire        cpu2:timer
tps       0     0     0     0     0     0     0      5852 act      64 cpu6:timer
MB/s   0.00  0.00  0.00  0.00  0.00  0.00  0.00    629748 inact    64 cpu4:timer
%busy     0     0     0     0     0     0     0           cache
                                                   490904 free 
                                                          buf


$ sudo sysctl hw.usb.uhci.debug=15
$ sudo tail -f /var/log/messages
...
Apr 21 14:26:11 irony kernel: uhci_dump_qh: QH(0xfffffe046844f000) at 0x07a4f002: h_next=0x07a50002 e_next=0x00000001
Apr 21 14:26:11 irony kernel: uhci_dump_qh: QH(0xfffffe0468450000) at 0x07a50002: h_next=0x07a51002 e_next=0x00000001
Apr 21 14:26:11 irony kernel: uhci_dump_qh: QH(0xfffffe0468451000) at 0x07a51002: h_next=0x07a52002 e_next=0x00000001
Apr 21 14:26:11 irony kernel: uhci_dump_qh: QH(0xfffffe0468452000) at 0x07a52002: h_next=0x00000001 e_next=0x07a53000
Apr 21 14:26:11 irony kernel: uhci_interrupt: uhci_interrupt: host controller halted
Apr 21 14:26:11 irony kernel: uhci_dumpregs: usbus2 regs: cmd=0080, sts=0020, intr=000f, frnum=01b6, flbase=07a4e6d8, sof=0040, portsc1=0080, portsc2=0080
...
# ^^^ spamming
$ sudo sysctl hw.usb.uhci.debug=0
hw.usb.uhci.debug: 15 -> 0


$ sudo sysctl hw.usb.debug=15; tail -f /var/log/messages
...
Apr 21 15:22:41 irony kernel: usbd_do_request_flags: udev=0xfffff80030eb4000 bmRequestType=0xa3 bRequest=0x00 wValue=0x0000 wIndex=0x0001 wLength=0x0004
Apr 21 15:22:41 irony kernel: usbd_do_request_flags: Handle Request function is set
...
# ^^^ spamming
$ sysctl hw.usb.debug=0
hw.usb.debug: 15 -> 0


$ sudo sysctl hw.usb.ehci.debug=15; tail -f /var/log/messages
hw.usb.ehci.debug: 0 -> 15
...
Apr 21 15:29:19 irony kernel: ehci_set_hw_power: 
Apr 21 15:29:19 irony kernel: ehci_roothub_exec: type=0xa3 request=0x00 wLen=0x0004 wValue=0x0000 wIndex=0x0001
Apr 21 15:29:19 irony kernel: ehci_roothub_exec: get port status i=1
Apr 21 15:29:19 irony kernel: ehci_roothub_exec: port status=0x1000
Apr 21 15:29:19 irony kernel: ehci_roothub_exec: type=0xa3 request=0x00 wLen=0x0004 wValue=0x0000 wIndex=0x0002
Apr 21 15:29:19 irony kernel: ehci_roothub_exec: get port status i=2
Apr 21 15:29:19 irony kernel: ehci_roothub_exec: port status=0x3000
Apr 21 15:29:19 irony kernel: ehci_roothub_exec: type=0xa3 request=0x00 wLen=0x0004 wValue=0x0000 wIndex=0x0003
Apr 21 15:29:19 irony kernel: ehci_roothub_exec: get port status i=3
Apr 21 15:29:19 irony kernel: ehci_roothub_exec: port status=0x1000
Apr 21 15:29:19 irony kernel: ehci_roothub_exec: type=0xa3 request=0x00 wLen=0x0004 wValue=0x0000 wIndex=0x0004
Apr 21 15:29:19 irony kernel: ehci_roothub_exec: get port status i=4
Apr 21 15:29:19 irony kernel: ehci_roothub_exec: port status=0x1000
Apr 21 15:29:19 irony kernel: ehci_roothub_exec: type=0xa3 request=0x00 wLen=0x0004 wValue=0x0000 wIndex=0x0005
Apr 21 15:29:19 irony kernel: ehci_roothub_exec: get port status i=5
Apr 21 15:29:19 irony kernel: ehci_roothub_exec: port status=0x1000
Apr 21 15:29:19 irony kernel: ehci_roothub_exec: type=0xa3 request=0x00 wLen=0x0004 wValue=0x0000 wIndex=0x0006
Apr 21 15:29:19 irony kernel: ehci_roothub_exec: get port status i=6
Apr 21 15:29:19 irony kernel: ehci_roothub_exec: port status=0x1000
...
# ^^^ spamming
$ sysctl hw.usb.ehci.debug=0
hw.usb.ehci.debug: 15 -> 0


$ sudo usbconfig 
ugen2.1: <UHCI root HUB Intel> at usbus2, cfg=0 md=HOST spd=FULL (12Mbps) pwr=SAVE (0mA)
ugen0.1: <UHCI root HUB Intel> at usbus0, cfg=0 md=HOST spd=FULL (12Mbps) pwr=SAVE (0mA)
ugen1.1: <UHCI root HUB Intel> at usbus1, cfg=0 md=HOST spd=FULL (12Mbps) pwr=SAVE (0mA)
ugen3.1: <EHCI root HUB Intel> at usbus3, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=SAVE (0mA)
ugen0.2: <Wired Keyboard 600 Microsoft> at usbus0, cfg=0 md=HOST spd=LOW (1.5Mbps) pwr=ON (100mA)


$ sudo usbconfig -d ugen0.2 power_save
$ sudo usbconfig                      
ugen2.1: <UHCI root HUB Intel> at usbus2, cfg=0 md=HOST spd=FULL (12Mbps) pwr=SAVE (0mA)
ugen0.1: <UHCI root HUB Intel> at usbus0, cfg=0 md=HOST spd=FULL (12Mbps) pwr=SAVE (0mA)
ugen1.1: <UHCI root HUB Intel> at usbus1, cfg=0 md=HOST spd=FULL (12Mbps) pwr=SAVE (0mA)
ugen3.1: <EHCI root HUB Intel> at usbus3, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=SAVE (0mA)
ugen0.2: <Wired Keyboard 600 Microsoft> at usbus0, cfg=0 md=HOST spd=LOW (1.5Mbps) pwr=SAVE (100mA)


$ sysctl hw.usb
hw.usb.uhid.debug: 0
hw.usb.ukbd.pollrate: 0
hw.usb.ukbd.no_leds: 0
hw.usb.ukbd.debug: 0
hw.usb.full_ddesc: 0
hw.usb.no_cs_fail: 0
hw.usb.proc.debug: 0
hw.usb.disable_port_power: 0
hw.usb.disable_enumeration: 0
hw.usb.power_timeout: 30
hw.usb.uhub.debug: 0
hw.usb.ugen.debug: 0
hw.usb.usb_lang_mask: 255
hw.usb.usb_lang_id: 9
hw.usb.template: 0
hw.usb.dev.debug: 0
hw.usb.timings.extra_power_up_time: 20
hw.usb.timings.resume_recovery: 50
hw.usb.timings.resume_wait: 50
hw.usb.timings.resume_delay: 250
hw.usb.timings.set_address_settle: 10
hw.usb.timings.port_resume_delay: 40
hw.usb.timings.port_powerup_delay: 300
hw.usb.timings.port_reset_recovery: 250
hw.usb.timings.port_root_reset_delay: 250
hw.usb.timings.port_reset_delay: 50
hw.usb.debug: 0
hw.usb.umass.throttle: 0
hw.usb.umass.debug: 0
hw.usb.no_shutdown_wait: 0
hw.usb.no_suspend_wait: 0
hw.usb.no_boot_wait: 0
hw.usb.ctrl.debug: 0
hw.usb.xhci.dma32: 0
hw.usb.xhci.use_polling: 0
hw.usb.xhci.xhci_port_route: 0
hw.usb.xhci.debug: 0
hw.usb.xhci.streams: 0
hw.usb.uhci.loop: 0
hw.usb.uhci.debug: 0
hw.usb.ohci.debug: 0
hw.usb.ehci.lostintrbug: 0
hw.usb.ehci.iaadbug: 1
hw.usb.ehci.no_hs: 0
hw.usb.ehci.debug: 0


# /var/log/dmesg.today
...
uhci0: <Intel 631XESB/632XESB/3100 USB controller USB-1> port 0x1800-0x181f irq 17 at device 29.0 on pci0 
usbus0 on uhci0
uhci1: <Intel 631XESB/632XESB/3100 USB controller USB-2> port 0x1820-0x183f irq 19 at device 29.1 on pci0
usbus1 on uhci1
uhci2: <Intel 631XESB/632XESB/3100 USB controller USB-3> port 0x1840-0x185f irq 18 at device 29.2 on pci0
usbus2 on uhci2
ehci0: <Intel 63XXESB USB 2.0 controller> mem 0xd8600400-0xd86007ff irq 17 at device 29.7 on pci0
usbus3: EHCI version 1.0
usbus3 on ehci0
...
usbus0: 12Mbps Full Speed USB v1.0
usbus2: 12Mbps Full Speed USB v1.0
usbus1: 12Mbps Full Speed USB v1.0
usbus3: 480Mbps High Speed USB v2.0
random: unblocking device.
ugen2.1: <Intel> at usbus2
ugen0.1: <Intel> at usbus0
uhub0: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus2
uhub1: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus0
ugen1.1: <Intel> at usbus1
ugen3.1: <Intel> at usbus3
uhub2: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus1
uhub3: <Intel EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus3
...
Timecounter "TSC" frequency 2000112372 Hz quality 1000
uhub0: 2 ports with 2 removable, self powered
uhub1: 2 ports with 2 removable, self powered
uhub2: 2 ports with 2 removable, self powered
Root mount waiting for: usbus3
Root mount waiting for: usbus3
uhub3: 6 ports with 6 removable, self powered
ugen0.2: <Microsoft> at usbus0
ukbd0: <Microsoft Wired Keyboard 600, class 0/0, rev 1.10/1.10, addr 2> on usbus0
kbd2 at ukbd0
uhid0: <Microsoft Wired Keyboard 600, class 0/0, rev 1.10/1.10, addr 2> on usbus0
...
pid 10821 (gcj-dbtool), uid 0: exited on signal 6 (core dumped)
Comment 1 Hans Petter Selasky freebsd_committer 2016-04-21 16:24:46 UTC
Can you set the UHCI debug to 16 and find out which interrupts are triggered?

--HPS
Comment 2 Jamie Ivanov 2016-04-21 20:39:29 UTC
I didn't let this run very long but this is what I kicked-up:

$ sudo sysctl hw.usb.uhci.debug=16; tail -f /var/log/messages
hw.usb.uhci.debug: 0 -> 16
Apr 21 20:28:12 irony kernel: uhci_interrupt: real interrupt
Apr 21 20:28:12 irony kernel: uhci_dumpregs: usbus2 regs: cmd=0080, sts=0020, intr=000f, frnum=01b6, flbase=07a4e6d8, sof=0040, portsc1=0080, portsc2=0080
Apr 21 20:28:12 irony kernel: uhci_interrupt: uhci_interrupt: host controller halted
Apr 21 20:28:12 irony kernel: uhci_dumpregs: usbus2 regs: cmd=0080, sts=0020, intr=000f, frnum=01b6, flbase=07a4e6d8, sof=0040, portsc1=0080, portsc2=0080
Apr 21 20:28:12 irony kernel: uhci_dump_qh: QH(0xfffffe046844f000) at 0x07a4f002: h_next=0x07a50002 e_next=0x00000001
Apr 21 20:28:12 irony kernel: uhci_dump_qh: QH(0xfffffe0468450000) at 0x07a50002: h_next=0x07a51002 e_next=0x00000001
Apr 21 20:28:12 irony kernel: uhci_dump_qh: QH(0xfffffe0468451000) at 0x07a51002: h_next=0x07a52002 e_next=0x00000001
Apr 21 20:28:12 irony kernel: uhci_dump_qh: QH(0xfffffe0468452000) at 0x07a52002: h_next=0x00000001 e_next=0x07a53000
# ^^^ spamming
...
Apr 21 20:28:12 irony kernel: uhci_interrupt: real interrupt
Apr 21 20:28:12 irony kernel: uhci_dumpregs: usbus2 regs: cmd=0080, sts=0020, intr=000f, frnum=01b6, flbase=07a4e6d8, sof=0040, portsc1=0080, portsc2=0080
Apr 21 20:28:12 irony kernel: uhci_interrupt: uhci_interrupt: host controller halted
Apr 21 20:28:12 irony kernel: uhci_dumpregs: usbus2 regs: cmd=0080, sts=0020, intr=000f, frnum=01b6, flbase=07a4e6d8, sof=0040, portsc1=0080, portsc2=0080
Apr 21 20:28:12 irony kernel: uhci_dump_qh: QH(0xfffffe046844f000) at 0x07a4f002: h_next=0x07a50002 e_next=0x00000001
Apr 21 20:28:12 irony kernel: uhci_dump_qh: QH(0xfffffe0468450000) at 0x07a50002: h_next=0x07a51002 e_next=0x00000001
Apr 21 20:28:12 irony kernel: uhci_dump_qh: QH(0xfffffe0468451000) at 0x07a51002: h_next=0x07a52002 e_next=0x00000001
Apr 21 20:28:12 irony kernel: uhci_dump_qh: QH(0xfffffe0468452000) at 0x07a52002: h_next=0x00000001 e_next=0x07a53000
Apr 21 20:28:12 irony kernel: uhci_interrupt: real interrupt
Apr 21 20:28:12 irony kernel: uhci_set_hw_power: 
Apr 21 20:28:12 irony kernel: uhci_set_hw_power: 
Apr 21 20:28:12 irony kernel: uhci_dumpregs: usbus2 regs: cmd=0080, sts=0020, intr=000f, frnum=01b6, flbase=07a4e6d8, sof=0040, portsc1=0080, portsc2=0080
Apr 21 20:28:12 irony kernel: uhci_set_hw_power: Some USB transfer is active on unit 0.
Apr 21 20:28:12 irony kernel: uhci_interrupt: uhci_interrupt: host controller halted
Apr 21 20:28:12 irony kernel: uhci_restart: Already started
Apr 21 20:28:12 irony kernel: uhci_dumpregs: usbus2 regs: cmd=0080, sts=0020, intr=000f, frnum=01b6, flbase=07a4e6d8, sof=0040, portsc1=0080, portsc2=0080
Apr 21 20:28:12 irony kernel: uhci_roothub_exec: type=0xa3 request=0x00 wLen=0x0004 wValue=0x0000 wIndex=0x0001
Apr 21 20:28:12 irony kernel: uhci_dump_qh: QH(0xfffffe046844f000) at 0x07a4f002: h_next=0x07a50002 e_next=0x00000001
Apr 21 20:28:12 irony kernel: uhci_roothub_exec: type=0xa3 request=0x00 wLen=0x0004 wValue=0x0000 wIndex=0x0002
Apr 21 20:28:12 irony kernel: uhci_dump_qh: QH(0xfffffe0468450000) at 0x07a50002: h_next=0x07a51002 e_next=0x00000001
Apr 21 20:28:12 irony kernel: uhci_dump_qh: QH(0xfffffe0468451000) at 0x07a51002: h_next=0x07a52002 e_next=0x00000001
Apr 21 20:28:12 irony kernel: uhci_set_hw_power: Power save on unit 1.
Apr 21 20:28:12 irony kernel: uhci_dump_qh: QH(0xfffffe0468452000) at 0x07a52002: h_next=0x00000001 e_next=0x07a53000
Apr 21 20:28:12 irony kernel: uhci_roothub_exec: type=0xa3 request=0x00 wLen=0x0004 wValue=0x0000 wIndex=0x0001
Apr 21 20:28:12 irony kernel: uhci_interrupt: real interrupt
Apr 21 20:28:12 irony kernel: uhci_set_hw_power: 
Apr 21 20:28:12 irony kernel: uhci_roothub_exec: type=0xa3 request=0x00 wLen=0x0004 wValue=0x0000 wIndex=0x0002
Apr 21 20:28:12 irony kernel: uhci_dumpregs: usbus2 regs: cmd=0080, sts=0020, intr=000f, frnum=01b6, flbase=07a4e6d8, sof=0040, portsc1=0080, portsc2=0080
Apr 21 20:28:12 irony kernel: uhci_interrupt: uhci_interrupt: host controller halted
Apr 21 20:28:12 irony kernel: uhci_dumpregs: usbus2 regs: cmd=0080, sts=0020, intr=000f, frnum=01b6, flbase=07a4e6d8, sof=0040, portsc1=0080, portsc2=0080
Apr 21 20:28:12 irony kernel: uhci_dump_qh: QH(0xfffffe046844f000) at 0x07a4f002: h_next=0x07a50002 e_next=0x00000001
Apr 21 20:28:12 irony kernel: uhci_dump_qh: QH(0xfffffe0468450000) at 0x07a50002: h_next=0x07a51002 e_next=0x00000001
Apr 21 20:28:12 irony kernel: uhci_dump_qh: QH(0xfffffe0468451000) at 0x07a51002: h_next=0x07a52002 e_next=0x00000001
Apr 21 20:28:12 irony kernel: uhci_dump_qh: QH(0xfffffe0468452000) at 0x07a52002: h_next=0x00000001 e_next=0x07a53000
Apr 21 20:28:12 irony kernel: uhci_set_hw_power: Power save on unit 2.
Apr 21 20:28:12 irony kernel: uhci_interrupt: real interrupt
Apr 21 20:28:12 irony kernel: uhci_dumpregs: usbus2 regs: cmd=0080, sts=0020, intr=000f, frnum=01b6, flbase=07a4e6d8, sof=0040, portsc1=0080, portsc2=0080
Apr 21 20:28:12 irony kernel: uhci_interrupt: uhci_interrupt: host controller halted
Apr 21 20:28:12 irony kernel: uhci_dumpregs: usbus2 regs: cmd=0080, sts=0020, intr=000f, frnum=01b6, flbase=07a4e6d8, sof=0040, portsc1=0080, portsc2=0080
Apr 21 20:28:12 irony kernel: uhci_dump_qh: QH(0xfffffe046844f000) at 0x07a4f002: h_next=0x07a50002 e_next=0x00000001
Apr 21 20:28:12 irony kernel: uhci_dump_qh: QH(0xfffffe0468450000) at 0x07a50002: h_next=0x07a51002 e_next=0x00000001
Apr 21 20:28:12 irony kernel: uhci_dump_qh: QH(0xfffffe0468451000) at 0x07a51002: h_next=0x07a52002 e_next=0x00000001
Apr 21 20:28:12 irony kernel: uhci_dump_qh: QH(0xfffffe0468452000) at 0x07a52002: h_next=0x00000001 e_next=0x07a53000
Apr 21 20:28:12 irony kernel: uhci_roothub_exec: type=0xa3 request=0x00 wLen=0x0004 wValue=0x0000 wIndex=0x0001
# ^^^ spamming again
$ sudo sysctl hw.usb.uhci.debug=0
hw.usb.uhci.debug: 16 -> 0

I plan on letting this run longer and parsing unique messages out of it to see if there is anything that's more than meets the eye.

-JI
Comment 3 Hans Petter Selasky freebsd_committer 2016-04-22 06:03:22 UTC
In sys/dev/usb/controller/uhci.c try to change:

        /* get acknowledge bits */
        status &= (UHCI_STS_USBINT |
            UHCI_STS_USBEI |
            UHCI_STS_RD |
            UHCI_STS_HSE |
            UHCI_STS_HCPE |
            UHCI_STS_HCH);

Into:

        /* get acknowledge bits */
        status &= (UHCI_STS_USBINT |
            UHCI_STS_USBEI |
            UHCI_STS_RD |
            UHCI_STS_HSE |
            UHCI_STS_HCPE);

I'm not sure if it helps.

--HPS
Comment 4 Jamie Ivanov 2016-08-08 17:25:52 UTC
Bueller?