From owner-freebsd-bugs Tue Apr 23 3:40:17 2002 Delivered-To: freebsd-bugs@hub.freebsd.org Received: from freefall.freebsd.org (freefall.FreeBSD.org [216.136.204.21]) by hub.freebsd.org (Postfix) with ESMTP id D2A3437B416 for ; Tue, 23 Apr 2002 03:40:02 -0700 (PDT) Received: (from gnats@localhost) by freefall.freebsd.org (8.11.6/8.11.6) id g3NAe2N19176; Tue, 23 Apr 2002 03:40:02 -0700 (PDT) (envelope-from gnats) Received: from marklar.elive.net (smtp.elive.ie [212.120.138.41]) by hub.freebsd.org (Postfix) with ESMTP id 1439A37B416 for ; Tue, 23 Apr 2002 03:31:03 -0700 (PDT) Received: from cornerstone.colley.ie (1Cust72.tnt3.dub2.ie.uudial.net [213.116.44.72]) by marklar.elive.net (8.11.6/8.11.6) with ESMTP id g3NAHDp25718 for ; Tue, 23 Apr 2002 11:17:19 +0100 Received: by cornerstone.colley.ie (Postfix, from userid 1001) id 96EF146; Mon, 22 Apr 2002 23:51:27 +0100 (IST) Message-Id: <20020422225127.96EF146@cornerstone.colley.ie> Date: Mon, 22 Apr 2002 23:51:27 +0100 (IST) From: Adrian Colley Reply-To: Adrian Colley To: FreeBSD-gnats-submit@FreeBSD.org X-Send-Pr-Version: 3.113 Subject: kern/37374: [PATCH] closing ums0 blocks with wmesg uhciab Sender: owner-freebsd-bugs@FreeBSD.ORG Precedence: bulk List-ID: List-Archive: (Web Archive) List-Help: (List Instructions) List-Subscribe: List-Unsubscribe: X-Loop: FreeBSD.org >Number: 37374 >Category: kern >Synopsis: [PATCH] closing ums0 blocks with wmesg uhciab >Confidential: no >Severity: non-critical >Priority: medium >Responsible: freebsd-bugs >State: open >Quarter: >Keywords: >Date-Required: >Class: sw-bug >Submitter-Id: current-users >Arrival-Date: Tue Apr 23 03:40:01 PDT 2002 >Closed-Date: >Last-Modified: >Originator: Adrian Colley >Release: FreeBSD 5.0-CURRENT i386 >Organization: Benevolent Order of Unemployed Hackers >Environment: System: FreeBSD muttley.colley.ie 5.0-CURRENT FreeBSD 5.0-CURRENT #4: Mon Apr 22 22:27:18 IST 2002 root@muttley.colley.ie:/c/usr.obj/usr/src/sys/MUTTLEY i386 Relevant lines from /var/run/dmesg.boot: pci0: physical bus=0 map[10]: type 3, range 32, base e0000000, size 26, enabled found-> vendor=0x1106, dev=0x3038, revid=0x10 bus=0, slot=7, func=2 class=0c-03-00, hdrtype=0x00, mfdev=0 intpin=d, irq=11 powerspec 2 supports D0 D3 current D0 map[20]: type 4, range 32, base 0000d400, size 5, enabled uhci0: port 0xd000-0xd01f irq 11 at device 7.2 on pci0 uhci0: LegSup = 0x0000a000 usb0: on uhci0 usb0: USB revision 1.0 uhub0: VIA UHCI root hub, class 9/0, rev 1.00/1.00, addr 1 uhub0: 2 ports with 2 removable, self powered ums0: Microsoft Microsoft IntelliMouse\M-. Explorer, rev 1.10/1.14, addr 2, iclass 3/1 ums0: 5 buttons and Z dir. uhci1: port 0xd400-0xd41f irq 11 at device 7.3 on pci0 uhci1: LegSup = 0x0000a000 usb1: on uhci1 usb1: USB revision 1.0 uhub1: VIA UHCI root hub, class 9/0, rev 1.00/1.00, addr 1 uhub1: 2 ports with 2 removable, self powered Relevant lines from /usr/src/sys/i386/conf/MUTTLEY: device uhci # UHCI PCI->USB interface device ohci # OHCI PCI->USB interface device usb # USB Bus (required) device ugen # Generic device uhid # "Human Interface Devices" device ukbd # Keyboard device ulpt # Printer device scbus # needed for umass device da # needed for umass device umass # Disks/Mass storage - Requires scbus and da options UMASS_DEBUG # See /sys/dev/usb/umass.c device ums # Mouse device urio # Diamond Rio 500 MP3 player options USB_DEBUG options UHCI_DEBUG World and kernel built from FreeBSD-current, last cvsupped on 2002-04-19 20:01 UTC. Using ddb(4), uhcidebug was assigned 0xb to enable debug printfs. >Description: When ums0 is closed (whether by the X server or moused), the process blocks. Attempts to kill the process fail (ps reports that it's in 'D' state). The wmesg for the process is "uhciab" (/sys/dev/usb/uhci.c:1.119:1951). Debug printfs (extracted from /var/log/messages) show the sequence of events: Apr 22 21:51:21 muttley sudo: aecolley : TTY=ttyv1 ; PWD=/usr/src/sys/dev/usb ; USER=root ; COMMAND=/usr/sbin/moused -p /dev/ums0 -I /var/run/moused.ums0.pid Apr 22 21:51:21 muttley kernel: uhci_open: pipe=0xcd779080, addr=2, endpt=129 (1) Apr 22 21:51:21 muttley kernel: uhci_setintr: pipe=0xcd779080 Apr 22 21:51:21 muttley kernel: uhci_setintr: ival=10 npoll=13 Apr 22 21:51:21 muttley kernel: uhci_setintr: bw=0 offs=0 Apr 22 21:51:21 muttley kernel: uhci_add_intr: n=0 sqh=0xc8df3f40 Apr 22 21:51:21 muttley kernel: uhci_add_intr: n=10 sqh=0xc8df3f20 Apr 22 21:51:21 muttley kernel: uhci_add_intr: n=20 sqh=0xc8df3f00 Apr 22 21:51:21 muttley kernel: uhci_add_intr: n=30 sqh=0xc8df3ee0 Apr 22 21:51:21 muttley kernel: uhci_add_intr: n=40 sqh=0xc8df3ec0 Apr 22 21:51:21 muttley kernel: uhci_add_intr: n=50 sqh=0xc8df3ea0 Apr 22 21:51:21 muttley kernel: uhci_add_intr: n=60 sqh=0xc8df3e80 Apr 22 21:51:21 muttley kernel: uhci_add_intr: n=70 sqh=0xc8df3e60 Apr 22 21:51:21 muttley kernel: uhci_add_intr: n=80 sqh=0xc8df3e40 Apr 22 21:51:21 muttley kernel: uhci_add_intr: n=90 sqh=0xc8df3e20 Apr 22 21:51:21 muttley kernel: uhci_add_intr: n=100 sqh=0xc8df3e00 Apr 22 21:51:21 muttley kernel: uhci_add_intr: n=110 sqh=0xc8df3de0 Apr 22 21:51:21 muttley kernel: uhci_add_intr: n=120 sqh=0xc8df3dc0 Apr 22 21:51:21 muttley kernel: uhci_setintr: returns 0xcd779080 Apr 22 21:51:21 muttley kernel: uhci_device_control type=0x02, request=0x01, wValue=0x0000, wIndex=0x0081 len=0, addr=2, endpt=0 Apr 22 21:51:21 muttley kernel: uhci_device_request: before transfer Apr 22 21:51:21 muttley kernel: TD(0xc8df2fc0) at 07b53fc0 = link=0x07b53fa4 status=0x1c800000 token=0x00e0022d buffer=0x07b72bd0 Apr 22 21:51:21 muttley kernel: 7b53fa4 1c800000,errcnt=3,actlen=1 pid=2d,addr=2,endpt=0,D=0,maxlen=8 Apr 22 21:51:21 muttley kernel: TD(0xc8df2fa0) at 07b53fa0 = link=0x00000001 status=0x1d800000 token=0xffe80269 buffer=0x00000000 Apr 22 21:51:21 muttley kernel: 1 1d800000,errcnt=3,actlen=1 pid=69,addr=2,endpt=0,D=1,maxlen=0 Apr 22 21:51:21 muttley kernel: uhci_add_ls_ctrl: sqh=0xc8df3f60 Apr 22 21:51:21 muttley kernel: usb0: uhci_softintr (0) Apr 22 21:51:21 muttley kernel: uhci_idone: ii=0xcce8d264, xfer=0xcce8d200, pipe=0xc8e3cc80 ready Apr 22 21:51:21 muttley kernel: TD(0xc8df2fc0) at 07b53fc0 = link=0x07b53fa4 status=0x1c000007 token=0x00e0022d buffer=0x07b72bd0 Apr 22 21:51:21 muttley kernel: 7b53fa4 1c000007,errcnt=3,actlen=8 pid=2d,addr=2,endpt=0,D=0,maxlen=8 Apr 22 21:51:21 muttley kernel: TD(0xc8df2fa0) at 07b53fa0 = link=0x00000001 status=0x1d0007ff token=0xffe80269 buffer=0x00000000 Apr 22 21:51:21 muttley kernel: 1 1d0007ff,errcnt=3,actlen=0 pid=69,addr=2,endpt=0,D=1,maxlen=0 Apr 22 21:51:21 muttley kernel: uhci_idone: actlen=0, status=0x0 Apr 22 21:51:21 muttley kernel: uhci_remove_ls_ctrl: sqh=0xc8df3f60 Apr 22 21:51:21 muttley kernel: uhci_ctrl_done: length=0 Apr 22 21:51:21 muttley kernel: usb0: uhci_intr: exit Apr 22 21:51:21 muttley kernel: uhci_device_intr_transfer: xfer=0xcce8d200 len=4 flags=4 Apr 22 21:51:21 muttley kernel: uhci_alloc_std_chain: addr=2 endpt=1 len=4 speed=1 flags=0x4 Apr 22 21:51:21 muttley kernel: uhci_alloc_std_chain: maxp=4 ntd=1 Apr 22 21:51:21 muttley kernel: uhci_alloc_std_chain: nexttog=1 Apr 22 21:51:21 muttley kernel: uhci_device_intr_transfer: data(1) Apr 22 21:51:21 muttley kernel: TD(0xc8df2f80) at 07b53f80 = link=0x00000005 status=0x3d8003ff token=0x00608269 buffer=0x076089c0 Apr 22 21:51:21 muttley kernel: 5 3d8003ff,errcnt=3,actlen=0 pid=69,addr=2,endpt=1,D=0,maxlen=4 Apr 22 21:51:21 muttley kernel: QH(0xc8df3f40) at 07b54f40: hlink=07b55f82 elink=00000001 Apr 22 21:51:21 muttley kernel: uhci_device_intr_transfer: qhs[0]=0xc8df3f40 Apr 22 21:51:21 muttley kernel: uhci_device_intr_transfer: data(2) Apr 22 21:51:21 muttley kernel: TD(0xc8df2f80) at 07b53f80 = link=0x00000005 status=0x3d8003ff token=0x00608269 buffer=0x076089c0 Apr 22 21:51:21 muttley kernel: 5 3d8003ff,errcnt=3,actlen=0 pid=69,addr=2,endpt=1,D=0,maxlen=4 Apr 22 21:51:21 muttley kernel: QH(0xc8df3f40) at 07b54f40: hlink=07b55f82 elink=07b53f80 Apr 22 21:51:49 muttley sudo: aecolley : TTY=ttyv1 ; PWD=/usr/src/sys/dev/usb ; USER=root ; COMMAND=/bin/kill 264 Apr 22 21:51:50 muttley kernel: uhci_device_intr_abort: xfer=0xcce8d200 Apr 22 21:51:50 muttley kernel: uhci_device_intr_abort: remove Apr 22 21:51:50 muttley kernel: uhci_abort_xfer: xfer=0xcce8d200, status=6 Apr 22 21:51:50 muttley kernel: uhci_abort_xfer: stop ii=0xcce8d264 Apr 22 21:51:50 muttley kernel: usb0: uhci_softintr (0) Apr 22 21:51:50 muttley kernel: uhci_check_intr: aborted xfer=0xcce8d200 Apr 22 21:51:50 muttley kernel: uhci_abort_xfer: tsleep An inspection of the code indicates that uhci_abort_xfer tsleeps in an splusb/splx block, expecting a wakeup that uhci_softintr will deliver. Unfortunately, uhci_softintr was called by way of callback (see /sys/dev/usb/usb.c:1.77:840) and so was not blocked by splusb. The code seems to use sc_softwake as an event flag to indicate that a wakeup is expected. My fix uses that flag to detect the usb_schedsoftintr callback. Perhaps USB_USE_SOFTINTR is supposed to be somehow defined in usb.c? (Extra note: in an earlier -current build, closing ums0 actually caused a system lockup (repeatably). Not possessing an NMI button (and not liking the ISA A0-B0 paperclip idea), there was nothing I could do except disable usbd.) >How-To-Repeat: /usr/sbin/moused -p /dev/ums0 -I /var/run/moused.ums0.pid kill `cat /var/run/moused.ums0.pid` ps l`cat /var/run/moused.ums0.pid` >Fix: --- usbfix.patch begins here --- Index: uhci.c =================================================================== RCS file: /b/cvs/src/sys/dev/usb/uhci.c,v retrieving revision 1.119 diff -u -r1.119 uhci.c --- uhci.c 7 Apr 2002 18:33:12 -0000 1.119 +++ uhci.c 22 Apr 2002 21:20:55 -0000 @@ -1946,8 +1946,10 @@ s = splusb(); sc->sc_softwake = 1; usb_schedsoftintr(&sc->sc_bus); - DPRINTFN(1,("uhci_abort_xfer: tsleep\n")); - tsleep(&sc->sc_softwake, PZERO, "uhciab", 0); + if (sc->sc_softwake) { + DPRINTFN(1,("uhci_abort_xfer: tsleep\n")); + tsleep(&sc->sc_softwake, PZERO, "uhciab", 0); + } splx(s); /* --- usbfix.patch ends here --- >Release-Note: >Audit-Trail: >Unformatted: To Unsubscribe: send mail to majordomo@FreeBSD.org with "unsubscribe freebsd-bugs" in the body of the message