From owner-freebsd-amd64@freebsd.org Thu Apr 21 16:07:44 2016 Return-Path: Delivered-To: freebsd-amd64@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 10A71B1615C for ; Thu, 21 Apr 2016 16:07:44 +0000 (UTC) (envelope-from bugzilla-noreply@freebsd.org) Received: from kenobi.freebsd.org (kenobi.freebsd.org [IPv6:2001:1900:2254:206a::16:76]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 009921BB5 for ; Thu, 21 Apr 2016 16:07:44 +0000 (UTC) (envelope-from bugzilla-noreply@freebsd.org) Received: from bugs.freebsd.org ([127.0.1.118]) by kenobi.freebsd.org (8.15.2/8.15.2) with ESMTP id u3LG7hdf040930 for ; Thu, 21 Apr 2016 16:07:43 GMT (envelope-from bugzilla-noreply@freebsd.org) From: bugzilla-noreply@freebsd.org To: freebsd-amd64@FreeBSD.org Subject: [Bug 208959] UHCI interrupt storm with "uhci_interrupt: uhci_interrupt: host controller halted" Date: Thu, 21 Apr 2016 16:07:43 +0000 X-Bugzilla-Reason: CC X-Bugzilla-Type: new X-Bugzilla-Watch-Reason: None X-Bugzilla-Product: Base System X-Bugzilla-Component: usb X-Bugzilla-Version: 10.3-RELEASE X-Bugzilla-Keywords: X-Bugzilla-Severity: Affects Only Me X-Bugzilla-Who: jamie.ivanov@gmail.com X-Bugzilla-Status: New X-Bugzilla-Resolution: X-Bugzilla-Priority: --- X-Bugzilla-Assigned-To: freebsd-usb@FreeBSD.org X-Bugzilla-Flags: X-Bugzilla-Changed-Fields: bug_id short_desc product version rep_platform op_sys bug_status bug_severity priority component assigned_to reporter cc attachments.created Message-ID: Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable X-Bugzilla-URL: https://bugs.freebsd.org/bugzilla/ Auto-Submitted: auto-generated MIME-Version: 1.0 X-Mailman-Approved-At: Thu, 21 Apr 2016 16:08:59 +0000 X-BeenThere: freebsd-amd64@freebsd.org X-Mailman-Version: 2.1.21 Precedence: list List-Id: Porting FreeBSD to the AMD64 platform List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 21 Apr 2016 16:07:44 -0000 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: at usbus2, cfg=3D0 md=3DHOST spd=3DFULL (12M= bps) pwr=3DSAVE (0mA) ugen0.1: at usbus0, cfg=3D0 md=3DHOST spd=3DFULL (12M= bps) pwr=3DSAVE (0mA) ugen1.1: at usbus1, cfg=3D0 md=3DHOST spd=3DFULL (12M= bps) pwr=3DSAVE (0mA) ugen3.1: at usbus3, cfg=3D0 md=3DHOST spd=3DHIGH (480= Mbps) pwr=3DSAVE (0mA) ugen0.2: 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: at usbus2, cfg=3D0 md=3DHOST spd=3DFULL (12M= bps) pwr=3DSAVE (0mA) ugen0.1: at usbus0, cfg=3D0 md=3DHOST spd=3DFULL (12M= bps) pwr=3DSAVE (0mA) ugen1.1: at usbus1, cfg=3D0 md=3DHOST spd=3DFULL (12M= bps) pwr=3DSAVE (0mA) ugen3.1: at usbus3, cfg=3D0 md=3DHOST spd=3DHIGH (480= Mbps) pwr=3DSAVE (0mA) ugen0.2: 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: port 0x1800-0x181f= irq 17 at device 29.0 on pci0=20 usbus0 on uhci0 uhci1: port 0x1820-0x183f= irq 19 at device 29.1 on pci0 usbus1 on uhci1 uhci2: port 0x1840-0x185f= irq 18 at device 29.2 on pci0 usbus2 on uhci2 ehci0: 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: at usbus2 ugen0.1: at usbus0 uhub0: on usbus2 uhub1: on usbus0 ugen1.1: at usbus1 ugen3.1: at usbus3 uhub2: on usbus1 uhub3: 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: at usbus0 ukbd0: on usbus0 kbd2 at ukbd0 uhid0: 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.=