Date: Mon, 22 Apr 2002 23:51:27 +0100 (IST) From: Adrian Colley <aecolley@spamcop.net> To: FreeBSD-gnats-submit@FreeBSD.org Subject: kern/37374: [PATCH] closing ums0 blocks with wmesg uhciab Message-ID: <20020422225127.96EF146@cornerstone.colley.ie>
next in thread | raw e-mail | index | archive | help
>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: <VIA 83C572 USB controller> port 0xd000-0xd01f irq 11 at device 7.2 on pci0
uhci0: LegSup = 0x0000a000
usb0: <VIA 83C572 USB controller> 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: <VIA 83C572 USB controller> port 0xd400-0xd41f irq 11 at device 7.3 on pci0
uhci1: LegSup = 0x0000a000
usb1: <VIA 83C572 USB controller> 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<VF> 1c800000<ACTIVE,LS>,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<T> 1d800000<ACTIVE,IOC,LS>,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<VF> 1c000007<LS>,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<T> 1d0007ff<IOC,LS>,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<T,VF> 3d8003ff<ACTIVE,IOC,LS,SPD>,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<T,VF> 3d8003ff<ACTIVE,IOC,LS,SPD>,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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20020422225127.96EF146>