Page 1 of 2
File write speed
Posted: Fri Apr 27, 2018 6:00 pm
by goatchurch
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)]
Re: File write speed
Posted: Fri Apr 27, 2018 8:22 pm
by dhylands
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.
Re: File write speed
Posted: Wed May 02, 2018 12:08 pm
by goatchurch
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?
Re: File write speed
Posted: Wed May 02, 2018 6:45 pm
by fdufnews
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.
Re: File write speed
Posted: Sun May 06, 2018 7:22 pm
by pythoncoder
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.
Re: File write speed
Posted: Sun May 13, 2018 4:57 pm
by goatchurch
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.
Re: File write speed
Posted: Mon May 14, 2018 11:53 am
by goatchurch
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).
Re: File write speed
Posted: Mon May 14, 2018 9:16 pm
by jickster
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
Re: File write speed
Posted: Mon May 14, 2018 9:24 pm
by jickster
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();
}
}
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.
Re: File write speed
Posted: Tue May 15, 2018 12:04 am
by jickster
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.