Problems with counting time intervals & SD performance

[attachment=0]bm_sd_rdwr.py[/attachment][attachment=0]bm_sd_rdwr.py[/attachment]

Hello colleagues!
I am trying to measure read and write operations on an external storage medium SD card.

I discovered the following feature of the time counting procedures - they show a strongly incorrect result. When conducting testing, I also measure the time with a wristwatch and find a discrepancy in the readings almost twice. One gets the impression that the procedures “utimr.tick_ms()” and other procedures for counting time have the wrong interrupt priority.

P.S. After doing such a test using the RTC, I found that he thinks it is naturally correct. But procedures that use even a hardware Timer2 (with callback function to counting) and other also count the time incorrectly.
For example, I give the program and the result of the work:

import pyb, machine, utime, sensor, image, os, gc

GPIO_LED_RED = 1
GPIO_LED_GREEN = 2
GPIO_LED_BLUE = 3
GPIO_LED_IR = 4

BLOCK_SIZE = 512
NUM_BLOCKS = 64 # 32768 байт

def SD_WR_Test():
    #os.remove('/data.txt')
    os.sync()
    f = open('/data.txt','wb')
    bytes = 0
    time_start = utime.ticks_ms()
    for n in range(1, 10000):
        bytes += f.write(fill_string)
    time_end = utime.ticks_ms()
    f.close()
    time_operation = (time_end - time_start)/1000.0
    speed = bytes / time_operation
    print("Write to SD: {} bytes, on times : {:.3f} sec, Speed: {:.3f} KBytes/sec".format(bytes, time_operation, speed / 1024))

def SD_RD_Test():
    gc.collect()
    buffer = bytearray(BLOCK_SIZE * NUM_BLOCKS)
    f = open('/data.txt','rb')
    bytes = 0
    time_start = utime.ticks_ms()
    for n in range(1, 10000):
        bytes += f.readinto(buffer)
    time_end = utime.ticks_ms()
    f.close()
    time_operation = (time_end - time_start)/1000.0
    speed = bytes / time_operation
    print("Read from SD: {} bytes, on times : {:.3f} sec, Speed: {:.3f} KBytes/sec".format(bytes, time_operation, speed / 1024))

pyb.LED(GPIO_LED_RED).on()

gc.collect()
print("Free heap memory: {} bytes".format(gc.mem_free()))

fill_string = 'A' * BLOCK_SIZE * NUM_BLOCKS
SD_WR_Test()
SD_RD_Test()

gc.collect()

print("Completed ! \r\n")
pyb.LED(GPIO_LED_RED).off()

while(True):
    pass

Results:

MicroPython v1.12-omv OpenMV v3.6.7 2020-07-20; OPENMV4P-STM32H743
Type “help()” for more information.

Free heap memory: 224736 bytes
Write to SD: 327680000 bytes, on times : 14.607 sec, Speed: 21907.303 KBytes/sec
Read from SD: 327647232 bytes, on times : 10.117 sec, Speed: 31626.766 KBytes/sec
Completed !

Real time 37sec, but in program - 14.607 !!!
Real time 15sec, but in program - 10.117 sec !!!

P.P.S:
Why such a big mistake? As an example, I took the Pycom LoPy4 board I have and it showed correct results when working with an SD card.
And there was a thought, but is the FPS measured correctly in the system as well?

Best regards, Eugeny
bm_sd_rdwr.py (1.74 KB)

Please post code using the code tag. Then formatting is kept.

Please use the pyb module .mills() to get the milliseconds.

ticks_ms() is for the fps counter. It’s not keeping track of time.

Regarding SD write performance. There’s margin on our end to improve that. Also, use bigger blocks of data. Like 32KB or more.

Ok, I’ll try later, report the results.

I replaced “utime.ticks_ms ()” with “pyb.millis ()”, and it had absolutely no effect on the result, there is a large time error.
As I said, I think there is a bug in the priorities of interrupt handling, either the timekeeping procedures or the SPI.

But there is good news, I am going to carry out a comprehensive test of performance and compatibility of various SD cards (potentially suitable), I have quite interesting specimens.

