USB Mass Storage file transfert extremely slow

[Ben_Squar3d]

Hi,

I have a FAT file system that I use with an USB Mass Storage feature. I use the mx25r64 NOR flash (the same as the nrf7002dk evalboard). I am working on ncs 3.0.2.

It takes around 50s to transfert a file of 1Mo.  This is extremely slow and I would like to know why. 

Here is the timings of block erase and page programming of the MX25R6435F according to datasheet :

If we need to erase all bytes before writing, according to the datasheet it would take (1Mo/32kB)*0.5s = 15.6s (typical erase time is 0.2s but it is up to 1.5s so let's take 0.5s average). Programming 1Mo takes less than 1s. So between 15s and 20s is expected if we erase 1Mo before writing 1Mo. But I measured 49s

Here is the part where I configure the spi bus in my device tree :

&spi4 {
    compatible = "nordic,nrf-spim";
    status = "okay";
    pinctrl-0 = <&spi4_default>;
    pinctrl-1 = <&spi4_sleep>;
    pinctrl-names = "default", "sleep";
    cs-gpios = <&gpio0 9 GPIO_ACTIVE_LOW>;
    mx25r64: mx25r6435f@0 {
        compatible = "jedec,spi-nor";
        reg = <0>;
        spi-max-frequency = <33000000>;
        jedec-id = [c2 28 17];
        sfdp-bfp = [
            e5 20 f1 ff ff ff ff 03 44 eb 08 6b 08 3b 04 bb
            ee ff ff ff ff ff 00 ff ff ff 00 ff 0c 20 0f 52
            10 d8 00 ff 23 72 f5 00 82 ed 04 cc 44 83 68 44
            30 b0 30 b0 f7 c4 d5 5c 00 be 29 ff f0 d0 ff ff
        ];
        size = <67108864>;
        has-dpd;
        t-enter-dpd = <10000>;
        t-exit-dpd = <5000>;
    };
};

Here is the part where I am defined my fatfs partition in the pm_static :

fatfs_storage:
  address: 0x4d8000
  affiliation:
  - disk
  device: DT_CHOSEN(nordic_pm_ext_flash)
  end_address: 0x6d4000
  extra_params:
    disk_cache_size: 0x1000
    disk_name: USB
    disk_read_only: 0x0
    disk_sector_size: 0x200
  placement:
    align:
      start: 0x1000
    before:
    - end
  region: external_flash
  size: 0x1fc000

If I configure the sector size as 0x1000 (as it actually is for the chip) it crashes. 

Here is my .conf file overlay for USB and mass storage : 

# Enable mass storage
CONFIG_FILE_SYSTEM=y
CONFIG_FAT_FILESYSTEM_ELM=y
CONFIG_DISK_DRIVERS=y
CONFIG_DISK_DRIVER_FLASH=y

# Enable file system formatting
CONFIG_FILE_SYSTEM_MKFS=y

# Enable Long File Names
CONFIG_FS_FATFS_LFN=y
CONFIG_FS_FATFS_MULTI_PARTITION=y

# USB related configs
CONFIG_USB_MAX_NUM_TRANSFERS=16
CONFIG_USB_REQUEST_BUFFER_SIZE=512
CONFIG_USB_DEVICE_STACK=y

CONFIG_USB_DEVICE_PID=0x0008
CONFIG_USB_MASS_STORAGE=y
CONFIG_MASS_STORAGE_DISK_NAME="USB"
CONFIG_USB_DEVICE_LOG_LEVEL_ERR=y
CONFIG_USB_MASS_STORAGE_LOG_LEVEL_ERR=y
CONFIG_USB_DEVICE_INITIALIZE_AT_BOOT=n
CONFIG_MASS_STORAGE_STACK_SIZE=1024

CONFIG_USB_MASS_STORAGE_LOG_LEVEL_DBG=y
CONFIG_USB_DEVICE_LOG_LEVEL_DBG=y

When I enable logs, here is what I have when I transfert a file : 

Fullscreen LOGS USB.txt Download

[00:00:24.104,431] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.262,542] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 249
[00:00:24.262,603] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.262,634] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.264,190] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 250
[00:00:24.264,221] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.264,221] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.265,808] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 251
[00:00:24.265,838] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.265,899] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.267,425] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 252
[00:00:24.267,486] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.267,517] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.269,012] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 253
[00:00:24.269,042] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.269,073] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.270,629] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 254
[00:00:24.270,629] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.270,690] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.272,186] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 255
[00:00:24.272,216] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.272,247] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.273,803] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 256
[00:00:24.273,834] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.273,895] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.432,495] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 257
[00:00:24.432,556] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.432,586] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.434,051] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 258
[00:00:24.434,082] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.434,112] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.435,668] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 259
[00:00:24.435,699] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.435,760] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.437,255] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 260
[00:00:24.437,286] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.437,316] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.438,873] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 261
[00:00:24.438,903] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.438,903] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.440,490] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 262
[00:00:24.440,521] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.440,551] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.442,077] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 263
[00:00:24.442,077] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.442,138] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.443,695] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 264
[00:00:24.443,725] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.443,725] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.601,409] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 265
[00:00:24.601,470] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.601,501] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.602,813] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 266
[00:00:24.602,844] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.602,874] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.604,217] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 267
[00:00:24.604,278] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.604,309] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.605,651] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 268
[00:00:24.605,712] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.605,743] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.607,208] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 269
[00:00:24.607,269] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.607,299] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.608,642] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 270
[00:00:24.608,703] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.608,734] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.610,137] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 271
[00:00:24.610,198] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.610,229] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.611,572] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 272
[00:00:24.611,602] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.611,633] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.769,409] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 273
[00:00:24.769,439] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.769,500] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.770,996] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 274
[00:00:24.770,996] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.771,057] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.772,613] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 275
[00:00:24.772,613] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.772,674] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.774,200] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 276
[00:00:24.774,261] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.774,291] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.775,787] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 277
[00:00:24.775,817] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.775,848] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.777,618] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 278
[00:00:24.777,618] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.777,679] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.779,205] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 279
[00:00:24.779,235] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.779,266] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.780,792] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 280
[00:00:24.780,822] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.780,853] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.939,666] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 281
[00:00:24.939,727] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.939,758] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.941,253] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 282
[00:00:24.941,284] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.941,314] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.942,840] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 283
[00:00:24.942,871] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.942,932] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.944,458] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 284
[00:00:24.944,488] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.944,549] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.946,044] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 285
[00:00:24.946,075] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.946,105] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.947,662] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 286
[00:00:24.947,692] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.947,723] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.949,310] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 287
[00:00:24.949,310] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.949,371] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:24.951,080] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 288
[00:00:24.951,080] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:24.951,141] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.109,191] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 289
[00:00:25.109,222] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.109,283] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.110,931] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 290
[00:00:25.110,961] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.110,961] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.112,487] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 291
[00:00:25.112,487] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.112,518] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.114,105] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 292
[00:00:25.114,196] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.114,196] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.115,814] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 293
[00:00:25.115,844] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.115,905] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.117,523] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 294
[00:00:25.117,523] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.117,553] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.119,110] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 295
[00:00:25.119,110] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.119,140] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.120,727] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 296
[00:00:25.120,758] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.120,758] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.229,675] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 297
[00:00:25.229,766] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.229,797] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.231,109] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 298
[00:00:25.231,140] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.231,170] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.232,513] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 299
[00:00:25.232,574] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.232,604] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.234,069] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 300
[00:00:25.234,100] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.234,130] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.235,504] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 301
[00:00:25.235,565] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.235,595] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.236,938] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 302
[00:00:25.236,968] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.236,999] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.238,342] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 303
[00:00:25.238,403] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.238,433] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.239,776] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 304
[00:00:25.239,807] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.239,837] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.397,521] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 305
[00:00:25.397,583] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.397,613] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.399,017] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 306
[00:00:25.399,017] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.399,047] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.566,192] <dbg> usb_msc: mass_storage_bulk_in: < BI - MSC_WAIT_CSW
[00:00:25.566,375] <dbg> usb_msc: mass_storage_bulk_out: > BO - MSC_READ_CBW
[00:00:25.566,406] <dbg> usb_msc: CBWDecode: >> WRITE
[00:00:25.566,406] <dbg> usb_msc: infoTransfer: LBA (block) : 0x133
[00:00:25.566,467] <dbg> usb_msc: infoTransfer: Size (block) : 0x80
[00:00:25.567,993] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 307
[00:00:25.567,993] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.568,054] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.569,671] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 308
[00:00:25.569,671] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.569,702] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.571,258] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 309
[00:00:25.571,289] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.571,289] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.572,875] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 310
[00:00:25.572,906] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.572,937] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.574,523] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 311
[00:00:25.574,523] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.574,554] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.576,080] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 312
[00:00:25.576,080] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.576,110] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.735,137] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 313
[00:00:25.735,198] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.735,229] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.736,816] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 314
[00:00:25.736,846] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.736,877] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.738,433] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 315
[00:00:25.738,464] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.738,494] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.740,020] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 316
[00:00:25.740,112] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.740,142] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.741,699] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 317
[00:00:25.741,699] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.741,729] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.743,316] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 318
[00:00:25.743,347] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.743,347] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.744,934] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 319
[00:00:25.744,964] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.744,995] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.746,520] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 320
[00:00:25.746,551] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.746,551] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.904,815] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 321
[00:00:25.904,907] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.904,937] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.906,250] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 322
[00:00:25.906,250] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.906,311] <dbg> usb_msc: mass_thread_main: sem 3
[00:00:25.907,714] <dbg> usb_msc: memoryWrite: Disk WRITE Qd 323
[00:00:25.907,745] <dbg> usb_msc: mass_storage_bulk_out: > BO not clearing NAKs yet
[00:00:25.907,775] <dbg> usb_msc: mass_thread_main: sem 3

 These logs are not complete, but the idea is there : it seems that most of the time, something is blocking. Is the log "BO not clearing NAKs yet" normal?

