File write speed
-
- Posts: 6
- Joined: Tue Sep 12, 2017 10:26 am
File write speed
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)]
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)]
Re: File write speed
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.
-
- Posts: 6
- Joined: Tue Sep 12, 2017 10:26 am
Re: File write speed
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?
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?
Re: File write speed
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.
- pythoncoder
- Posts: 5956
- Joined: Fri Jul 18, 2014 8:01 am
- Location: UK
- Contact:
Re: File write speed
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.
Index to my micropython libraries.
-
- Posts: 6
- Joined: Tue Sep 12, 2017 10:26 am
Re: File write speed
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.
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.
-
- Posts: 6
- Joined: Tue Sep 12, 2017 10:26 am
Re: File write speed
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).
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).
Re: File write speed
Store your code in Internal ROMgoatchurch wrote: ↑Mon May 14, 2018 11:53 amNope, 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).
Re: File write speed
goatchurch wrote: ↑Mon May 14, 2018 11:53 amNope, 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();
}
}
Last edited by jickster on Tue May 15, 2018 12:06 am, edited 3 times in total.
Re: File write speed
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.goatchurch wrote: ↑Mon May 14, 2018 11:53 amNope, 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).
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.