USB config SX lock deadlock

Daniel O'Connor doconnor at gsoft.com.au
Thu Mar 20 04:40:44 UTC 2014 

On 10 Oct 2013, at 18:18, Hans Petter Selasky <hps at bitfrost.no> wrote:
> On 10/10/13 09:38, Daniel O'Connor wrote:
>> 
>> On 10/10/2013, at 16:59, Hans Petter Selasky <hps at bitfrost.no> wrote:
>> The usb_fifo_* code handles all wakeups so I am not sure.
> 
> The usb_fifo code only will only do refcounting. If you do USB control requests, you should use the f_ioctl_post, callback, because the f_ioctl callback does not protect against attach and detach or the enumeration thread running.
> 
>        err = (f->methods->f_ioctl) (f, cmd, addr, fflags);
> 
>        DPRINTFN(2, "f_ioctl cmd 0x%lx = %d\n", cmd, err);
> 
>        if (err != ENOIOCTL)
>                goto done;
> 
>        if (usb_usb_ref_device(cpd, &refs)) {
>                err = ENXIO;
>                goto done;
>        }
> 
>        err = (f->methods->f_ioctl_post) (f, cmd, addr, fflags);
> 
>        DPRINTFN(2, "f_ioctl_post cmd 0x%lx = %d\n", cmd, err);

After a long hiatus I have come back to this problem.

I updated a test system to 9-STABLE (r263062) and the problem occurs quite often. I'm still trying to find _why_ my device disconnects (unfortunately it has no debugger so it's tricky), however with this kernel is very reliably hangs (under and hour of tests).

I end up with the following backtrace of the thread in question..
(kgdb) bt
#0  sched_switch (td=0xfffffe011fa9c000, newtd=0xfffffe0002953000, flags=<value optimized out>) at /local0/src/sys/kern/sched_ule.c:1904
#1  0xffffffff8089e5b0 in mi_switch (flags=260, newtd=0x0) at /local0/src/sys/kern/kern_synch.c:485
#2  0xffffffff808d5274 in sleepq_wait (wchan=0xfffffe011faed050, pri=0) at /local0/src/sys/kern/subr_sleepqueue.c:618
#3  0xffffffff8089d916 in _sx_xlock_hard (sx=0xfffffe011faed050, tid=18446741879512481792, opts=<value optimized out>, file=<value optimized out>,
    line=<value optimized out>) at /local0/src/sys/kern/kern_sx.c:678
#4  0xffffffff8089de06 in _sx_xlock (sx=0xfffffe011faed050, opts=0, file=0xffffffff80e4d528 "/local0/src/sys/dev/usb/usb_device.c", line=2651) at sx.h:161
#5  0xffffffff8071245a in usbd_enum_lock (udev=0xfffffe011faed000) at /local0/src/sys/dev/usb/usb_device.c:2651
#6  0xffffffff807207a2 in usbd_do_request_flags (udev=0xfffffe011faed000, mtx=0x0, req=0xffffff812c402920, data=0xfffffe011fab8274, flags=4, actlen=0x0, timeout=5000)
    at /local0/src/sys/dev/usb/usb_request.c:459
#7  0xffffffff81c6493c in ugsio_udioctl (fifo=<value optimized out>, cmd=3222040644, data=0xfffffe011fab8270, fflags=<value optimized out>) at ugsio.c:1038
#8  0xffffffff8070f932 in usb_ioctl (dev=<value optimized out>, cmd=3222040644, addr=0xfffffe011fab8270 "\001", fflag=<value optimized out>, td=<value optimized out>)
    at /local0/src/sys/dev/usb/usb_dev.c:1075
#9  0xffffffff8078f01a in devfs_ioctl_f (fp=0xfffffe0008f21be0, com=3222040644, data=<value optimized out>, cred=<value optimized out>, td=0xfffffe011fa9c000)
    at /local0/src/sys/fs/devfs/devfs_vnops.c:758
#10 0xffffffff808df946 in kern_ioctl (td=0xfffffe011fa9c000, fd=3, com=3222040644, data=0xfffffe011fab8270 "\001") at file.h:311
#11 0xffffffff808dfb5d in sys_ioctl (td=0xfffffe011fa9c000, uap=0xffffff812c402b70) at /local0/src/sys/kern/sys_generic.c:696
#12 0xffffffff80c4ee58 in amd64_syscall (td=0xfffffe011fa9c000, traced=0) at subr_syscall.c:135
#13 0xffffffff80c3aa67 in Xfast_syscall () at /local0/src/sys/amd64/amd64/exception.S:391
#14 0x00000008010e7d9c in ?? ()