I’ll have to check the SD card code. We use the SDIO bus, so, it’s much faster than SPI. The DMA might have interrupts disabled. I’ll check. This code needs to be optimized but, it more or less works good enough so it hasn’t been a focus.

Greetings!
I tested the MicroSD cards that I found. Slightly changed the program for correct time tracking, using the hardware RTC. I would be very grateful to fix the work of millis () and tick_ms () in the future.
It was very unexpected to find that MicroSDXC cards with exFAT also work, although I have met somewhere on the forum that only SDHC cards up to 32Gb work. I ran the test program from the IDE, actually from RAM. 32 KB blocks were used for the exchange.
If the driver of exchange with the card is improved, I can also make a new test.

import pyb, machine, utime, sensor, image, gc, uos

LED_RED = 1
LED_GREEN = 2
LED_BLUE = 3
LED_IR = 4

BLOCK_SIZE = 512
NUM_BLOCKS = 64 # 32768 Bytes

def SD_WR_Test():
    # Synchronization operation
    uos.sync()
    # Create file
    f = open('/data.txt','wb')
    bytes = 0
    #time_start = utime.ticks_ms()
    #time_start = pyb.millis()
    time_rtc_start = rtc.datetime()
    for n in range(1, 10000):
        bytes += f.write(fill_string)
    #time_end = utime.ticks_ms()
    #time_end = pyb.millis()
    time_rtc_stop = rtc.datetime()
    f.close()
    #time_operation = (time_end - time_start)/1000.0
    time_operation = (time_rtc_stop[5] * 60.0 + time_rtc_stop[6] + (1.0 - time_rtc_stop[7] / 256.0)) - \
        (time_rtc_start[5] * 60.0 + time_rtc_start[6] + (1.0 - time_rtc_start[7] / 256.0))
    speed = bytes / time_operation
    print("Write to SD: {} bytes, in time: {:.3f} sec, Speed: {:.3f} KBytes/sec".format(bytes, time_operation, speed / 1024))

def SD_RD_Test():
    gc.collect()
    buffer = bytearray(BLOCK_SIZE * NUM_BLOCKS)
    # Open file in binary read mode
    f = open('/data.txt','rb')
    bytes = 0
    #time_start = utime.ticks_ms()
    #time_start = pyb.millis()
    time_rtc_start = rtc.datetime()
    for n in range(1, 10000):
        bytes += f.readinto(buffer)
    #time_end = utime.ticks_ms()
    #time_end = pyb.millis()
    time_rtc_stop = rtc.datetime()
    f.close()
    #time_operation = (time_end - time_start)/1000.0
    time_operation = (time_rtc_stop[5] * 60.0 + time_rtc_stop[6] + (1.0 - time_rtc_stop[7] / 256.0)) - \
        (time_rtc_start[5] * 60.0 + time_rtc_start[6] + (1.0 - time_rtc_start[7] / 256.0))
    speed = bytes / time_operation
    print("Read from SD: {} bytes, in time: {:.3f} sec, Speed: {:.3f} KBytes/sec".format(bytes, time_operation, speed / 1024))
    # Remove file
    uos.remove('/data.txt')


# Main
pyb.LED(LED_RED).on()

rtc = pyb.RTC()
# Any time base (year, month, day, weekday, hours, minutes, seconds, subseconds)
rtc.datetime((2014, 5, 1, 4, 13, 0, 0, 0))
pyb.delay(1000)

gc.collect()
print("Start testing ...")
print("Free heap memory: {} bytes".format(gc.mem_free()))
print("Statvfs info: {}".format(uos.statvfs('/')))

fill_string = 'A' * BLOCK_SIZE * NUM_BLOCKS
SD_WR_Test()
SD_RD_Test()

print("Completed ! \r\n")
pyb.LED(LED_RED).off()

while(True):
    pass

FINAL RESULTS:


Old cards and not working

Kingston 1Gb “MicroSD” [SDC/1GB-2P1A] Declared: - old card, but not used
Statvfs info: (16384, 16384, 62855, 62855, 62855, 0, 0, 0, 0, 255)
Write to SD: 327647232 bytes, in time: 88.797 sec, Speed: 3603.370 KBytes/sec
Read from SD: 327647232 bytes, in time: 22.875 sec, Speed: 13987.671 KBytes/sec

