Date: Thu, 21 Apr 2016 16:07:43 +0000 From: bugzilla-noreply@freebsd.org To: freebsd-amd64@FreeBSD.org Subject: [Bug 208959] UHCI interrupt storm with "uhci_interrupt: uhci_interrupt: host controller halted" Message-ID: <bug-208959-6@https.bugs.freebsd.org/bugzilla/>
next in thread | raw e-mail | index | archive | help
https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=3D208959 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@FreeBSD.org Reporter: jamie.ivanov@gmail.com CC: freebsd-amd64@FreeBSD.org CC: freebsd-amd64@FreeBSD.org Created attachment 169528 --> https://bugs.freebsd.org/bugzilla/attachment.cgi?id=3D169528&action= =3Dedit 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 i= s 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.=20 $ uname -a FreeBSD irony 10.3-RELEASE FreeBSD 10.3-RELEASE #0 r297264: Fri Mar 25 02:1= 0:02 UTC 2016 root@releng1.nyi.freebsd.org:/usr/obj/usr/src/sys/GENERIC amd= 64 $ 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 PAG= ER Tot Share Tot Share Free in out in o= ut 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 atkbd= 0 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 =3D=3D=3D=3D=3D=3D++ daefr= 1080 cpu0:timer dtbuf prcfr 127 em0 2= 56 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=20=20=20=20= =20=20 cpu1:timer Disks ada0 da0 da1 da2 da3 da4 da5 intrn=20=20=20=20= =20=20 cpu3:timer KB/t 0.00 0.00 0.00 0.00 0.00 0.00 0.00 15174496 wire=20=20=20=20= =20=20=20 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=20 buf $ sudo sysctl hw.usb.uhci.debug=3D15 $ sudo tail -f /var/log/messages ... Apr 21 14:26:11 irony kernel: uhci_dump_qh: QH(0xfffffe046844f000) at 0x07a4f002: h_next=3D0x07a50002 e_next=3D0x00000001 Apr 21 14:26:11 irony kernel: uhci_dump_qh: QH(0xfffffe0468450000) at 0x07a50002: h_next=3D0x07a51002 e_next=3D0x00000001 Apr 21 14:26:11 irony kernel: uhci_dump_qh: QH(0xfffffe0468451000) at 0x07a51002: h_next=3D0x07a52002 e_next=3D0x00000001 Apr 21 14:26:11 irony kernel: uhci_dump_qh: QH(0xfffffe0468452000) at 0x07a52002: h_next=3D0x00000001 e_next=3D0x07a53000 Apr 21 14:26:11 irony kernel: uhci_interrupt: uhci_interrupt: host controll= er halted Apr 21 14:26:11 irony kernel: uhci_dumpregs: usbus2 regs: cmd=3D0080, sts= =3D0020, intr=3D000f, frnum=3D01b6, flbase=3D07a4e6d8, sof=3D0040, portsc1=3D0080, p= ortsc2=3D0080 ... # ^^^ spamming $ sudo sysctl hw.usb.uhci.debug=3D0 hw.usb.uhci.debug: 15 -> 0 $ sudo sysctl hw.usb.debug=3D15; tail -f /var/log/messages ... Apr 21 15:22:41 irony kernel: usbd_do_request_flags: udev=3D0xfffff80030eb4= 000 bmRequestType=3D0xa3 bRequest=3D0x00 wValue=3D0x0000 wIndex=3D0x0001 wLengt= h=3D0x0004 Apr 21 15:22:41 irony kernel: usbd_do_request_flags: Handle Request functio= n is set ... # ^^^ spamming $ sysctl hw.usb.debug=3D0 hw.usb.debug: 15 -> 0 $ sudo sysctl hw.usb.ehci.debug=3D15; tail -f /var/log/messages hw.usb.ehci.debug: 0 -> 15 ... Apr 21 15:29:19 irony kernel: ehci_set_hw_power:=20 Apr 21 15:29:19 irony kernel: ehci_roothub_exec: type=3D0xa3 request=3D0x00 wLen=3D0x0004 wValue=3D0x0000 wIndex=3D0x0001 Apr 21 15:29:19 irony kernel: ehci_roothub_exec: get port status i=3D1 Apr 21 15:29:19 irony kernel: ehci_roothub_exec: port status=3D0x1000 Apr 21 15:29:19 irony kernel: ehci_roothub_exec: type=3D0xa3 request=3D0x00 wLen=3D0x0004 wValue=3D0x0000 wIndex=3D0x0002 Apr 21 15:29:19 irony kernel: ehci_roothub_exec: get port status i=3D2 Apr 21 15:29:19 irony kernel: ehci_roothub_exec: port status=3D0x3000 Apr 21 15:29:19 irony kernel: ehci_roothub_exec: type=3D0xa3 request=3D0x00 wLen=3D0x0004 wValue=3D0x0000 wIndex=3D0x0003 Apr 21 15:29:19 irony kernel: ehci_roothub_exec: get port status i=3D3 Apr 21 15:29:19 irony kernel: ehci_roothub_exec: port status=3D0x1000 Apr 21 15:29:19 irony kernel: ehci_roothub_exec: type=3D0xa3 request=3D0x00 wLen=3D0x0004 wValue=3D0x0000 wIndex=3D0x0004 Apr 21 15:29:19 irony kernel: ehci_roothub_exec: get port status i=3D4 Apr 21 15:29:19 irony kernel: ehci_roothub_exec: port status=3D0x1000 Apr 21 15:29:19 irony kernel: ehci_roothub_exec: type=3D0xa3 request=3D0x00 wLen=3D0x0004 wValue=3D0x0000 wIndex=3D0x0005 Apr 21 15:29:19 irony kernel: ehci_roothub_exec: get port status i=3D5 Apr 21 15:29:19 irony kernel: ehci_roothub_exec: port status=3D0x1000 Apr 21 15:29:19 irony kernel: ehci_roothub_exec: type=3D0xa3 request=3D0x00 wLen=3D0x0004 wValue=3D0x0000 wIndex=3D0x0006 Apr 21 15:29:19 irony kernel: ehci_roothub_exec: get port status i=3D6 Apr 21 15:29:19 irony kernel: ehci_roothub_exec: port status=3D0x1000 ... # ^^^ spamming $ sysctl hw.usb.ehci.debug=3D0 hw.usb.ehci.debug: 15 -> 0 $ sudo usbconfig=20 ugen2.1: <UHCI root HUB Intel> at usbus2, cfg=3D0 md=3DHOST spd=3DFULL (12M= bps) pwr=3DSAVE (0mA) ugen0.1: <UHCI root HUB Intel> at usbus0, cfg=3D0 md=3DHOST spd=3DFULL (12M= bps) pwr=3DSAVE (0mA) ugen1.1: <UHCI root HUB Intel> at usbus1, cfg=3D0 md=3DHOST spd=3DFULL (12M= bps) pwr=3DSAVE (0mA) ugen3.1: <EHCI root HUB Intel> at usbus3, cfg=3D0 md=3DHOST spd=3DHIGH (480= Mbps) pwr=3DSAVE (0mA) ugen0.2: <Wired Keyboard 600 Microsoft> at usbus0, cfg=3D0 md=3DHOST spd=3D= LOW (1.5Mbps) pwr=3DON (100mA) $ sudo usbconfig -d ugen0.2 power_save $ sudo usbconfig=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20= =20=20=20 ugen2.1: <UHCI root HUB Intel> at usbus2, cfg=3D0 md=3DHOST spd=3DFULL (12M= bps) pwr=3DSAVE (0mA) ugen0.1: <UHCI root HUB Intel> at usbus0, cfg=3D0 md=3DHOST spd=3DFULL (12M= bps) pwr=3DSAVE (0mA) ugen1.1: <UHCI root HUB Intel> at usbus1, cfg=3D0 md=3DHOST spd=3DFULL (12M= bps) pwr=3DSAVE (0mA) ugen3.1: <EHCI root HUB Intel> at usbus3, cfg=3D0 md=3DHOST spd=3DHIGH (480= Mbps) pwr=3DSAVE (0mA) ugen0.2: <Wired Keyboard 600 Microsoft> at usbus0, cfg=3D0 md=3DHOST spd=3D= LOW (1.5Mbps) pwr=3DSAVE (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=20 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) --=20 You are receiving this mail because: You are on the CC list for the bug.=
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?bug-208959-6>