SDC slow when calling f_write repeatedly

[bitto]

Hello.
Our system configuration is:
ChibiStudio 7
Olimex STM32 E407

We have noticed a poor performance in terms of bytes written per second when calling repeatedly f_write().

Surprisingly, performance dramatically increases when inserting a delay between each call to f_write()

Here is a sample code:

Code: Select all

  // write message in file
  for (i = 0; i < CHUNK_PER_FILE; i++) {
    startSTTime = chTimeNow();
    f_write(&activeFileP, &(fileChunkBuffer[0]), FILE_CHUNK_SIZE, &written);
    elapsedSTTime     = chTimeElapsedSince(startSTTime);
    totFileWriteTime += elapsedSTTime;
    fNumOfBytes      += written;
    chThdSleepMilliseconds(TIME_TO_WAIT);
  }

where:

FILE_CHUNK_SIZE = 4096
CHUNK_PER_FILE = 65536

Empirically we have found a threshold value of 4 ms for TIME_TO_WAIT

Below this threshold value, with our hardware configuration we measure rates around 1 Mb/s
Above the threshold value the speed boosts up to approximately 30 Mb/s

Any suggestions?

Thanks in advance

Alberto

[Giovanni]

Strange problem, it would be interesting to know if the time is lost inside FatFS or into the SDC driver, you could perform a measurement into the FatFS binding module and measure just the physical writes there.

Giovanni

[bitto]

Quite strange indeed!

Just to make sure, you mean it would be nice to measure the time spent in disk_write() defined in fatfs_diskio.c, correct?

Thanks

Alberto

[Giovanni]

Yes, that would allow to identify where the problem is, assuming there is a problem.

Giovanni

[bitto]

Giovanni,
here is the output of our tests, performed on two different uSD cards (and cross-cheched on two different Olimex boards.

In both cases we write 4096 times a 4096 bytes block.

CASE 1 CARD DETAILS: VERBATIM CLASS 4 SDHC [8 Gb]

Code: Select all

Sleep delay:                0 ms
time spent in f_write():    15247 ms
time spent in disk_write(): 15218 ms
number of bytes written:    16777216
average writing speed:      1100 Kb/s 

Sleep delay:                1 ms
time spent in f_write():    11143 ms
time spent in disk_write(): 11119 ms
number of bytes written:    16777216
average writing speed:      1505 Kb/s 

Sleep delay:                4 ms
time spent in f_write():    3260 ms
time spent in disk_write(): 3243 ms
number of bytes written:    16777216
average writing speed:      5146 Kb/s 

Sleep delay:                6 ms
time spent in f_write():    2193 ms
time spent in disk_write(): 2178 ms
number of bytes written:    16777216
average writing speed:      7650 Kb/s 

Sleep delay:                8 ms
time spent in f_write():    1777 ms
time spent in disk_write(): 1764 ms
number of bytes written:    16777216
average writing speed:      9441 Kb/s 

Sleep delay:                10 ms
time spent in f_write():    1644 ms
time spent in disk_write(): 1633 ms
number of bytes written:    16777216
average writing speed:      10205 Kb/s 

Sleep delay:                15 ms
time spent in f_write():    1456 ms
time spent in disk_write(): 1450 ms
number of bytes written:    16777216
average writing speed:      11522 Kb/s 

CASE 2 CARD DETAILS: SAMSUNG EVO UHS-1 [8 Gb]

Code: Select all

Sleep delay:                0 ms
time spent in f_write():    9076 ms
time spent in disk_write(): 9050 ms
number of bytes written:    16777216
average writing speed:      1848 Kb/s 

Sleep delay:                1 ms
time spent in f_write():    4900 ms
time spent in disk_write(): 4890 ms
number of bytes written:    16777216
average writing speed:      3423 Kb/s 

Sleep delay:                4 ms
time spent in f_write():    388 ms
time spent in disk_write(): 383 ms
number of bytes written:    16777216
average writing speed:      43240 Kb/s 

Sleep delay:                6 ms
time spent in f_write():    383 ms
time spent in disk_write(): 378 ms
number of bytes written:    16777216
average writing speed:      43804 Kb/s 

Sleep delay:                8 ms
time spent in f_write():    401 ms
time spent in disk_write(): 396 ms
number of bytes written:    16777216
average writing speed:      41838 Kb/s 

Sleep delay:                10 ms
time spent in f_write():    323 ms
time spent in disk_write(): 318 ms
number of bytes written:    16777216
average writing speed:      51941 Kb/s 

Sleep delay:                15 ms
time spent in f_write():    300 ms
time spent in disk_write(): 295 ms
number of bytes written:    16777216
average writing speed:      55924 Kb/s 

I guess the slight fluctuation in the second case giving a non monotonic increase in speed may be related to the millisecond granularity of systime.
Do you have any comments or suggestion for additional tests?

Thanks

Alberto

[Giovanni]

I wonder if the driver is just waiting for some internal card activity to finish, adding sleeps makes it wait less time.

Giovanni

[rew]

It looks as if some driver at some point does a:

Code: Select all

if (card_is_busy) sleep (10ms) 

So... look for this construct in the fatfs and SD card drivers.

Consider that sleeping for a certain time has a few "interface" calls. Consider using some define trickery to make all those sleep calls print where they are called.

The write speeds of 40Mbyte per second sounds like "too high". The most advanced SD cards will work at 100MHz, and then transfer half a byte per cycle. This results in 50Mbyte per second, using 4 datalines... If you're using the MMC over SPI driver that should not be possible.

In my experience most SD cards top out around 8 mbyte per second write speed. Are you sure your data is ending up on the card? Maybe there is an "if (card_is_busy) return ERROR;" somewhere that isn't caught in a higher layer.