On Fri, 16 Oct 2015, Paul Jones wrote: > Added some debugging statements in f_mass_storage/net2280 to get an idea of what is going on on the wire (as I unfortunately don’t have any tools to figure it out any other way). > Additional debug statement locations: ... > Log for a single large read request: ... > The above is using the standard buffer size of 16k with 8 buffers. > > f_mass_storage performs a vfs_read and waits for it’s result before performing a start_in_transfer. > The start_in_transfer doesn’t return until the transfer is queued. > If the read request is large enough to require multiple buffers then the next vfs_read is only issued after the transfer is queued. > > Occasionally a vfs_read requests is slow (20+us) but the other calls are relatively fast (2-3us) for the same transfer size, which is presumably due to read ahead in the vfs layer. > Similarly queuing some of the bulk transfers is very slow (4-15us), but others are fast (1-2us). Some of these delays you see may be due to interrupts coming from other devices. There's not much you can do about those. > The slow queuing of transfers seems to be due to waiting in a spin lock on ep->dev->lock (4+ us). > I’m guessing this is caused by the fact that there sometimes seems to be significant time between when the spin lock is acquired in net2280_queue and when it is released. > Any idea why that may be? There shouldn't be any contention on that spinlock -- at least, not until the driver's interrupt handler needs to run. Everything else in the mass-storage gadget is single-threaded. I don't know why it should take so long to acquire the spinlock when nothing else is happening, unless once again you're seeing interrupts from other devices. > It seems to take about 95-100us from the first usb_ep_queue to bulk_in_complete for 16384 bytes of payload. > Subsequent bulk_in_complete events are returned at a 95-100us between them. > Any ideas why that may be? That's the time it takes to actually send the data across the USB bus. You appear to be getting about 1/3 the maximum possible throughput, since the maximum data rate is 500 MB/s and you're getting 16384 B in about 100 us. > Given that most of the bulk-in requests are overlapping, the underlying hardware shouldn’t have to wait for anything except for the host stalling the data reception (which I think is unlikely). Don't be so sure. The fact is, either the host's or the gadget's hardware could easily be running at a sub-optimal speed. Hardware implementations are rarely ideal. > I noticed that the done function in net2280 releases and requires the ep->dev->lock around the call to the completion callback. > Given that sometimes acquiring the lock takes a long time, we could be stalling interrupts for a significant amount of time as well. > I’ll try to add some logging in the irq handler to see how long this are taking... One thing you did not show here was the delay between sending the last data buffer of one command and sending the first data buffer of the next command. That overhead could significantly affect the overall throughput. Alan Stern -- 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