SanDisk Ultra 8 Gb “UHS-I U1” [SDSDQUAN-008G-G4A] Declared: "SPEED up to 30 MBs"
OLD CARD NOT WORK WITH OPENMV, BUT ON PC WORKS WELL !!!


microSDHC / UHS-I Class 10

ADATA Premier 8 Gb “UHS-I Class10” [AUSDH8GUICL10-R] Declared: Write 10 MBs, Read 50 MBs
Statvfs info: (32768, 32768, 236768, 236764, 236764, 0, 0, 0, 0, 255)
Write to SD: 327647232 bytes, in time: 35.816 sec, Speed: 8933.559 KBytes/sec
Read from SD: 327647232 bytes, in time: 17.832 sec, Speed: 17943.440 KBytes/sec

ADATA Premier 16 Gb “UHS-I Class10” [AUSDH16GUICL10-R] Declared: Write 10 MBs, Read 50 MBs
Statvfs info: (32768, 32768, 483040, 483039, 483039, 0, 0, 0, 0, 255)
Write to SD: 327647232 bytes, in time: 40.754 sec, Speed: 7851.223 KBytes/sec
Read from SD: 327647232 bytes, in time: 16.359 sec, Speed: 19558.693 KBytes/sec

SanDisk Ultra 16 Gb “UHS-I Class10” [SDSQUNS-016G-GN3MA] Declared: Write 10 MBs, Read 80 MBs
Statvfs info: (32768, 32768, 473472, 473471, 473471, 0, 0, 0, 0, 255)
Write to SD: 327647232 bytes, in time: 44.402 sec, Speed: 7206.106 KBytes/sec
Read from SD: 327647232 bytes, in time: 25.723 sec, Speed: 12439.150 KBytes/sec

SanDisk Ultra 32 Gb “UHS-I Class10” [SDSQUNS-032G-GN3MN] Declared: Write 10 MBs, Read 80 MBs
Statvfs info: (32768, 32768, 973584, 963582, 963582, 0, 0, 0, 0, 255)
Write to SD: 327647232 bytes, in time: 30.758 sec, Speed: 10402.820 KBytes/sec
Read from SD: 327647232 bytes, in time: 16.578 sec, Speed: 19300.614 KBytes/sec

Transcend Premium 16Gb “UHS-I Class10 200x” [TS16GUSDC10] Declared: Write 10 MBs, Read 30 MBs
Statvfs info: (32768, 32768, 485936, 367978, 367978, 0, 0, 0, 0, 255)
Write to SD: 327647232 bytes, in time: 40.570 sec, Speed: 7886.752 KBytes/sec
Read from SD: 327647232 bytes, in time: 16.734 sec, Speed: 19120.403 KBytes/sec


microSDHC / UHS-I U1

Mirex 32Gb “UHS-I U1 Class10” [13613-ADSUHS32] Declared: Write 45 MBs, Read 104 MBs
Statvfs info: (32768, 32768, 953824, 953823, 953823, 0, 0, 0, 0, 255)
Write to SD: 327647232 bytes, in time: 35.543 sec, Speed: 9002.287 KBytes/sec
Read from SD: 327647232 bytes, in time: 15.789 sec, Speed: 20265.167 KBytes/sec

Qumo 32Gb “UHS-I U1 Class10” [QM32GMICSDHC10U1] Declared: Write 10 MBs, Read 90 MBs
Statvfs info: (32768, 32768, 953792, 947937, 947937, 0, 0, 0, 0, 255)
Write to SD: 327647232 bytes, in time: 35.164 sec, Speed: 9099.290 KBytes/sec
Read from SD: 327647232 bytes, in time: 15.512 sec, Speed: 20627.501 KBytes/sec

Smartbuy 32 Gb “UHS-I U1 Class10” [SB32GBSDCL10-01] Declared: Write 20 MBs, Read 40 MBs
Statvfs info: (32768, 32768, 966016, 956015, 956015, 0, 0, 0, 0, 255)
Write to SD: 327647232 bytes, in time: 44.398 sec, Speed: 7206.740 KBytes/sec
Read from SD: 327647232 bytes, in time: 17.594 sec, Speed: 18186.459 KBytes/sec

