File write speed

All ESP32 boards running MicroPython.
Target audience: MicroPython users with an ESP32 board.
goatchurch
Posts: 6
Joined: Tue Sep 12, 2017 10:26 am

File write speed

Post by goatchurch » Fri Apr 27, 2018 6:00 pm

I've noticed that you can write data to the file system very quickly, about 1.3miliseconds per 8 byte block, but then every time 4096 bytes gets written it stalls for 90miliseconds.

The same effect happens on the ESP8266 but a little slower.

Is there a way to avoid this stalling? Can the async features get round this?

[code]import time

fout = open("data2.txt", "w")
d = [ ]
t0 = time.ticks_ms()
n = 3000
sumdt = 0
i0 = 0
for i in range(n):
t = time.ticks_ms()
fout.write("%08d" % t)
dt = t-t0
if dt > 20:
d.append(((i-i0)*8, dt))
i0 = i
else:
sumdt += dt
t0 = t
fout.close()
t = time.ticks_ms()
print("closetime", t-t0)
if i == n-1:
print("meanshortwrite", sumdt/(n-len(d)))
print("longwrite_ms", d)
[/code]

result:
meanshortwrite 1.314295
longwrite_ms [(8, 47), (4096, 88), (4096, 89), (4096, 88), (4096, 88), (4096, 89)]

User avatar
dhylands
Posts: 3821
Joined: Mon Jan 06, 2014 6:08 pm
Location: Peachland, BC, Canada
Contact:

Re: File write speed

Post by dhylands » Fri Apr 27, 2018 8:22 pm

What's happening is that the small writes are being buffered. When a full block is available then it actually writes the block to flash.

goatchurch
Posts: 6
Joined: Tue Sep 12, 2017 10:26 am

Re: File write speed

Post by goatchurch » Wed May 02, 2018 12:08 pm

So I'm trying to log a temperature sensor at 10ms intervals to the flash (for analysis of time constants) and these 80ms gaps in the data are not ideal.

I think the file.write() eventually goes via flashbdev.esp.flash_write(), which then calls to the low-level Espressive function spi_flash_write(): https://dl.espressif.com/doc/esp-idf/la ... flash.html

It doesn't say about the time it takes for a write, but it does say they shut down the interrupts and the second co-processor in case it is writing the program memory (which it isn't in my application).

Any thoughts on a work-around? Is the same issue of 80ms stalls on flash write going to occur regardless of the programming language (eg for arduino C++ instead of Micropython on the ESP32)?

Last time I was doing this sort of thing I resorted to using two Teensy3.1s; the first reading the analog sensor data and sending it by UART line to the second which controlled the SD card (same as flash, I believe).

The UART serial buffers on the second Teensy (which I could make very big) continued to work and accept data from RX no matter what stalling happened in the SD-write functions (sometimes as much as 300ms). But in that case the Teensy can't execute code from the SD card, so there was no reason for its OS to shut off the interrupts.

Is it possible this solution won't even work on the ESP32, if it can't even keep the UART buffering working when it is writing to its flash memory?

fdufnews
Posts: 76
Joined: Mon Jul 25, 2016 11:31 am

Re: File write speed

Post by fdufnews » Wed May 02, 2018 6:45 pm

You can store the samples in a FIFO (10 samples deep will be enough) so they will accumulate during the 80ms dead time and when the write buffer is available you can resume the transfer.

User avatar
pythoncoder
Posts: 5956
Joined: Fri Jul 18, 2014 8:01 am
Location: UK
Contact:

Re: File write speed

Post by pythoncoder » Sun May 06, 2018 7:22 pm

Using uasyncio may be an option: the StreamWriter should be able to perform asynchronous file output. I haven't tested this with files or measured its performance but it works well writing large strings to slow UARTs.
Peter Hinch
Index to my micropython libraries.

goatchurch
Posts: 6
Joined: Tue Sep 12, 2017 10:26 am

Re: File write speed

Post by goatchurch » Sun May 13, 2018 4:57 pm

I know the UART (in and out) responds asynchronously.

It's the filewrite (using spi_flash_write) to the flash memory that has this delay of 80ms.

When I try to record a long sequence values from a sensor at high frequency (eg 2ms) I get these big gaps in the sensor data whenever the file hits a 4096byte page.

* I just realized I haven't tried timerchannel.irq() and writing the ADC values in a short ringbuffer to see if that escapes the problem, or if the spi_flash_write() disables these interrupts during its 80ms operation.

goatchurch
Posts: 6
Joined: Tue Sep 12, 2017 10:26 am

Re: File write speed

Post by goatchurch » Mon May 14, 2018 11:53 am

Nope, using hardware timers doesn't work. My code is here:
https://github.com/goatchurchprime/jupy ... gIRQ.ipynb

I've got a 10ms period and start it working with:

timer = Timer(0); timer.init(period=10, mode=Timer.PERIODIC, callback=irqtrigger)