I noticed that If I increase the CONFIG_MASS_STORAGE_STACK_SIZE to at least 5000, then the first transfert is fast (around 10s). Only the first transfert of each power cycle, which is strange. 

Finally, here is the USB mass storage sample configured for nRF7002DK and with 1Mo mass storage size to easily reproduce the issue : 

5148.mass.zip

Sorry for the long post and thank you in advance for your help. 

Best regards

[Håkon Alseth]

Hi Benoît,

 

Transferring 1 MB over USB should ideally be done in approx. ~5 seconds over the USB interface using USBD peripheral (200-300 kB/s max throughput), so I suspect that the delay is in the external flash.

 

I have two test files, created with dd:

dd if=/dev/urandom of=1mb_random_file.txt bs=1000K count=1
dd if=/dev/zero of=1mb_file.txt bs=1000K count=1

 

I consistently see a difference between the timing on these devices where all zero's will use approx. 45-46 seconds:

pv 1mb_file.txt | dd of=/media/hkn/5961-0800/1mb_file.txt
1000KiB 0:00:00 [95,2MiB/s] [===========================================================>] 100%            
2000+0 records in
2000+0 records out
1024000 bytes (1,0 MB, 1000 KiB) copied, 45,4911 s, 22,5 kB/s

 

And a random pattern will use approx. 34 seconds:

pv 1mb_random_file.txt | dd of=/media/hkn/5961-0800/1mb_file.txt
1000KiB 0:00:05 [ 167KiB/s] [===========================================================>] 100%            
2000+0 records in
2000+0 records out
1024000 bytes (1,0 MB, 1000 KiB) copied, 27,5651 s, 37,1 kB/s

So there is a dependency on writing bitwise '1' vs writing '0'.

 

What you could try is to set it up in a "high performance mode":

&mx25r64 {
	mxicy,mx25r-power-mode = "high-performance";
	partitions {
		compatible = "fixed-partitions";
		#address-cells = <1>;
		#size-cells = <1>;

		storage_partition: partition@0 {
			label = "storage";
			reg = <0x00000000 0x00100000>;
		};
	};
};

I believe the default boot up mode is a ultra-low power mode.

 

Using this high performance mode of the mx25r64, I see these numbers:

pv 1mb_ones_file.txt | dd of=/media/hkn/5961-0800/1mb_file.txt
1000KiB 0:00:00 [84,5MiB/s] [===========================================================>] 100%            
2000+0 records in
2000+0 records out
1024000 bytes (1,0 MB, 1000 KiB) copied, 15,6999 s, 65,2 kB/s
pv 1mb_file.txt | dd of=/media/hkn/5961-0800/1mb_file.txt
1000KiB 0:00:00 [98,6MiB/s] [===========================================================>] 100%            
2000+0 records in
2000+0 records out
1024000 bytes (1,0 MB, 1000 KiB) copied, 20,7949 s, 49,2 kB/s

 

Could you check if adding this mode also increases the performance to approx. 15-20 seconds at your end as well?

 

Here's my test files:

1mb_random_file.txt

1mb_ones_file.txt

1mb_file.txt

 

Kind regards,

Håkon

[Ben_Squar3d]

Hi,

Thank you very much for your quick and accurate answer! Indeed I see an improvement of the performance, but not as much as you.

For the 1mb_random file : ~20s 

For the all zero file : ~30s 

It is a real improvement (regarding the 49s at the beginning), but I need to estimate the additionnal current consumption to know if this tradeoff is acceptable.

Do you have improved speed when setting CONFIG_MASS_STORAGE_STACK_SIZE to at least 5000? 

Thank you very much for your help

Best regards

[Håkon Alseth]

Hi Benoît,

 

Glad to hear that you see an improvement as well.

Ben_Squar3d said:

Do you have improved speed when setting CONFIG_MASS_STORAGE_STACK_SIZE to at least 5000? 

I did try to adjust a bit here and there, and no option seemed to give a higher throughput, as the bottle neck does seem to be the external flash.

 

I tested on ubuntu 24.04.

If you are testing on Windows, there will be a bit of a USB CDC_ACM throughput difference as compared to linux. See here for similar test vectors:

 USBD with CDC ACM class Windows 10 maximum data rate 

Slightly newer measurement here:

 RE: [nRF52840] USB CDC baud rate 

  

Kind regards,

Håkon