Transcend Premium 8 Gb “UHS-I U1 Class10 400x” [TS8GUSDU1] Declared: Write 10 MBs, Read 60 MBs
Statvfs info: (32768, 32768, 239328, 233135, 233135, 0, 0, 0, 0, 255)
Write to SD: 327647232 bytes, in time: 33.781 sec, Speed: 9471.763 KBytes/sec
Read from SD: 327647232 bytes, in time: 16.246 sec, Speed: 19695.072 KBytes/sec


microSDHC / UHS-I U3

Kingston Canvas React microSDHC 32 Gb “UHS-I U3 A1 V30” [SDCR/32GBSP] Declared: Write 70 MBs, Read 100 MBs
Statvfs info: (32768, 32768, 948864, 948863, 948863, 0, 0, 0, 0, 255)
Write to SD: 327647232 bytes, in time: 30.723 sec, Speed: 10414.724 KBytes/sec
Read from SD: 327647232 bytes, in time: 18.867 sec, Speed: 16958.966 KBytes/sec

Panasonic 16 Gb “UHS-I U3 Class10” [RP-SMGB16GAK] Declared: Write 45 MBs, Read 95 MBs
Statvfs info: (32768, 32768, 488704, 488701, 488701, 0, 0, 0, 0, 255)
Write to SD: 327647232 bytes, in time: 31.602 sec, Speed: 10125.070 KBytes/sec
Read from SD: 327647232 bytes, in time: 20.766 sec, Speed: 15408.542 KBytes/sec

Sandisk Extreme 32 Gb “UHC-I U3” [SDSQXNE-032G-GN6AA] Declared: Write 40 MBs, Read 90 MBs
Statvfs info: (32768, 32768, 973584, 963584, 963584, 0, 0, 0, 0, 255)
Write to SD: 327647232 bytes, in time: 28.898 sec, Speed: 11072.155 KBytes/sec
Read from SD: 327647232 bytes, in time: 16.809 sec, Speed: 19035.976 KBytes/sec

Sony 16 Gb “UHC-I U3 95Mbs” [SR-16UX2] Declared: Write 60 MBs, Read 95 MBs
Statvfs info: (32768, 32768, 493280, 491059, 491059, 0, 0, 0, 0, 255)
Write to SD: 327647232 bytes, in time: 26.391 sec, Speed: 12124.305 KBytes/sec
Read from SD: 327647232 bytes, in time: 16.438 sec, Speed: 19465.734 KBytes/sec


microSDXC / UHS-I U1 & U3

Sandisk Extreme 64 Gb “UHC-I U3 A1 V30” [SDSQXAF-064G-GN6MA] Declared: Write 60 MBs, Read 100 MBs
Statvfs info: (131072, 131072, 486992, 484419, 484419, 0, 0, 0, 0, 255)
Write to SD: 327647232 bytes, in time: 24.492 sec, Speed: 13064.084 KBytes/sec
Read from SD: 327647232 bytes, in time: 16.109 sec, Speed: 19862.223 KBytes/sec

SanDisk Ultra 256 Gb “UHS-I U1 A1” [SDSQUAR-256G-GN6MA] Declared: Write 10-20 MBs, Read 100 MBs (One)
Statvfs info: (262144, 262144, 975808, 975805, 975805, 0, 0, 0, 0, 255)
Write to SD: 327647232 bytes, in time: 29.207 sec, Speed: 10955.169 KBytes/sec
Read from SD: 327647232 bytes, in time: 16.785 sec, Speed: 19062.556 KBytes/sec

SanDisk Ultra 256 Gb “UHS-I U1 A1” [SDSQUAR-256G-GN6MA] Declared: Write 10-20 MBs, Read 100 MBs (Two)
Statvfs info: (262144, 262144, 975808, 975805, 975805, 0, 0, 0, 0, 255)
Write to SD: 327647232 bytes, in time: 21.160 sec, Speed: 15121.249 KBytes/sec
Read from SD: 327647232 bytes, in time: 16.570 sec, Speed: 19309.713 KBytes/sec

