On Sat, 2009-02-28 at 14:09 -0500, Paul O'Keefe wrote:
> On Sat, 2009-02-28 at 12:36 -0500, Alan Stern wrote:
> > On Sat, 28 Feb 2009, Chris Frey wrote:
> >
> > > There were two issues confusing the debugging process. One was that the
> > > timeout appeared to be 1ms in gdb, but this was just a stack anomaly...
> > > stepping a bit farther changed gdb's results... probably due to using
> > > -O2 for the build.
> > >
> > > The other issue was a timeout in libusb's usb_bulk_read() function.
> > > This depended on:
> > >
> > > - a fairly modern tool chain (e.g. Debian Lenny or Ubuntu Jaunty)
> > > - a 2.6.28 kernel or higher (2.6.27 never shows this issue)
> > >
> > > My setup is a Debian Etch system running 2.6.28.7, and a Debian Lenny
> > > system running in a QEMU VM. btool (compiled with g++ 4.1.2 on Etch)
> > > runs fine on 2.6.28.7 and 2.6.28.4 on the bare Etch system. But if I run
> > > btool in the VM Lenny system using 2.6.28.4, compiled with g++ 4.3.2,
> > > I get a timeout. Adding a delay doesn't seem to help.
> >
> > You've got so many variables here, it's hard to keep things straight:
> >
> > Distribution (Etch vs. Lenny),
> >
> > Kernel (2.6.28.4 vs. 2.6.28.7),
> >
> > Environment (bare vs. VM),
> >
> > Compiler (4.1.2 vs. 4.3.2).
> >
> > Maybe other things as well. The cardinal rule of debugging is to vary
> > only one ingredient at a time.
> >
>
> I'm varying one ingredient in my testing ;-). I only began
> experimenting with this set of tools once I had already completed an
> upgrade to Ubuntu Jaunty. So far I have varied only the Kernel (works
> under 2.6.27.x with same libc, same libusb, same libboost-*, and same
> libbarry) and did not work with 2.6.28.x kernel with all those same
> variables.
>
> libusb as discussed calls the REAPURBNDELAY function as part of it's
> SUBMITURB processing. I'm still seeing the timeouts, however my
> BlackBerry doesn't get lost with the 100uSec sleep after the Clear Halts
> and things proceed normally now. Here's another strace (abbreviated)
> showing the 100uSec sleeps and some selected parts.
>
> I don't know if the timeout is from the device, from the libusb
> processing, but I still venture that it was introduced by some Kernel
> change between 2.6.27 and 2.6.28 and I think Chris is on the right track
> to find where it occurs. But ultimately I'll bet that we'll either have
> to ignore the timeout (if it's not affecting the overall device/connect
> process) or make code changes to eliminate the REAPURBNDELAY functions
> in libusb.
>
> log segments follow:
>
> First, see effect of inserting the sleeps
> -------------------------------------
> 13:52:33.456174 open("/dev/bus/usb/007/005", O_RDWR) = 3
> 13:52:33.456324 ioctl(3, USBDEVFS_CONTROL, 0xbfcb961c) = 1
> 13:52:33.456650 ioctl(3, USBDEVFS_CLAIMINTERFACE, 0xbfcb9634) = 0
> 13:52:33.456766 ioctl(3, USBDEVFS_CLEAR_HALT, 0xbfcb9644) = 0
> -----------sleep 1----------------V
> 13:52:33.457116 nanosleep({0, 100000000}, NULL) = 0
> 13:52:33.557517 ioctl(3, USBDEVFS_CLEAR_HALT, 0xbfcb9644) = 0
> -----------sleep 2----------------V
> 13:52:33.557904 nanosleep({0, 100000000}, NULL) = 0
> 13:52:33.658313 gettimeofday({1235847153, 658378}, NULL) = 0
> 13:52:33.658447 ioctl(3, USBDEVFS_SUBMITURB, 0xbfcb94e4) = 0
> -----------still times out--------------------------------------V
> 13:52:33.658562 ioctl(3, USBDEVFS_REAPURBNDELAY, 0xbfcb9528) = -1 EAGAIN
> (Resource temporarily unavailable)
> 13:52:33.658706 select(4, NULL, [3], NULL, {0, 1000}) = 1 (out [3], left
> {0, 992})
> 13:52:33.660212 gettimeofday({1235847153, 660264}, NULL) = 0
> -----------But recovers on first retry-------------------------V
> 13:52:33.660330 ioctl(3, USBDEVFS_REAPURBNDELAY, 0xbfcb9528) = 0
> 13:52:33.660439 futex(0x9af4964, FUTEX_WAIT_PRIVATE, 1, NULL) = 0
> 13:52:33.714335 futex(0x9af4948, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
> 13:52:33.714458 futex(0x9af4948, FUTEX_WAKE_PRIVATE, 1) = 0
> 13:52:33.714565 futex(0x9af4964, FUTEX_WAIT_PRIVATE, 3, NULL) = 0
> 13:52:33.714944 futex(0x9af4948, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
> 13:52:33.715048 futex(0x9af4948, FUTEX_WAKE_PRIVATE, 1) = 0
> 13:52:33.715221 gettimeofday({1235847153, 715263}, NULL) = 0
> 13:52:33.715326 ioctl(3, USBDEVFS_SUBMITURB, 0xbfcb9454) = 0
> -----------------time out---------------------------------------V
> 13:52:33.715423 ioctl(3, USBDEVFS_REAPURBNDELAY, 0xbfcb9498) = -1 EAGAIN
> (Resource temporarily unavailable)
> 13:52:33.715534 select(4, NULL, [3], NULL, {0, 1000}) = 1 (out [3], left
> {0, 990})
> 13:52:33.715673 gettimeofday({1235847153, 715708}, NULL) = 0
> ------------------ recover ------------------------------------v
> 13:52:33.715769 ioctl(3, USBDEVFS_REAPURBNDELAY, 0xbfcb9498) = 0
>
> I'll boot 2.6.27x and repeat.
>
Here's 2.6.27-11-generic (Ubuntu Intrepid)
14:15:45.584430 open("/dev/bus/usb/007/005", O_RDWR) = 3
14:15:45.584589 ioctl(3, USBDEVFS_CONTROL, 0xbfc9330c) = 1
14:15:45.584971 ioctl(3, USBDEVFS_CLAIMINTERFACE, 0xbfc93324) = 0
14:15:45.585088 ioctl(3, USBDEVFS_CLEAR_HALT, 0xbfc93334) = 0
14:15:45.585471 nanosleep({0, 100000000}, NULL) = 0
14:15:45.685725 ioctl(3, USBDEVFS_CLEAR_HALT, 0xbfc93334) = 0
14:15:45.686101 nanosleep({0, 100000000}, NULL) = 0
14:15:45.786501 gettimeofday({1235848545, 786565}, NULL) = 0
14:15:45.786637 ioctl(3, USBDEVFS_SUBMITURB, 0xbfc931d4) = 0
-------------------- our friendly timeout was there in 2.6.27--v
14:15:45.786763 ioctl(3, USBDEVFS_REAPURBNDELAY, 0xbfc93218) = -1 EAGAIN
(Resource temporarily unavailable)
14:15:45.786916 select(4, NULL, [3], NULL, {0, 1000}) = 1 (out [3], left
{0, 1000})
14:15:45.787055 gettimeofday({1235848545, 787095}, NULL) = 0
---------------- clears on first try --------------------------v
14:15:45.787157 ioctl(3, USBDEVFS_REAPURBNDELAY, 0xbfc93218) = 0
The rest looks similar. Some timeouts, recoveries and it moves on.
So we need to separate the issue of the timeout (which recovers) from
the issue of the device getting lost because it didn't get enough time
to reset. I don't see a heck of a lot of difference between my 2.6.27
and 2.6.28 straces. I can post them completely if it is of any help.
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