and the code at frame 7
1033	    usbreq.bRequest = VC_CMD;
1034	    USETW(usbreq.wValue, vccmd->value);
1035	    USETW(usbreq.wIndex, vccmd->index);
1036	    USETW(usbreq.wLength, sizeof(vccmd->data));
1037
1038	    if ((err = usbd_do_request_flags(udev, NULL, &usbreq, vccmd->data, USB_SHORT_XFER_OK, NULL, 20000)) != USB_ERR_NORMAL_COMPLETION) {
1039		DPRINTFN(1, "USB request failed: %d\n", err);
1040		return(err);
1041	    }
1042

The lock object looks like..
(kgdb) print sx
$1 = (struct sx *) 0xfffffe011faed050
(kgdb) print *sx
$2 = {lock_object = {lo_name = 0xffffffff80e4d3d7 "USB config SX lock", lo_flags = 41091072, lo_data = 0, lo_witness = 0x0}, sx_lock = 18446741874768565396}

I tried 'show alllocks' in DDB but it doesn't list anything even though witness is in the kernel :(

However some digging shows most of the USB process threads look the same except for..

* 42 Thread 100030 (PID=15: usb/usbus0)  sched_switch (td=0xfffffe0004e75490, newtd=0xfffffe0002953000, flags=<value optimized out>)
    at /local0/src/sys/kern/sched_ule.c:1904
#0  sched_switch (td=0xfffffe0004e75490, newtd=0xfffffe0002953000, flags=<value optimized out>) at /local0/src/sys/kern/sched_ule.c:1904
#1  0xffffffff8089e5b0 in mi_switch (flags=260, newtd=0x0) at /local0/src/sys/kern/kern_synch.c:485
#2  0xffffffff808d5274 in sleepq_wait (wchan=0xfffffe000851a288, pri=0) at /local0/src/sys/kern/subr_sleepqueue.c:618
#3  0xffffffff80852c6d in _cv_wait (cvp=0xfffffe000851a288, lock=0xffffffff81403700) at /local0/src/sys/kern/kern_condvar.c:139
#4  0xffffffff8071195c in usb_fifo_free (f=0xfffffe000851a200) at /local0/src/sys/dev/usb/usb_dev.c:609
#5  0xffffffff80711a52 in usb_fifo_detach (f_sc=0xfffffe0008802458) at /local0/src/sys/dev/usb/usb_dev.c:1824
#6  0xffffffff81c64041 in ugsio_detach (dev=<value optimized out>) at ugsio.c:341
#7  0xffffffff808c35a4 in device_detach (dev=0xfffffe0008bf3100) at device_if.h:214
#8  0xffffffff807130b8 in usb_detach_device (udev=0xfffffe011faed000, iface_index=32 ' ', flag=<value optimized out>) at /local0/src/sys/dev/usb/usb_device.c:1050
#9  0xffffffff80713a7c in usb_unconfigure (udev=0xfffffe011faed000, flag=<value optimized out>) at /local0/src/sys/dev/usb/usb_device.c:450
#10 0xffffffff80714287 in usbd_set_config_index (udev=0xfffffe011faed000, index=255 '�') at /local0/src/sys/dev/usb/usb_device.c:513
#11 0xffffffff8071ce11 in uhub_explore (udev=0xfffffe0008166000) at /local0/src/sys/dev/usb/usb_hub.c:460
#12 0xffffffff8071ca4b in uhub_explore (udev=0xfffffe0006f2f000) at /local0/src/sys/dev/usb/usb_hub.c:524
#13 0xffffffff80707782 in usb_bus_explore (pm=<value optimized out>) at /local0/src/sys/dev/usb/controller/usb_controller.c:381
#14 0xffffffff80720403 in usb_process (arg=<value optimized out>) at /local0/src/sys/dev/usb/usb_process.c:169
#15 0xffffffff8086b4cd in fork_exit (callout=0xffffffff80720340 <usb_process>, arg=0xffffff80007e5db0, frame=0xffffff80f5d34c00) at /local0/src/sys/kern/kern_fork.c:996
#16 0xffffffff80c3acae in fork_trampoline () at /local0/src/sys/amd64/amd64/exception.S:606
#17 0x0000000000000000 in ?? ()

So I think usb_detach_device has grabbed the enum lock, but I'm not sure what sort of fix would be appropriate, any ideas?

Thanks.

--
Daniel O'Connor software and network engineer
for Genesis Software - http://www.gsoft.com.au
"The nice thing about standards is that there
are so many of them to choose from."
  -- Andrew Tanenbaum
GPG Fingerprint - 5596 B766 97C0 0E94 4347 295E E593 DC20 7B3F CE8C






-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 195 bytes
Desc: Message signed with OpenPGP using GPGMail
URL: <http://lists.freebsd.org/pipermail/freebsd-usb/attachments/20140320/1c4c2080/attachment.sig>

More information about the freebsd-usb mailing list