On 05 Oct 2015, at 20:29, Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> wrote: > On Mon, 5 Oct 2015, Paul Jones wrote: > >> I�m investigating the (lack of) performance (around 150MB/s) of the USB3380 gadget in mass storage mode. >> Whilst tracing on a Linux 4.1 host I noticed that the Linux max storage driver is requesting 240 blocks, 16 blocks, 240 blocks, 16 blocks, etc. when doing a dd directly on the device: >> dd if=/dev/sdb of=/dev/null bs=64k count=8k >> where /dev/sdb is the emulated device. >> The emulated device is provided from a secondary machine with a USB3380 card emulating the mass storage device from a local SSD (local dd of the disk file reads at 542 MB/s). >> >> lsusb on the host: >> /: Bus 04.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/3p, 480M >> |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/8p, 480M >> /: Bus 03.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/3p, 480M >> |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/6p, 480M >> /: Bus 02.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/6p, 5000M >> |__ Port 3: Dev 3, If 0, Class=Mass Storage, Driver=usb-storage, 5000M >> |__ Port 6: Dev 4, If 0, Class=Mass Storage, Driver=usb-storage, 5000M >> /: Bus 01.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/15p, 480M >> >> lspci on the host: > > ... > >> Tracing using usbmon on the host shows: >> ffff88002ea45b40 558636438 S Bo:2:003:2 -115 31 = 55534243 63c20000 00000000 00000600 00000000 00000000 00000000 000000 >> ffff88002ea45b40 558636455 C Bo:2:003:2 0 31 > >> ffff88002ea45b40 558636459 S Bi:2:003:1 -115 13 < >> ffff88002ea45b40 558636537 C Bi:2:003:1 0 13 = 55534253 63c20000 00000000 00 >> ffff88002ea45b40 558636593 S Bo:2:003:2 -115 31 = 55534243 64c20000 00000000 0000061e 00000001 00000000 00000000 000000 >> ffff88002ea45b40 558636610 C Bo:2:003:2 0 31 > >> ffff88002ea45b40 558636627 S Bi:2:003:1 -115 13 < >> ffff88002ea45b40 558636669 C Bi:2:003:1 0 13 = 55534253 64c20000 00000000 00 >> ffff88002ea45b40 558636748 S Bo:2:003:2 -115 31 = 55534243 65c20000 00e00100 80000a28 00000000 000000f0 00000000 000000 >> ffff88002ea45b40 558636757 C Bo:2:003:2 0 31 > >> ffff880407982f00 558636765 S Bi:2:003:1 -115 122880 < >> ffff880407982f00 558637699 C Bi:2:003:1 0 122880 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 >> ffff88002ea45b40 558637717 S Bi:2:003:1 -115 13 < >> ffff88002ea45b40 558637728 C Bi:2:003:1 0 13 = 55534253 65c20000 00000000 00 >> ffff88002ea45b40 558637760 S Bo:2:003:2 -115 31 = 55534243 66c20000 00200000 80000a28 00000000 f0000010 00000000 000000 >> ffff88002ea45b40 558637778 C Bo:2:003:2 0 31 > >> ffff88040ca76a80 558637797 S Bi:2:003:1 -115 8192 < >> ffff88040ca76a80 558637892 C Bi:2:003:1 0 8192 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 >> ffff88002ea45b40 558637908 S Bi:2:003:1 -115 13 < >> ffff88002ea45b40 558637933 C Bi:2:003:1 0 13 = 55534253 66c20000 00000000 00 >> ffff88002ea45b40 558637959 S Bo:2:003:2 -115 31 = 55534243 67c20000 00e00100 80000a28 00000001 000000f0 00000000 000000 >> ffff88002ea45b40 558637973 C Bo:2:003:2 0 31 > >> ffff880407982f00 558637976 S Bi:2:003:1 -115 122880 < >> ffff880407982f00 558638898 C Bi:2:003:1 0 122880 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 >> ffff88002ea45b40 558638901 S Bi:2:003:1 -115 13 < >> ffff88002ea45b40 558638938 C Bi:2:003:1 0 13 = 55534253 67c20000 00000000 00 >> ffff88002ea45b40 558638976 S Bo:2:003:2 -115 31 = 55534243 68c20000 00200000 80000a28 00000001 f0000010 00000000 000000 >> ffff88002ea45b40 558638984 C Bo:2:003:2 0 31 > >> ffff88040ca76a80 558638992 S Bi:2:003:1 -115 8192 < >> ffff88040ca76a80 558639095 C Bi:2:003:1 0 8192 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 >> ffff88002ea45b40 558639110 S Bi:2:003:1 -115 13 < >> ffff88002ea45b40 558639136 C Bi:2:003:1 0 13 = 55534253 68c20000 00000000 00 >> >> Any ideas why the driver is requesting varying block sizes? > > The usb-storage driver requests what the block layer tells it to > request. I’m running a dd with a block size of 64k, so it seems to be aggregating 2 requests and then splits them again. > Unless you change the settings, the maximum number of blocks allowed in > a single transfer is 240 (i.e., 120 KB). Consequently, 128-KB reads > get broken up into 120 KB followed by 8 KB. (You can alter the default > by writing to /sys/block/sd*/queue/max_sectors_kb -- fill in the * > appropriately). I’ll give that a try. > >> It also seems odd that the mass storage gadget takes a long time to >> respond to the CBW of each read request (as it doesn�t actually need >> to return the data at that point). > > I don't know what you mean. The response time for the first READ CBW > was 9 microseconds (558636757 - 558636748 in the timestamp column); for > the second it was 18 us; then 14 us and 8 us for the third and fourth. > Those don't seem very long. > > Are you sure you're not looking at the time required to transfer the > actual data? I’m looking at the times between the CBW and the response to that. In the beginning it seemed that more often than not the 240 block request was taking 14-20us and the 16 block request was taking around 8us. I just went back to check the numbers and towards the end of the (1+ GB ) transfer I’m seeing more like 35us for both: ffff88002ea45b40 562458384 S Bo:2:003:2 -115 31 = 55534243 62e20000 00e00100 80000a28 00000ffe 000000f0 00000000 000000 ffff88002ea45b40 562458420 C Bo:2:003:2 0 31 > ffff880407982f00 562458422 S Bi:2:003:1 -115 122880 < ffff880407982f00 562459148 C Bi:2:003:1 0 122880 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 ffff88002ea45b40 562459151 S Bi:2:003:1 -115 13 < ffff88002ea45b40 562459176 C Bi:2:003:1 0 13 = 55534253 62e20000 00000000 00 ffff88002ea45b40 562459182 S Bo:2:003:2 -115 31 = 55534243 63e20000 00200000 80000a28 00000ffe f0000010 00000000 000000 ffff88002ea45b40 562459217 C Bo:2:003:2 0 31 > ffff880407982f00 562459219 S Bi:2:003:1 -115 8192 < ffff880407982f00 562459271 C Bi:2:003:1 0 8192 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 ffff88002ea45b40 562459273 S Bi:2:003:1 -115 13 < ffff88002ea45b40 562459311 C Bi:2:003:1 0 13 = 55534253 63e20000 00000000 00 ffff88002ea45b40 562459316 S Bo:2:003:2 -115 31 = 55534243 64e20000 00e00100 80000a28 00000fff 000000f0 00000000 000000 ffff88002ea45b40 562459351 C Bo:2:003:2 0 31 > ffff880407982f00 562459353 S Bi:2:003:1 -115 122880 < ffff880407982f00 562460079 C Bi:2:003:1 0 122880 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 ffff88002ea45b40 562460081 S Bi:2:003:1 -115 13 < ffff88002ea45b40 562460106 C Bi:2:003:1 0 13 = 55534253 64e20000 00000000 00 ffff88002ea45b40 562460112 S Bo:2:003:2 -115 31 = 55534243 65e20000 00200000 80000a28 00000fff f0000010 00000000 000000 ffff88002ea45b40 562460146 C Bo:2:003:2 0 31 > ffff880407982f00 562460148 S Bi:2:003:1 -115 8192 < ffff880407982f00 562460202 C Bi:2:003:1 0 8192 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 ffff88002ea45b40 562460204 S Bi:2:003:1 -115 13 < ffff88002ea45b40 562460242 C Bi:2:003:1 0 13 = 55534253 65e20000 00000000 00 So I guess that contradicts my initial observation as well. Note that both machines in question are not doing anything else. Both machine have a core i5 4690s (quad core 3.2Ghz) with 16GB of RAM, so I am not sure why there is a 35us delay... Back to the drawing board :( Paul. -- 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
