TeensyDigital
Well-known member
I have been using LittleFS for a QSPI data logging application for the last year on a T4.1 with a 64Mb W25Q512JVEIQ NOR chip. This is being used to log flight telemetry on amateur test rockets, so it is a very volatile environment. To get reliable crash data I need to open, write, and close the files each time, otherwise I risk losing whatever has not been "saved" by a close. I have an old Mac that was running 1.54 beta10 and Little FS to this chip was consistently opening-writing 100 characters-and-closing about 6.5 times a second (150ms). But I recently bought a new Mac and dropped in Teensyduino 1.56 and my LittleFS logging performance completely tanked, causing other processes on my flight computer to back-up. So, I created a simple benchmark program to open, write, and close and I compiled it under the old computer and the new computer with the same T4.1 hardware. Under 1.56 the performance is about 2-3X slower and very erratic. Under 1.54 beta10 it is consistent and fast.
Did something significant change in LittleFS when it went GA? Is it possible I am missing something else in the environment or board settings? (CPU speed and optimize settings are the same for both). Any insight would be appreciated. I will likely be re-writing my logging handler to queue write requests in memory and keep the file open with fast write speeds and then close-and-reopen it every 750ms to "save" intervals. This would only put at risk 750ms worth of data, but would complicate the logging thread.
Here is the code I am running to benchmark 1.54b10 vs. 1.56.
Here is the output from 1.54 beta 10:
LittleFS Open Close Write Speed Test
Volume size 64 MByte
Completed 100 open/write/close in a total of 15400 ms - avg tx/ms = 154
Per Tx in Micros: Avg open: 555 Avg print: 153443 Avg close: 0
Completed 100 open/write/close in a total of 15400 ms - avg tx/ms = 154
Per Tx in Micros: Avg open: 555 Avg print: 153442 Avg close: 0
Completed 100 open/write/close in a total of 15400 ms - avg tx/ms = 154
Per Tx in Micros: Avg open: 555 Avg print: 153442 Avg close: 0
Completed 100 open/write/close in a total of 15400 ms - avg tx/ms = 154
Per Tx in Micros: Avg open: 555 Avg print: 153441 Avg close: 0
Completed 100 open/write/close in a total of 15400 ms - avg tx/ms = 154
Per Tx in Micros: Avg open: 555 Avg print: 153442 Avg close: 0
Completed 100 open/write/close in a total of 15400 ms - avg tx/ms = 154
Per Tx in Micros: Avg open: 555 Avg print: 153443 Avg close: 0
Completed 100 open/write/close in a total of 15400 ms - avg tx/ms = 154
Per Tx in Micros: Avg open: 555 Avg print: 153442 Avg close: 0
Completed 100 open/write/close in a total of 15399 ms - avg tx/ms = 153
Per Tx in Micros: Avg open: 555 Avg print: 153442 Avg close: 0
Completed 100 open/write/close in a total of 15400 ms - avg tx/ms = 154
Per Tx in Micros: Avg open: 555 Avg print: 153442 Avg close: 0
Here is the output from 1.56
LittleFS Open Close Write Speed Test
Volume size 64 MByte
Completed 100 open/write/close in a total of 27255 ms - avg tx/ms = 272
Per Tx in Micros: Avg open: 5580 Avg print: 258644 Avg close: 8332
Completed 100 open/write/close in a total of 31456 ms - avg tx/ms = 314
Per Tx in Micros: Avg open: 14013 Avg print: 296760 Avg close: 3785
Completed 100 open/write/close in a total of 34387 ms - avg tx/ms = 343
Per Tx in Micros: Avg open: 14306 Avg print: 325879 Avg close: 3685
Completed 100 open/write/close in a total of 36042 ms - avg tx/ms = 360
Per Tx in Micros: Avg open: 6094 Avg print: 353692 Avg close: 625
Completed 100 open/write/close in a total of 39877 ms - avg tx/ms = 398
Per Tx in Micros: Avg open: 13057 Avg print: 382008 Avg close: 3710
Completed 100 open/write/close in a total of 40901 ms - avg tx/ms = 409
Per Tx in Micros: Avg open: 13323 Avg print: 392006 Avg close: 3679
Completed 100 open/write/close in a total of 29031 ms - avg tx/ms = 290
Per Tx in Micros: Avg open: 13867 Avg print: 272617 Avg close: 3815
Completed 100 open/write/close in a total of 31994 ms - avg tx/ms = 319
Per Tx in Micros: Avg open: 14309 Avg print: 301904 Avg close: 3730
Completed 100 open/write/close in a total of 33423 ms - avg tx/ms = 334
Per Tx in Micros: Avg open: 6376 Avg print: 327193 Avg close: 660
Did something significant change in LittleFS when it went GA? Is it possible I am missing something else in the environment or board settings? (CPU speed and optimize settings are the same for both). Any insight would be appreciated. I will likely be re-writing my logging handler to queue write requests in memory and keep the file open with fast write speeds and then close-and-reopen it every 750ms to "save" intervals. This would only put at risk 750ms worth of data, but would complicate the logging thread.
Here is the code I am running to benchmark 1.54b10 vs. 1.56.
Code:
// measure the time to open, print/write, and close to a file
#include <LittleFS.h>
LittleFS_QSPIFlash myfs;
void setup() {
Serial.begin(115200);
Serial.println("LittleFS Open Close Write Speed Test");
if (!myfs.begin()) {
Serial.printf("Error starting %s\n", "SPI FLASH");
while (1) ; // stop here
}
Serial.printf("Volume size %d MByte\n", myfs.totalSize() / 1048576);
myfs.remove("stest.txt");
}
void loop() {
unsigned long startTime = 0;
unsigned long goTime = 0;
int openTime = 0;
int printTime = 0;
int closeTime = 0;
int totalTime = 0;
startTime = millis();
for(int n=0; n < 100; n++) {
goTime = micros();
File myfile = myfs.open("stest.txt", FILE_WRITE);
if(myfile) {
openTime += (micros() - goTime);
goTime = micros();
myfile.println("12345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890");
printTime += (micros() - goTime);
goTime = micros();
myfile.close();
closeTime += (micros() - goTime);
}
}
totalTime = millis() - startTime;
Serial.print("Completed 100 open/write/close in a total of ");
Serial.print(totalTime);
Serial.print(" ms - avg tx/ms = ");
Serial.println(totalTime/100);
Serial.print("Per Tx in Micros: Avg open: ");Serial.print(openTime/100);Serial.print(" Avg print: ");Serial.print(printTime/100);Serial.print(" Avg close: ");Serial.println(closeTime/100);
openTime = 0;
printTime = 0;
closeTime = 0;
totalTime = 0;
delay(2000);
}
Here is the output from 1.54 beta 10:
LittleFS Open Close Write Speed Test
Volume size 64 MByte
Completed 100 open/write/close in a total of 15400 ms - avg tx/ms = 154
Per Tx in Micros: Avg open: 555 Avg print: 153443 Avg close: 0
Completed 100 open/write/close in a total of 15400 ms - avg tx/ms = 154
Per Tx in Micros: Avg open: 555 Avg print: 153442 Avg close: 0
Completed 100 open/write/close in a total of 15400 ms - avg tx/ms = 154
Per Tx in Micros: Avg open: 555 Avg print: 153442 Avg close: 0
Completed 100 open/write/close in a total of 15400 ms - avg tx/ms = 154
Per Tx in Micros: Avg open: 555 Avg print: 153441 Avg close: 0
Completed 100 open/write/close in a total of 15400 ms - avg tx/ms = 154
Per Tx in Micros: Avg open: 555 Avg print: 153442 Avg close: 0
Completed 100 open/write/close in a total of 15400 ms - avg tx/ms = 154
Per Tx in Micros: Avg open: 555 Avg print: 153443 Avg close: 0
Completed 100 open/write/close in a total of 15400 ms - avg tx/ms = 154
Per Tx in Micros: Avg open: 555 Avg print: 153442 Avg close: 0
Completed 100 open/write/close in a total of 15399 ms - avg tx/ms = 153
Per Tx in Micros: Avg open: 555 Avg print: 153442 Avg close: 0
Completed 100 open/write/close in a total of 15400 ms - avg tx/ms = 154
Per Tx in Micros: Avg open: 555 Avg print: 153442 Avg close: 0
Here is the output from 1.56
LittleFS Open Close Write Speed Test
Volume size 64 MByte
Completed 100 open/write/close in a total of 27255 ms - avg tx/ms = 272
Per Tx in Micros: Avg open: 5580 Avg print: 258644 Avg close: 8332
Completed 100 open/write/close in a total of 31456 ms - avg tx/ms = 314
Per Tx in Micros: Avg open: 14013 Avg print: 296760 Avg close: 3785
Completed 100 open/write/close in a total of 34387 ms - avg tx/ms = 343
Per Tx in Micros: Avg open: 14306 Avg print: 325879 Avg close: 3685
Completed 100 open/write/close in a total of 36042 ms - avg tx/ms = 360
Per Tx in Micros: Avg open: 6094 Avg print: 353692 Avg close: 625
Completed 100 open/write/close in a total of 39877 ms - avg tx/ms = 398
Per Tx in Micros: Avg open: 13057 Avg print: 382008 Avg close: 3710
Completed 100 open/write/close in a total of 40901 ms - avg tx/ms = 409
Per Tx in Micros: Avg open: 13323 Avg print: 392006 Avg close: 3679
Completed 100 open/write/close in a total of 29031 ms - avg tx/ms = 290
Per Tx in Micros: Avg open: 13867 Avg print: 272617 Avg close: 3815
Completed 100 open/write/close in a total of 31994 ms - avg tx/ms = 319
Per Tx in Micros: Avg open: 14309 Avg print: 301904 Avg close: 3730
Completed 100 open/write/close in a total of 33423 ms - avg tx/ms = 334
Per Tx in Micros: Avg open: 6376 Avg print: 327193 Avg close: 660