From: Daniel D. <da...@re...> - 2009-12-23 13:55:42
|
El 23/12/09 08:45, "@ndré THEVENIN" escribió: > > > Hello, > > I have tried strace, I have got the following trace > > 09:32:39.737923 timerfd_create(CLOCK_MONOTONIC, 0x800 /* TFD_??? */) = 5 > ...... (here, the loop to detect my device) > 09:32:39.818991 write(1, "0483:5740 (bus 2, device 2)\n"..., 28) = 28 > 09:32:39.828216 open("/dev/bus/usb/002/002", O_RDWR) = 6 > 09:32:39.831571 write(4, "\1"..., 1) = 1 > 09:32:39.832483 read(3, "\1"..., 1) = 1 > 09:32:39.833610 ioctl(6, USBDEVFS_IOCTL, 0xbfa3ffa0) = 0 > 09:32:39.895512 write(1, "detach kernel 144646736 144642400"..., 36) = 36 > 09:32:39.902056 ioctl(6, USBDEVFS_CLAIMINTERFACE, 0xbfa3ffc4) = 0 > 09:32:39.903145 write(1, "claim interface 144646736 1446424"..., 38) = 38 > 09:32:39.904223 clock_gettime(CLOCK_MONOTONIC, {667, 944906583}) = 0 This is the basis for the timing calculation. > 09:32:39.906351 ioctl(6, USBDEVFS_SUBMITURB, 0x89f1238) = 0 > 09:32:39.931278 timerfd_settime(5, TFD_TIMER_ABSTIME, {it_interval={0, > 0}, it_value={668, 444906000}}, NULL) = 0 The timer is set for exactly 500ms after the basis discovered above. It looks like submitting the ioctl took about 30ms, or something else delayed us before we could program the timer. It's debatable whether libusb's timing basis should be generated before or after submitting the URB. > 09:32:39.932187 write(1, "submit 0\n"..., 9) = 9 > 09:32:39.934389 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}, > {fd=6, events=POLLOUT}], 3, 60000) = 1 ([{fd=5, revents=POLLIN}]) > 09:32:40.407377 timerfd_settime(5, 0, {it_interval={0, 0}, it_value={0, > 0}}, NULL) = 0 Now libusb listens for events on 3 (internal control pipe), 5 (timer), and 6 (USB handle) And the one that triggers is the timer, exactly 500ms after the time-basis was discovered. (Yes, it is normal that there is not an ioctl for checking the URB status. It is done by poll(). You expect a POLLOUT event on fd 6 when there is an URB ready to be reaped. This did not happen in the 470ms that remained before the timer expired.) > 09:32:40.407883 clock_gettime(CLOCK_MONOTONIC, {668, 447201169}) = 0 > 09:32:40.408268 ioctl(6, USBDEVFS_DISCARDURB, 0x89f1238) = 0 Then it figures out that the 500ms timeout for the control transfer has expired, and cancels it, which involves a round-trip with the kernel. > 09:32:40.429764 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}, > {fd=6, events=POLLOUT}], 3, 60000) = 1 ([{fd=6, revents=POLLOUT}]) > 09:32:40.430304 ioctl(6, USBDEVFS_REAPURBNDELAY, 0xbfa3ff08) = 0 Then the cancellation notification arrives in the form of an event on the USB handle, and libusb calls the user timeout callback. So it looks like everything is fine from the libusb perspective. It would be interesting to see usbmon logs to see if that shows that the transfer completes before libusb cancels it. (judging from the strace, I don't think it does since that condition would cause DISCARDURB to fail, but it would be good to be sure) Another interesting experiment would be increasing the timeout. Daniel |