zephyrproject-rtos / zephyr

Primary Git Repository for the Zephyr Project. Zephyr is a new generation, scalable, optimized, secure RTOS for multiple hardware architectures.
https://docs.zephyrproject.org
Apache License 2.0
10.95k stars 6.66k forks source link

usb mass storage on mimxrt595_evk_cm33 mount very slow #54695

Open hvbon2010 opened 1 year ago

hvbon2010 commented 1 year ago

Describe the bug Built and ran the usb mass storage demo with zephyr v3.2.0 on mimxrt595_evk_cm33, wait for 30 seconds to usb msc can mount to PC.

To Reproduce Steps to reproduce the behavior: build: west build -b mimxrt595_evk_cm33 zephyr/samples/subsys/usb/mass --pristine connect usb port to PC.

Expected behavior

Logs and console output

*** Booting Zephyr OS build zephyr-v3.2.0-4384-ga5e04ccd4ab9 ***
[00:38:16.011,298] <inf> usb_msc: Sect Count 64
[00:38:16.011,303] <inf> usb_msc: Memory Size 32768
[00:38:17.466,109] <inf> main: No file system selected
[00:38:17.466,118] <dbg> usb_device: usb_enable: lock usb_enable_lock mutex
[00:38:17.466,141] <dbg> usb_dc_mcux: usb_dc_attach: Attached
[00:38:17.466,192] <dbg> usb_device: composite_setup_ep_cb: set cb, ep: 0x1
[00:38:17.466,198] <dbg> usb_device: composite_setup_ep_cb: set cb, ep: 0x81
[00:38:17.466,209] <dbg> usb_device: usb_enable: unlock usb_enable_lock mutex
[00:38:17.466,216] <inf> main: The device is put in USB mass storage mode.