The irqtrigger() stores time.ticks_ms() into a ringbuffer, from which the numbers are copied out and saved to a file as 8character decimals ("%08d" % t).

Interestingly, when I download and print the timings, they looked like:
..., 23662, 23672, 23682, 23779, 23780, 23780, 23780, 23780, 23780, 23787, 23797, 23807, 23817, ...

So the timer works very well in phase (at 2ms past the 10ms tick), then about 7 interrupts are held back and happen simultaneously when the spi_flash_write() occurs, before we resume on a different phase (at 7ms past the 10ms tick).

So I can't see a work-around within this device (async is probably afflicted by the same issue).

jickster
Posts: 629
Joined: Thu Sep 07, 2017 8:57 pm

Re: File write speed

Post by jickster » Mon May 14, 2018 9:16 pm

goatchurch wrote:
Mon May 14, 2018 11:53 am
Nope, using hardware timers doesn't work. My code is here:
https://github.com/goatchurchprime/jupy ... gIRQ.ipynb

I've got a 10ms period and start it working with:

timer = Timer(0); timer.init(period=10, mode=Timer.PERIODIC, callback=irqtrigger)

The irqtrigger() stores time.ticks_ms() into a ringbuffer, from which the numbers are copied out and saved to a file as 8character decimals ("%08d" % t).

Interestingly, when I download and print the timings, they looked like:
..., 23662, 23672, 23682, 23779, 23780, 23780, 23780, 23780, 23780, 23787, 23797, 23807, 23817, ...

So the timer works very well in phase (at 2ms past the 10ms tick), then about 7 interrupts are held back and happen simultaneously when the spi_flash_write() occurs, before we resume on a different phase (at 7ms past the 10ms tick).

So I can't see a work-around within this device (async is probably afflicted by the same issue).
Store your code in Internal ROM

jickster
Posts: 629
Joined: Thu Sep 07, 2017 8:57 pm

Re: File write speed

Post by jickster » Mon May 14, 2018 9:24 pm

goatchurch wrote:
Mon May 14, 2018 11:53 am
Nope, using hardware timers doesn't work. My code is here:
https://github.com/goatchurchprime/jupy ... gIRQ.ipynb

I've got a 10ms period and start it working with:

timer = Timer(0); timer.init(period=10, mode=Timer.PERIODIC, callback=irqtrigger)

The irqtrigger() stores time.ticks_ms() into a ringbuffer, from which the numbers are copied out and saved to a file as 8character decimals ("%08d" % t).

Interestingly, when I download and print the timings, they looked like:
..., 23662, 23672, 23682, 23779, 23780, 23780, 23780, 23780, 23780, 23787, 23797, 23807, 23817, ...

So the timer works very well in phase (at 2ms past the 10ms tick), then about 7 interrupts are held back and happen simultaneously when the spi_flash_write() occurs, before we resume on a different phase (at 7ms past the 10ms tick).

So I can't see a work-around within this device (async is probably afflicted by the same issue).
As far as I can know, the only time program code is written to flash is via the esptool.py, (Micropython files don't count as they are interpreted), so I don't see why the crazy assumption that spi_flash_write() would be writing stuff under the program counter?

Code: Select all

const int array[] = {1, 2, 3, 4, 5};
void func(int n)
{
    int i;
    for(int i = 0; i < n; i++)
    {
        array[i] = something();
    }
}
array is constant data and you could be writing over it when you write the data section but you might be executing func() which uses this data section.
Last edited by jickster on Tue May 15, 2018 12:06 am, edited 3 times in total.

jickster
Posts: 629
Joined: Thu Sep 07, 2017 8:57 pm

Re: File write speed

Post by jickster » Tue May 15, 2018 12:04 am

goatchurch wrote:
Mon May 14, 2018 11:53 am
Nope, using hardware timers doesn't work. My code is here:
https://github.com/goatchurchprime/jupy ... gIRQ.ipynb

I've got a 10ms period and start it working with:

timer = Timer(0); timer.init(period=10, mode=Timer.PERIODIC, callback=irqtrigger)

The irqtrigger() stores time.ticks_ms() into a ringbuffer, from which the numbers are copied out and saved to a file as 8character decimals ("%08d" % t).

Interestingly, when I download and print the timings, they looked like:
..., 23662, 23672, 23682, 23779, 23780, 23780, 23780, 23780, 23780, 23787, 23797, 23807, 23817, ...

So the timer works very well in phase (at 2ms past the 10ms tick), then about 7 interrupts are held back and happen simultaneously when the spi_flash_write() occurs, before we resume on a different phase (at 7ms past the 10ms tick).

So I can't see a work-around within this device (async is probably afflicted by the same issue).
I did some more reading on my micro K60P144M150 and I think it's a very common thing that simultaneous read and write to the same flash block is not possible.
So I think this is an issue with flash memory in general and nothing to do with ESP operating system and definitely has nothing to do with micropython.

Post Reply