Zephyr FATFS Flash disk cache commit slow down by 200x when mass storage USB disconnected

[JustinL]

I am using nrf5340 on a custom board with NRF Connect sdk 2.3 with an SPI (Not QSPI) external NOR flash configured as a flash disk for use by USB mass storage and for access by my application.

With the board connected to my pc everything works as expected. The mass storage device appears on windows and I can write files to the external flash from my zephyr application with expected performance.

I have added a debug line to the flashdisc.c to measure the cache commit time.

A cache commit of 4096 bytes takes 35ms if the usb cable is plugged in.
However, if the usb cable is not plugged in then the the cache commit time increases to 6410ms !!!!

I have a test application that creates a file and writes writes 100k of 0xFF data to it.  

Below is the output of the test application.
I start the application with with no usb cable and then I plug it in.

You can see the mass storage driver connect the usb device and then immediate the cache commit time drop back down to 35ms.

This is a big problem for me as it makes my application unusable without the usb plugged in. 

Do you have any ideas of what is causing this change when the usb device is not present?

[00:00:09.202,606] <inf> wr_ecm: Creating new file
[00:00:09.207,916] <inf> wr_ecm: Writing 100000 bytes to target file
[00:00:24.872,161] <inf> wr_ecm: Writen 1000 bytes to target file. took 15658 ms
[00:00:24.885,009] <inf> wr_ecm: Writen 2000 bytes to target file. took 15670 ms
[00:00:24.897,796] <inf> wr_ecm: Writen 3000 bytes to target file. took 15683 ms
[00:00:24.910,614] <inf> wr_ecm: Writen 4000 bytes to target file. took 15696 ms
[00:00:25.922,973] <inf> flashdisk: JXL about to flashdisk_cache_commit
[00:00:32.332,824] <inf> flashdisk: flashdisk_cache_commit: 4096 write time: 6410ms
[00:00:33.945,648] <inf> flashdisk: JXL about to flashdisk_cache_commit
[00:00:40.354,736] <inf> flashdisk: flashdisk_cache_commit: 4096 write time: 6409ms
[00:00:40.567,596] <inf> wr_ecm: Writen 5000 bytes to target file. took 31353 ms
[00:00:40.580,444] <inf> wr_ecm: Writen 6000 bytes to target file. took 31366 ms
[00:00:40.593,292] <inf> wr_ecm: Writen 7000 bytes to target file. took 31379 ms
[00:00:40.606,140] <inf> wr_ecm: Writen 8000 bytes to target file. took 31392 ms
[00:00:41.618,927] <inf> flashdisk: JXL about to flashdisk_cache_commit
[00:00:41.673,858] <inf> usb_cdc_acm: Device suspended
[00:00:41.776,245] <inf> usb_cdc_acm: Device resumed
[00:00:41.781,707] <inf> usb_cdc_acm: from suspend
[00:00:41.853,027] <inf> flashdisk: flashdisk_cache_commit: 4096 write time: 234ms
[00:00:41.990,570] <inf> usb_cdc_acm: Device configured
[00:00:41.999,023] <inf> flashdisk: JXL about to flashdisk_cache_commit
[00:00:42.034,088] <inf> flashdisk: flashdisk_cache_commit: 4096 write time: 35ms
[00:00:42.051,300] <inf> wr_ecm: Writen 9000 bytes to target file. took 32837 ms
[00:00:42.064,453] <inf> wr_ecm: Writen 10000 bytes to target file. took 32850 ms
[00:00:42.077,667] <inf> wr_ecm: Writen 11000 bytes to target file. took 32863 ms
[00:00:42.091,857] <inf> wr_ecm: Writen 12000 bytes to target file. took 32877 ms
[00:00:42.187,011] <inf> flashdisk: JXL about to flashdisk_cache_commit
[00:00:42.223,022] <inf> flashdisk: flashdisk_cache_commit: 4096 write time: 35ms
[00:00:42.333,007] <inf> flashdisk: JXL about to flashdisk_cache_commit
[00:00:42.372,009] <inf> flashdisk: flashdisk_cache_commit: 4096 write time: 39ms

Thanks,

Justin

[JustinL]

I have narrowed it down to the spi_context_wait_for_completion() function. When the USB is not connected every third SPI transaction this function it takes 200ms, which is the configured SPI transaction timeout.

With the USB plugged in every third transaction takes just 1ms. So right there is the 200x difference.
(See output below).

The spi_context_wait_for_completion() function is waiting on a semaphore 

k_sem_take(&ctx->sync, timeout) where timeout is 200ms in my case.

So for some reason when the SPI transaction has finished it is not being signalled when there is no USB device.

 

[00:00:24.977,600] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 200ms

[00:00:24.986,877] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 0ms

[00:00:24.995,971] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 0ms

[00:00:25.205,139] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 200ms

[00:00:25.214,416] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 0ms

[00:00:25.223,510] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 0ms

[00:00:25.432,678] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 200ms

[00:00:25.441,955] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 0ms

[00:00:25.451,049] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 0ms

[00:00:25.660,186] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 200ms

[00:00:25.669,464] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 0ms

[00:00:25.678,558] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 0ms

[00:00:14.746,673] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 1ms

[00:00:14.755,798] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 0ms

[00:00:14.764,892] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 0ms

[00:00:14.774,688] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 1ms

[00:00:14.783,782] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 0ms

[00:00:14.792,877] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 0ms

[00:00:14.802,673] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 1ms

[00:00:14.811,798] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 0ms

[00:00:14.820,892] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 0ms

[00:00:14.830,688] <err> spi_nrfx_spim: spi_context_wait_for_completion elasped time: 1ms

[JustinL]

Hi,

The issue is resolved.

I had a old compilation unit still in the cmake which should not have been there. The file did contain some old SPI initialisation code. It was obtaining a handle to the nrfx SPIM instance. Not sure why that caused this issue but removing it from cmake resolved the issue.

Thanks for you help along the way.