[00:38:17.778,356] <dbg> usb_msc: mass_storage_status_cb: USB device reset detected
--- 31 messages dropped ---
[00:38:17.824,034] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00
--- 8 messages dropped ---
[00:38:17.824,045] <dbg> usb_device: custom_handler: bRequest 0x06, wIndex 0x0000
[00:38:17.824,052] <dbg> usb_device: usb_get_descriptor: Get Descriptor request
[00:38:17.824,092] <dbg> usb_device: usb_handle_control_transfer: ep 0x80, status 0x02
[00:38:17.824,101] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x01
[00:38:17.824,293] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00
[00:38:17.824,303] <dbg> usb_device: custom_handler: bRequest 0x06, wIndex 0x0000
[00:38:17.824,310] <dbg> usb_device: usb_get_descriptor: Get Descriptor request
[00:38:17.824,345] <dbg> usb_device: usb_handle_control_transfer: ep 0x80, status 0x02
[00:38:17.824,355] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x01
[00:38:17.824,693] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00
[00:38:17.824,704] <dbg> usb_device: custom_handler: bRequest 0x09, wIndex 0x0000
[00:38:17.824,711] <dbg> usb_device: usb_set_configuration: Set Configuration 1 request
[00:38:17.824,721] <dbg> usb_device: set_endpoint: Set endpoint 0x81 type 2 MPS 512
[00:38:17.824,743] <dbg> usb_device: set_endpoint: Set endpoint 0x1 type 2 MPS 512
[00:38:17.824,791] <dbg> usb_msc: mass_storage_status_cb: USB device configured
[00:38:17.824,819] <dbg> usb_device: usb_handle_control_transfer: ep 0x80, status 0x02
[00:38:17.831,347] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00
[00:38:17.831,360] <dbg> usb_device: class_handler: bRequest 0xfe, wIndex 0x0000
[00:38:17.831,370] <dbg> usb_msc: mass_storage_class_handle_req: MSC_REQUEST_GET_MAX_LUN
[00:38:17.831,398] <dbg> usb_device: usb_handle_control_transfer: ep 0x80, status 0x02
[00:38:17.831,407] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x01
[00:38:17.831,659] <dbg> usb_msc: mass_storage_bulk_out: > BO - MSC_READ_CBW
[00:38:17.831,673] <dbg> usb_msc: CBWDecode: >> TUR
[00:38:17.831,725] <dbg> usb_msc: mass_storage_bulk_in: < BI - MSC_WAIT_CSW
[00:38:17.934,591] <dbg> usb_msc: mass_storage_bulk_out: > BO - MSC_READ_CBW
[00:38:17.934,601] <dbg> usb_msc: CBWDecode: >> INQ
[00:38:17.934,643] <dbg> usb_msc: mass_storage_bulk_in: < BI - MSC_SEND_CSW
[00:38:17.934,760] <dbg> usb_msc: mass_storage_bulk_in: < BI - MSC_WAIT_CSW
[00:38:17.935,353] <dbg> usb_msc: mass_storage_bulk_out: > BO - MSC_READ_CBW
[00:38:17.935,360] <dbg> usb_msc: CBWDecode: >> TUR
[00:38:17.935,414] <dbg> usb_msc: mass_storage_bulk_in: < BI - MSC_WAIT_CSW
[00:38:17.935,583] <dbg> usb_msc: mass_storage_bulk_out: > BO - MSC_READ_CBW
[00:38:17.935,590] <dbg> usb_msc: CBWDecode: >> INQ
[00:38:17.935,678] <dbg> usb_msc: mass_storage_bulk_in: < BI - MSC_SEND_CSW
[00:38:17.935,780] <dbg> usb_msc: mass_storage_bulk_in: < BI - MSC_WAIT_CSW
[00:38:18.131,360] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00
[00:38:18.131,389] <dbg> usb_device: custom_handler: bRequest 0x06, wIndex 0x0000
[00:38:18.131,394] <dbg> usb_device: usb_get_descriptor: Get Descriptor request
[00:38:18.131,415] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x01
[00:38:18.131,424] <dbg> usb_device: usb_handle_control_transfer: ep 0x80, status 0x02
[00:38:18.964,313] <dbg> usb_msc: mass_storage_bulk_out: > BO - MSC_READ_CBW
[00:38:18.964,320] <dbg> usb_msc: CBWDecode: >> TUR
[00:38:18.964,562] <dbg> usb_msc: mass_storage_bulk_in: < BI - MSC_WAIT_CSW
[00:38:18.964,886] <dbg> usb_msc: mass_storage_bulk_out: > BO - MSC_READ_CBW
[00:38:18.964,896] <dbg> usb_msc: CBWDecode: >> MEDIA_REMOVAL
[00:38:18.965,065] <dbg> usb_msc: mass_storage_bulk_in: < BI - MSC_WAIT_CSW
[00:38:18.965,522] <dbg> usb_msc: mass_storage_bulk_out: > BO - MSC_READ_CBW
[00:38:18.965,533] <dbg> usb_msc: CBWDecode: >> READ_CAPACITY
[00:38:18.965,669] <dbg> usb_msc: mass_storage_bulk_in: < BI - MSC_SEND_CSW
[00:38:18.965,958] <dbg> usb_msc: mass_storage_bulk_in: < BI - MSC_WAIT_CSW
[00:38:18.966,617] <dbg> usb_msc: mass_storage_bulk_out: > BO - MSC_READ_CBW
[00:38:18.966,625] <wrn> usb_msc: >> default CB[0] 5a
[00:38:18.966,643] <err> usb_dc_mcux: Failed to fill ep 0x81 buffer
[00:38:18.966,649] <err> usb_msc: usb write failure
[00:38:18.967,026] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00
[00:38:18.967,036] <dbg> usb_device: custom_handler: bRequest 0x00, wIndex 0x0081
[00:38:18.967,088] <dbg> usb_device: usb_handle_control_transfer: ep 0x80, status 0x02
[00:38:18.967,097] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x01
[00:38:18.967,606] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00
[00:38:18.967,614] <dbg> usb_device: custom_handler: bRequest 0x01, wIndex 0x0081
[00:38:18.967,622] <inf> usb_device: Clear halt ep 0x81
[00:38:18.967,637] <dbg> usb_msc: mass_storage_status_cb: USB unknown state
[00:38:18.967,660] <dbg> usb_device: usb_handle_control_transfer: ep 0x80, status 0x02

Environment (please complete the following information): OS: Linux (Ubuntu 22.04.1 LTS). Toolchain: Zephyr SDK 0.15.2

Additional context I found the issue was from MODE_SENSE10 command do not support by zephyr msc.

[00:38:18.966,625] <wrn> usb_msc: >> default CB[0] 5a
[00:38:18.966,643] <err> usb_dc_mcux: Failed to fill ep 0x81 buffer
[00:38:18.966,649] <err> usb_msc: usb write failure
hvbon2010 commented 1 year ago

Suggestion patch to fix this issue:

diff --git a/subsys/usb/device/class/msc.c b/subsys/usb/device/class/msc.c
index d01dadb35e..fbc3f012ea 100644
--- a/subsys/usb/device/class/msc.c
+++ b/subsys/usb/device/class/msc.c
@@ -349,6 +349,13 @@ static bool modeSense6(void)
        return write(sense6, sizeof(sense6));
 }