Transcend Ultimate 64 Gb “UHC-I U3 633x” [TS64GUSDU3] Declared: Write 85 MBs, Read 95 MBs
Statvfs info: (131072, 131072, 494328, 360944, 360944, 0, 0, 0, 0, 255)
Write to SD: 327647232 bytes, in time: 43.992 sec, Speed: 7273.291 KBytes/sec
Read from SD: 327647232 bytes, in time: 17.590 sec, Speed: 18190.496 KBytes/sec


microSDHC & microSDXC / UHS-II (UHS-I Compatible)

GoodRam IRPRO 32 Gb “UHS-II U3 V90” [IRP-M9BA-0320R11] Declared: Write 260 MBs, Read 280 MBs
Statvfs info: (32768, 32768, 979584, 979583, 979583, 0, 0, 0, 0, 255)
Write to SD: 327647232 bytes, in time: 19.492 sec, Speed: 16415.191 KBytes/sec
Read from SD: 327647232 bytes, in time: 15.980 sec, Speed: 20022.440 KBytes/sec


Other

Internal flash memory OpenMV4P (32Mb) 100 cycles for file 3.27Mb:
Statvfs info: (4096, 4096, 8183, 8177, 8177, 0, 0, 0, 0, 255)
Write to SD: 3244032 bytes, in time: 32.320 sec, Speed: 98.019 KBytes/sec
Read from SD: 3244032 bytes, in time: 0.066 sec, Speed: 47706.351 KBytes/sec

Nice work. Looks like the Quadspi chip we are using isn’t in DDR mode. The read performance is about 50 MB/s which matches using a 100 MHz with 4-bit per clock. I’ll check if that can go 2x faster.

We updated all our docs to say we support SDXC and exFAT.

As for the SD card. I think we should max out at 25 MB/s. It looks like you’re almost getting there but not quite. Maybe make the block size larger.

Hi, it looks like the quadspi flash speed is right where it should be. We aren’t using the DDR chip so it should max out around 50 MB/s.

As for the SD card, try bigger blocks and see if that helps. The SD card hardware uses DMA when doing multi-block writes. SD cards typically start an erase operation and then program once you finish your multi-block write. The only way to increase performance is to make that write/read size bigger. You should be able to get up to a max of 25 MB/s

Not sure why this is the case. But, the larger the write/read operation the faster SD cards go. That said, note that because of the FAT file system overhead you may not be able to go much faster as the file system layer will have to bail on writing to the disk in one go when switching to the new sector to write to as it will have to stop the write, read/write the FAT, and then continue.

To note, OSes get around this by loading the whole FAT (read how the FAT file system works) into RAM and then only flushing that when they want to. This allows much higher performance. But, it requires many megabytes of RAM to be stored. FATFs doesn’t support this so it’s performance is capped to the maximum write-able block size of the FAT partition.

If you want to make your disk a lot faster reformat it with huge FAT sectors.

Use exFAT which huge clusters: exFAT Filesystem

http://elm-chan.org/docs/mmc/mmc_e.html

Thanks!
When formatting, the system also asks for the sector size. I’ll have to experiment. Earlier I tried to change the block size to 64K, at first glance the increase is not noticeable.
I will try to approach this issue in more detail.

Yeah, the two things slowing it down are this:

  1. After writing out a cluster fatfs has to read the fat again to find the next free cluster. So, basically there’s a small read and write that happen between every large cluster write. These smaller ops are very slow. This is what kills performance. As mentioned before, modern OSes will avoid these small read/write by caching the FAT.

  2. The SD card has internal erase block sizes. Moving data in blocks up to the erase block size should improve performance. Beyond that not so much.

Issue #1 is where most of the speed is lost though. All you can do to fix this is make the cluster size very large. I suggest exFAT with 128k or larger clusters. This allows larger multi block writes which give you the best speed. But, this is limited by #2.

Cards only go into their highest performance modes when you do a multi block operation and never stop (by caching most of the FS in RAM).