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)
Can you set the UHCI debug to 16 and find out which interrupts are triggered? --HPS
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
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
Bueller?