[Bug 208959] UHCI interrupt storm with "uhci_interrupt: uhci_interrupt: host controller halted"
bugzilla-noreply at freebsd.org
bugzilla-noreply at freebsd.org
Thu Apr 21 16:07:44 UTC 2016
https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=208959
Bug ID: 208959
Summary: UHCI interrupt storm with "uhci_interrupt:
uhci_interrupt: host controller halted"
Product: Base System
Version: 10.3-RELEASE
Hardware: amd64
OS: Any
Status: New
Severity: Affects Only Me
Priority: ---
Component: usb
Assignee: freebsd-usb at FreeBSD.org
Reporter: jamie.ivanov at gmail.com
CC: freebsd-amd64 at FreeBSD.org
CC: freebsd-amd64 at FreeBSD.org
Created attachment 169528
--> https://bugs.freebsd.org/bugzilla/attachment.cgi?id=169528&action=edit
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 at 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)
--
You are receiving this mail because:
You are on the CC list for the bug.
More information about the freebsd-amd64
mailing list