Skip site navigation (1)Skip section navigation (2)
Date:      Thu, 11 Oct 2012 21:32:24 +1030
From:      Benjamin Close <Benjamin.Close@clearchain.com>
To:        "Kenneth D. Merry" <ken@freebsd.org>
Cc:        freebsd-stable@freebsd.org
Subject:   Re: usb port issue in 9.1-Prerelease (Possibly Cam related)
Message-ID:  <5076A740.2090203@clearchain.com>
In-Reply-To: <20121008153546.GA7850@nargothrond.kdm.org>
References:  <504DED78.2010203@clearchain.com> <20121008153546.GA7850@nargothrond.kdm.org>

next in thread | previous in thread | raw e-mail | index | archive | help
On 9/10/12 2:05 AM, Kenneth D. Merry wrote:
> On Mon, Sep 10, 2012 at 23:09:04 +0930, Benjamin Close wrote:
>> Hi Folks,
>>      I've facing an intermittent hang with a USB port which seems cam
>> related:
>>
>> Event's that happen are:
>>
>>      o USB modem (HUAWEI E220) plugged into PC
>>
>> ugen3.2: <HUA WEI> at usbus3
>> u3g0: <3G Modem> on usbus3
>> u3g0: Found 3 ports.
>> umass0: <USB MASS STORAGE> on usbus3
>> umass0:  SCSI over Bulk-Only; quirks = 0x0000
>> umass0:6:0:-1: Attached to scbus6
>> umass1: <USB MASS STORAGE> on usbus3
>> umass1:  SCSI over Bulk-Only; quirks = 0x0000
>> umass1:7:1:-1: Attached to scbus7
>> cd1 at umass-sim0 bus 0 scbus6 target 0 lun 0
>> cd1: <HUAWEI Mass Storage 2.31> Removable CD-ROM SCSI-2 device
>> cd1: 1.000MB/s transfers
>> cd1: Attempt to query device size failed: NOT READY, Medium not present
>> da0 at umass-sim1 bus 1 scbus7 target 0 lun 0
>> da0: <HUAWEI SD Storage 2.31> Removable Direct Access SCSI-2 device
>> da0: 1.000MB/s transfers
>> da0: Attempt to query device size failed: NOT READY, Medium not present
>>
>>
>>      o Time Elapses....many packets passed, no da0 or cd1 used.
>>
>>
>>      o USB Modem drops off the bus
>>         (It does this occasionally as it resets itself)
>>
>>      o Causes USB bus to lose devices
>>
>> ugen3.2: <HUA WEI> at usbus3 (disconnected)
>> u3g0: at uhub3, port 1, addr 2 (disconnected)
>> (cd1:umass-sim0:0:0:0): lost device, 1 refs
>> (cd1:umass-sim0:0:0:0): removing device entry
>> (pass4:umass-sim0:0:0:0): passdevgonecb: devfs entry is gone
>> (da0:umass-sim1:1:0:0): lost device - 0 outstanding, 1 refs
>> (da0:umass-sim1:1:0:0): removing device entry
>> (pass5:umass-sim1:1:0:0): passdevgonecb: devfs entry is gone
>> umass0: at uhub3, port 1, addr 2 (disconnected)
>>
>>
>> At this point that particular USB port is effectively useless. Plugging
>> anything into the ports shows no device showing up.
>>
>> Running usbconfig hangs with:
>>
>>    PID    TID COMM             TDNAME KSTACK
>> 48562 101874 usbconfig        -                mi_switch+0x186
>> sleepq_wait+0x42 _sx_xlock_hard+0x426 usbd_enum_lock+0xac
>> usb_ref_device+0x21c usb_open+0xc7 devfs_open+0x197 vn_open_cred+0x2ff
>> kern_openat+0x20a amd64_syscall+0x540 Xfast_syscall+0xf7
>>
>> Controller is:
>>
>> uhci0@pci0:0:26:0:      class=0x0c0300 card=0x02091028 chip=0x28348086
>> rev=0x02 hdr=0x00
>>      vendor     = 'Intel Corporation'
>>      device     = '82801H (ICH8 Family) USB UHCI Controller'
>>      class      = serial bus
>>      subclass   = USB
>> uhci1@pci0:0:26:1:      class=0x0c0300 card=0x02091028 chip=0x28358086
>> rev=0x02 hdr=0x00
>>      vendor     = 'Intel Corporation'
>>      device     = '82801H (ICH8 Family) USB UHCI Controller'
>>      class      = serial bus
>>      subclass   = USB
>> ehci0@pci0:0:26:7:      class=0x0c0320 card=0x02091028 chip=0x283a8086
>> rev=0x02 hdr=0x00
>>      vendor     = 'Intel Corporation'
>>      device     = '82801H (ICH8 Family) USB2 EHCI Controller'
>>      class      = serial bus
>>      subclass   = USB
>>
>> It does however seem related to cam as looking at the various threads
>> for the usb hub I find:
>>
>> (kgdb) bt
>> #0  sched_switch (td=0xfffffe0002650000, newtd=0xfffffe000227f000,
>> flags=Variable "flags" is not available.
>> ) at /usr/src/sys/kern/sched_ule.c:1927
>> #1  0xffffffff808f34c6 in mi_switch (flags=260, newtd=0x0) at
>> /usr/src/sys/kern/kern_synch.c:485
>> #2  0xffffffff8092bfd2 in sleepq_wait (wchan=0xfffffe001ec2a900, pri=92)
>> at /usr/src/sys/kern/subr_sleepqueue.c:623
>> #3  0xffffffff808f3c69 in _sleep (ident=0xfffffe001ec2a900,
>> lock=0xfffffe00371e9210, priority=Variable "priority" is not available.
>> ) at /usr/src/sys/kern/kern_synch.c:250
>> #4  0xffffffff802bea02 in cam_sim_free (sim=0xfffffe001ec2a900,
>> free_devq=1) at /usr/src/sys/cam/cam_sim.c:112
>> #5  0xffffffff8074f8ba in umass_detach (dev=Variable "dev" is not available.
>> ) at /usr/src/sys/dev/usb/storage/umass.c:2183
>> #6  0xffffffff8091a054 in device_detach (dev=0xfffffe001ec2e900) at
>> device_if.h:214
>> #7  0xffffffff8075c458 in usb_detach_device (udev=0xfffffe0007ce8800,
>> iface_index=32 ' ', flag=Variable "flag" is not available.
>> ) at /usr/src/sys/dev/usb/usb_device.c:1065
>> #8  0xffffffff8075c5f4 in usb_unconfigure (udev=0xfffffe0007ce8800,
>> flag=Variable "flag" is not available.
>> ) at /usr/src/sys/dev/usb/usb_device.c:455
>> #9  0xffffffff8075c88e in usb_free_device (udev=0xfffffe0007ce8800,
>> flag=Variable "flag" is not available.
>> ) at /usr/src/sys/dev/usb/usb_device.c:2093
>> #10 0xffffffff80764e5e in uhub_explore (udev=0xfffffe0007353800) at
>> /usr/src/sys/dev/usb/usb_hub.c:358
>> #11 0xffffffff8074f536 in usb_bus_explore (pm=Variable "pm" is not
>> available.
>> ) at /usr/src/sys/dev/usb/controller/usb_controller.c:359
>> #12 0xffffffff80769173 in usb_process (arg=Variable "arg" is not available.
>> ) at /usr/src/sys/dev/usb/usb_process.c:170
>> #13 0xffffffff808bc2df in fork_exit (callout=0xffffffff807690a0
>> <usb_process>, arg=0xffffff80007c0e88, frame=0xffffff804743cc40) at
>> /usr/src/sys/kern/kern_fork.c:992
>> #14 0xffffffff80bc216e in fork_trampoline () at
>> /usr/src/sys/amd64/amd64/exception.S:602
>>
>>
>> From:   cam_sim_free(struct cam_sim *sim, int free_devq)
>>
>> (kgdb) l
>> 107     {
>> 108             int error;
>> 109
>> 110             sim->refcount--;
>> 111             if (sim->refcount > 0) {
>>
>> 112                     error = msleep(sim, sim->mtx, PRIBIO, "simfree", 0);
>>
>> 113                     KASSERT(error == 0, ("invalid error value for
>> msleep(9)"));
>> 114             }
>> 115
>> 116             KASSERT(sim->refcount == 0, ("sim->refcount == 0"));
>>
>>
>> It almost appears as if the cam layer is trying to finalise a write of
>> some sort but the physical device has already gone.
>>
>> (kgdb) p sim->refcount
>> $1 = 1
>>
>> Not sure why refcount is still ==1.
>>
>> The same device in a box running 9.0-Stable (as of about 3 months ago)
>> with a ICH9 controller works as expected.
>>
>> Any suggestions?
> Do you happen to have 'camcontrol devlist -v' output for the above
> scenario?
>
> I have attached a patch for the pass(4) driver that might help things
> somewhat.  The pass(4) driver won't go away completely if there is a
> context that has the driver open when the underlying device goes away.
>
> That might be what is holding up the SIM refcount, although I'm not
> certain.
>
> Ken

It took a while before it failed but output is below for when a failure 
occurs.

scbus0 on siisch0 bus 0:
<WDC WD10EACS-00ZJB0 01.01B01>     at scbus0 target 0 lun 0 (pass0,ada0)
<>                                 at scbus0 target -1 lun -1 ()
scbus1 on siisch1 bus 0:
<WDC WD10EACS-00ZJB0 01.01B01>     at scbus1 target 0 lun 0 (pass1,ada1)
<>                                 at scbus1 target -1 lun -1 ()
scbus2 on ata0 bus 0:
<MATSHITA DVD+-RW UJ-857G Z111>    at scbus2 target 0 lun 0 (pass2,cd0)
<>                                 at scbus2 target -1 lun -1 ()
scbus3 on ahcich0 bus 0:
<Hitachi HTS543212L9A300 FBBOC40C>  at scbus3 target 0 lun 0 (pass3,ada2)
<>                                 at scbus3 target -1 lun -1 ()
scbus4 on ahcich2 bus 0:
<>                                 at scbus4 target -1 lun -1 ()
scbus5 on ctl2cam0 bus 0:
<>                                 at scbus5 target -1 lun -1 ()
scbus6 on umass-sim0 bus 0:
<HUAWEI Mass Storage 2.31>         at scbus6 target 0 lun 0 (pass4)
scbus7 on umass-sim1 bus 1:
<HUAWEI SD Storage 2.31>           at scbus7 target 0 lun 0 (da0,pass5)
scbus-1 on xpt0 bus 0:
<>                                 at scbus-1 target -1 lun -1 (xpt0)


Difference from normal is:

root@taurus:~/work/temp $BUILD_ENV$GITBRANCH| diff -u working.log 
failed.log
--- working.log    2012-10-11 09:16:53.782748589 +1030
+++ failed.log    2012-10-11 09:11:58.923409082 +1030
@@ -15,7 +15,7 @@
  scbus5 on ctl2cam0 bus 0:
  <>                                 at scbus5 target -1 lun -1 ()
  scbus6 on umass-sim0 bus 0:
-<HUAWEI Mass Storage 2.31>         at scbus6 target 0 lun 0 (cd1,pass4)
+<HUAWEI Mass Storage 2.31>         at scbus6 target 0 lun 0 (pass4)
  scbus7 on umass-sim1 bus 1:
  <HUAWEI SD Storage 2.31>           at scbus7 target 0 lun 0 (da0,pass5)
  scbus-1 on xpt0 bus 0:

I do wonder if 
http://lists.freebsd.org/pipermail/svn-src-head/2012-September/040561.html 
could also relate to the problem.
I'll apply the patch and let you know the results.

Cheers,
     Benjamin



Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?5076A740.2090203>