From: Matthew Bright [mailto:Matthew.Bright@alliedtelesis.co.nz] Sent: Wednesday, June 22, 2016 11:42 AM To: Rajesh Bhagat rajesh.bhagat@nxp.com; marex@denx.de Cc: u-boot@lists.denx.de; Chris Packham Chris.Packham@alliedtelesis.co.nz; Mark Tomlinson Mark.Tomlinson@alliedtelesis.co.nz Subject: testing: [PATCH v7 0/3] common: usb_storage: Implement logic to calculate optimal usb maximum trasfer blocks
On 06/16/2016 12:35 PM, Rajesh Bhagat wrote:
Performs code cleanup by making common function for usb_stor_read/write and implements the logic to calculate the optimal usb maximum trasfer blocks instead of sending USB_MAX_XFER_BLK blocks which is 65535 and 20 in case of EHCI and other USB protocols respectively. Rajesh Bhagat (3): common: usb_storage: Make common function for usb_read_10/usb_write_10 common: usb_storage: Make common function for usb_stor_read/usb_stor_write common: usb_storage : Implement logic to calculate optimal usb maximum trasfer blocks common/usb_storage.c | 213 +++++++++++++++++++++++---------------------------- include/usb.h | 1 + 2 files changed, 98 insertions(+), 116 deletions(-)
Hi Rajesh & Marek
I have spend the last couple of days testing these patches on the v2016.05 release, with an usb mass storage device that is able to consistently reproduce the USB_MAX_XFER_BLK issue as described in the "Issue with USB mass storage (thumb drives)" u-boot thread.
http://lists.denx.de/pipermail/u-boot/2016-February/244464.html%E2%80%8B
Hello Matt,
I can confirm the patch correctly increases the max transfer bocks after a successful read, and decreases the max transfer bocks after a read failure. However, I have noticed that once the ehci time out error occurs, the usb device appears to lock up. When in this state the usb device will stop responding to any further transfers. This behavior is independent of the number of blocks, and will continue until the ehci has been reset.
I believe the lockup behavior mentioned by you to be device specific quirk. I tested 3 pen drives, which recovered from EHCI timeout behavior by reducing the number of blocks (check below output):
USB write: device 0 block # 0, count 524288 ... usb_stor_read_write: retry #2, cur_xfer_blks 4095, smallblks 4095 usb_stor_read_write: retry #2, cur_xfer_blks 8191, smallblks 8191 usb_stor_read_write: retry #2, cur_xfer_blks 16383, smallblks 16383 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 65535, smallblks 65535 EHCI timed out on TD - token=0xa6008c80 usb_stor_read_write: retry #1, cur_xfer_blks 32767, smallblks 32767 <== usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 4114 524288 blocks write: OK
USB read: device 0 block # 0, count 524288 ... usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 65535, smallblks 65535 EHCI timed out on TD - token=0x2c008d80 usb_stor_read_write: retry #1, cur_xfer_blks 32767, smallblks 32767 <== usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 32767 usb_stor_read_write: retry #2, cur_xfer_blks 32767, smallblks 16 524288 blocks read: OK
Best Regards, Rajesh Bhagat
The following debug output demonstrates this behavior:
(note: the retry attempts has been set to 4)
=> fatload usb 0:auto 0x1000000 test.rel
(where test.rel is dd if=/dev/urandom of=test.rel bs=32M count=2)
usb_stor_read_write: udev 0
usb_stor_read_write: dev 0 startblk 0, blccnt 1 buffer 7fb0d980 usb_stor_read_write: retry #4, cur_xfer_blks 4095, smallblks 1 usb_read_write_10: start 0 blocks 1 usb_stor_read_write: end startblk 1, blccnt 1 buffer 7fb0db80
(40 further transfers occur with blccnt bewteen 1 and 8 blocks)
usb_stor_read_write: udev 0
usb_stor_read_write: dev 0 startblk 169a0, blccnt 20000 buffer 1000000 usb_stor_read_write: retry #4, cur_xfer_blks 4095, smallblks 4095 usb_read_write_10: start 169a0 blocks 4095 usb_stor_read_write: retry #4, cur_xfer_blks 8191, smallblks 8191 usb_read_write_10: start 1799f blocks 8191 usb_stor_read_write: retry #4, cur_xfer_blks 16383, smallblks 16383 usb_read_write_10: start 1999e blocks 16383 usb_stor_read_write: retry #4, cur_xfer_blks 32767, smallblks 32767 usb_read_write_10: start 1d99d blocks 32767 usb_stor_read_write: retry #4, cur_xfer_blks 65535, smallblks 65535 usb_read_write_10: start 2599c blocks 65535 EHCI timed out on TD - token=0x26008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 usb_stor_read_write: retry #3, cur_xfer_blks 32767, smallblks 32767 usb_read_write_10: start 2599c blocks 32767 EHCI timed out on TD - token=0x801f8c80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x801f8c80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 usb_stor_read_write: retry #2, cur_xfer_blks 16383, smallblks 16383 usb_read_write_10: start 2599c blocks 16383 EHCI timed out on TD - token=0x801f8c80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x801f8c80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 usb_stor_read_write: retry #1, cur_xfer_blks 8191, smallblks 8191 usb_read_write_10: start 2599c blocks 8191 EHCI timed out on TD - token=0x801f8c80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x801f8c80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 usb_stor_read_write: retry #0, cur_xfer_blks 4095, smallblks 4095 usb_read_write_10: start 2599c blocks 4095 EHCI timed out on TD - token=0x801f8c80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x801f8c80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 usb_stor_read_write: end startblk 2599c, blccnt fff buffer 2dff800 Error reading cluster ** Unable to read file test.rel ** => fatload usb 0:auto 0x1000000 test.rel
usb_stor_read_write: udev 0
sb_stor_read_write: dev 0 startblk 0, blccnt 1 buffer 7fb0d980 usb_stor_read_write: retry #4, cur_xfer_blks 4095, smallblks 1 usb_read_write_10: start 0 blocks 1 EHCI timed out on TD - token=0x801f8c80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x801f8c80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 usb_stor_read_write: retry #3, cur_xfer_blks 4095, smallblks 1 usb_read_write_10: start 0 blocks 1 EHCI timed out on TD - token=0x801f8c80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x801f8c80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 usb_stor_read_write: retry #2, cur_xfer_blks 4095, smallblks 1 usb_read_write_10: start 0 blocks 1 EHCI timed out on TD - token=0x801f8c80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x801f8c80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 usb_stor_read_write: retry #1, cur_xfer_blks 4095, smallblks 1 usb_read_write_10: start 0 blocks 1 EHCI timed out on TD - token=0x801f8c80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x801f8c80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 usb_stor_read_write: retry #0, cur_xfer_blks 4095, smallblks 1 usb_read_write_10: start 0 blocks 1 EHCI timed out on TD - token=0x801f8c80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x801f8c80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 EHCI timed out on TD - token=0x80008d80 usb_stor_read_write: end startblk 0, blccnt 1 buffer 7fb0d980 ** Can't read partition table on 0:0 **
(usb_read_write_10 is repeated 15 more times producing the same errors)
** No valid partitions found ** => usb reset resetting USB... USB0: USB EHCI 1.00 scanning bus 0 for devices... 2 USB Device(s) found scanning usb for storage devices... usb_stor_read_write: udev 0
usb_stor_read_write: dev 0 startblk 0, blccnt 1 buffer 7fb0d980 usb_stor_read_write: retry #4, cur_xfer_blks 4095, smallblks 1 usb_read_write_10: start 0 blocks 1 usb_stor_read_write: end startblk 1, blccnt 1 buffer 7fb0db80 1 Storage Device(s) found => fatload usb 0:auto 0x1000000 test.rel
usb_stor_read_write: udev 0
usb_stor_read_write: dev 0 startblk 0, blccnt 1 buffer 7fb0d980 usb_stor_read_write: retry #4, cur_xfer_blks 4095, smallblks 1 usb_read_write_10: start 0 blocks 1 usb_stor_read_write: end startblk 1, blccnt 1 buffer 7fb0db80
(transfers continues on happily until 65535 blocks is hit again)
This debug output shows the ehci timeout error occur for a transfer with 65535 blocks (as expected) however the timeout error continues for each proceeding transfer. This occurs even though the number of blocks are reduced back to what should be an acceptable number.
I am currently unsure if this "lock up" behavior is simply a quirk of the specific usb device that I am using. However, if such behavior is common, then it could render this fix moot. This is assuming that the ehci cannot be reset part way through a transfer (i.e. after the echi time out error occurs).
I have been able to consistently reproduce this "lock up" behavior on a single 4-GB Apacer usb flash device (details below). However I have been unable to reproduce this behavior on several 8GB counterparts as they appear to work fine with the maximum possible block size.
=> usb info 1: Hub, USB Revision 2.0 - u-boot EHCI Host Controller - Class: Hub - PacketSize: 64 Configurations: 1 - Vendor: 0x0000 Product 0x0000 Version 1.0 Configuration: 1 - Interfaces: 1 Self Powered 0mA Interface: 0 - Alternate Setting 0, Endpoints: 1 - Class Hub - Endpoint 1 In Interrupt MaxPacket 2048 Interval 255ms
2: Mass Storage, USB Revision 2.0 - USB FLASH DRIVE AP9BDE1B0918CBDB - Class: (from Interface) Mass Storage - PacketSize: 64 Configurations: 1 - Vendor: 0x1005 Product 0xb113 Version 1.0 Configuration: 1 - Interfaces: 1 Bus Powered 500mA Interface: 0 - Alternate Setting 0, Endpoints: 2 - Class Mass Storage, Transp. SCSI, Bulk only - Endpoint 2 In Bulk MaxPacket 512 - Endpoint 1 Out Bulk MaxPacket 512
I think this patch is a good solution to the original problem. Please let me know if there is anything I can do to help.
Cheers.
- Matt Bright