+static bool modeSense10(void)
+{
+       uint8_t sense10[] = { 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00 };
+
+       return write(sense10, sizeof(sense10));
+}
+
 static bool readFormatCapacity(void)
 {
        uint8_t capacity[] = { 0x00, 0x00, 0x00, 0x08,
@@ -556,6 +563,12 @@ static void CBWDecode(uint8_t *buf, uint16_t size)
                                modeSense6();
                        }
                        break;
+               case MODE_SENSE10:
+                       LOG_DBG(">> MODE_SENSE10");
+                       if (check_cbw_data_length()) {
+                               modeSense10();
+                       }
+                       break;
                case READ_FORMAT_CAPACITIES:
                        LOG_DBG(">> READ_FORMAT_CAPACITY");
                        if (check_cbw_data_length()) {
jfischer-no commented 1 year ago

I found the issue was from MODE_SENSE10 command do not support by zephyr msc.

[00:38:18.966,625] <wrn> usb_msc: >> default CB[0] 5a
[00:38:18.966,643] <err> usb_dc_mcux: Failed to fill ep 0x81 buffer
[00:38:18.966,649] <err> usb_msc: usb write failure

Maybe, but the issue is in the driver, IP3511 again. @mmahadevan108 please take a look.

tmon-nordic commented 1 year ago

uint8_t sense10[] = { 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00 };

If implement hard-coded response (like the rest in the old stack), please at least make it standard compliant.

uint8_t sense10[] = {0x00, 0x06, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00 }; is valid MODE SENSE(10) response for disk with no block descriptors.

github-actions[bot] commented 10 months ago

This issue has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this issue will automatically be closed in 14 days. Note, that you can always re-open a closed issue at any time.

github-actions[bot] commented 7 months ago

This issue has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this issue will automatically be closed in 14 days. Note, that you can always re-open a closed issue at any time.

bmulder-innoseis commented 7 months ago

I'm still having the same issue, I'm on nrf52480 with a SDMMC card backend using Fat32. Basically it makes the USB MSC nearly useless, as manually moving the SD card to a card reader and back is faster than using the zephyr MSC to transfer data.

tmon-nordic commented 7 months ago

I'm still having the same issue, I'm on nrf52480 with a SDMMC card backend using Fat32. Basically it makes the USB MSC nearly useless, as manually moving the SD card to a card reader and back is faster than using the zephyr MSC to transfer data.

Are you sure this is really the same issue? Note that nRF52840 has Full-Speed only USB (12 Mbps) so depending on the size of data you want to transfer the card reader might be faster.

For a standard compliant USB Mass Storage class implementation, check out the new experimental USB device stack. The old stack MSC implementation is very questionable and can lead to multiple silly handling loops (e.g. because it does not respond with proper error values). This is all fixed in the new experimental stack which has completely new implementation.

bmulder-innoseis commented 7 months ago

Are you sure this is really the same issue? Note that nRF52840 has Full-Speed only USB (12 Mbps) so depending on the size of data you want to transfer the card reader might be faster.

For a standard compliant USB Mass Storage class implementation, check out the new experimental USB device stack. The old stack MSC implementation is very questionable and can lead to multiple silly handling loops (e.g. because it does not respond with proper error values). This is all fixed in the new experimental stack which has completely new implementation.

The problem arises only when mounting. Copying files, for instance, has quite acceptable speeds. I tried the new USB device stack and it has the exact same issues for me.

tmon-nordic commented 7 months ago

The problem arises only when mounting. Copying files, for instance, has quite acceptable speeds. I tried the new USB device stack and it has the exact same issues for me.

Can you provide USB packet captures (with the new USB device stack)? Wireshark (usbmon) should be good enough to be able to roughly identify what is going on.

github-actions[bot] commented 5 months ago

This issue has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this issue will automatically be closed in 14 days. Note, that you can always re-open a closed issue at any time.

tmon-nordic commented 5 months ago

Can you run USB3CV MSC Tests? NRF52840, nRF5340 and nRF54H20 do pass the MSC Tests flawlessly with the new USB stack.

The MSC tests did reveal quite few issues in nRF54H20 driver during driver development so they are quite good in revealing various issues (the real root cause can be not clearly visible, but at least the test will fail somewhere if the driver is bad).

bmulder-innoseis commented 5 months ago

The problem arises only when mounting. Copying files, for instance, has quite acceptable speeds. I tried the new USB device stack and it has the exact same issues for me.

Can you provide USB packet captures (with the new USB device stack)? Wireshark (usbmon) should be good enough to be able to roughly identify what is going on.

@tmon-nordic I made a pcap file to show what is going on when connecting the device: https://we.tl/t-coywZdJyqp

It seems like a lot of SCSI data is sent over USB including a lot of zeroes (e.g. at 8 seconds) and only after ~24s it is ready transferring. I confirmed in my device that it is done reading from my SD card after those 24 seconds.

But 24s is a long time for it to show up correctly in my file explorer.

dleach02 commented 5 months ago

@jfischer-no can I assign this to you since it is being reported across multiple SOCs?

jfischer-no commented 5 months ago

@jfischer-no can I assign this to you since it is being reported across multiple SOCs?

Why? I see it is only reported for mimxrt595_evk_cm33.

dleach02 commented 5 months ago

@jfischer-no can I assign this to you since it is being reported across multiple SOCs?

Why? I see it is only reported for mimxrt595_evk_cm33.

@bmulder-innoseis is suggesting a similar problem on a nRF52840 but it seems the discussion thread may not have come to agreement with this.

jfischer-no commented 5 months ago

@bmulder-innoseis is suggesting a similar problem on a nRF52840 but it seems the discussion thread may not have come to agreement with this.

It looks different to me, I think it is more about throughput, nRF52840DK has a full-speed device controller and SD card is connected via SPI, the throughput is very low, the disk (SD card), based on the data from pcap file has no partitions and is formatted FAT32,

Filesystem type: FAT32   
OEM name: MSDOS5.0
Total sectors: 7744512
Total data clusters: 966144
Data size: 3957325824 (3.68555G)
Disk size: 3965190144 (3.69287G)
Bytes per sector: 512
Sectors per cluster: 8
Bytes per cluster: 4096
Reserved sectors: 1288
Sectors per FAT: 7548
Fat size: 3864576 (3.68555M)
FAT1 start address: 00000000000a1000
FAT2 start address: 0000000000450800
Data start address: 0000000000800000
Root directory cluster: 2
Disk label: NO NAME

During the mount, the host filesystem driver will read a lot of clusters, to get information about the filesystem, BPBs, FATs, RD... And because throughput is very low (about 127 kB/s, reading 1000 clusters) it will take some time (16s for me using disk with the same geometry). One will see the same low throughput coping files from the disk. The same SD card in a modern card reader, but forced to full-speed, has a throughput of about 789 kB/s. On nRF52840, the throughput for the bulk transfers is about 460 kB/s. Emulating the disk geometry above with #62286, I see throughput of about 386 kB/s (577 kB/s on FRDM K64F, there is also some MSC communication overhead and based on sector number emulation overhead). The limiting factor is the SD card connected via SPI interface and there is nothing we can do to improve it.

bmulder-innoseis commented 5 months ago

@jfischer-no from what do you get the throughput of 127 kb/s for the SD card via SPI? from the pcap or from known limitations? The SPI maximum throughput should be 24 mbit (3 MB). Now it will not actually hit those speeds, but 127 kB seems a bit on the low side to me. Or is there another part that bottlenecks it?

tmon-nordic commented 4 months ago

@tmon-nordic I made a pcap file to show what is going on when connecting the device: https://we.tl/t-coywZdJyqp

It seems like a lot of SCSI data is sent over USB including a lot of zeroes (e.g. at 8 seconds) and only after ~24s it is ready transferring. I confirmed in my device that it is done reading from my SD card after those 24 seconds.

But 24s is a long time for it to show up correctly in my file explorer.

Transfer expired. So unless you put it up again, I won't be able to take a look at it.

jfischer-no commented 4 months ago

@jfischer-no from what do you get the throughput of 127 kb/s for the SD card via SPI? from the pcap or from known limitations? The SPI maximum throughput should be 24 mbit (3 MB). Now it will not actually hit those speeds, but 127 kB seems a bit on the low side to me. Or is there another part that bottlenecks it?

127 kB/s on the host side, dd first 1000 clusters. The SPI clock can be 24MHz, but the data throughput will be much lower than 24Mbit.

github-actions[bot] commented 2 months ago

This issue has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this issue will automatically be closed in 14 days. Note, that you can always re-open a closed issue at any time.

github-actions[bot] commented 3 weeks ago

This issue has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this issue will automatically be closed in 14 days. Note, that you can always re-open a closed issue at any time.