appending to file in SPIFFS gets slower as file grows

[brianjmurrell]

Basic Infos

Hardware

Hardware: NodeMCU 1.0 ESP-12E
Core Version: 2.4.0

Description

Appending to a file in SPIFFS gets slower as the file gets bigger.

Settings in IDE

Module: NodeMCU 1.0 ESP-12E
Flash Size: 4MB/3MB
CPU Frequency: 80Mhz
Flash Mode: ???
Flash Frequency: ???
Upload Using: SERIAL
Reset Method: ???

Sketch

#include <Arduino.h>
#include <FS.h>

void setup() {
  SPIFFS.begin()
}

void loop() {

  File f = SPIFFS.open("/stats.txt", "a");
    
  if (!f) {
    Serial.println("Failed to open /stats.txt");
    return;
  }
  
  f.println("A string to add to the file");

  f.close();

}

Debug Messages

NA.

What I find is that if I measure the time to run each iteration of the loop, it will start to take several thousand milliseconds to run just one iteration. At this point the file is just over 2MB.

I've tried running a sketch like this:

#include <FS.h>

void setup() {

  Serial.begin(115200);

  SPIFFS.begin();
  SPIFFS.remove("/stats.txt");

}

unsigned long last_millis = 0;

char msg[] = "1517604525,60,51,23,23,nan,14";
unsigned int msg_len = strlen(msg);

void loop() {

  unsigned long start = millis();
  File f = SPIFFS.open("/stats.txt", "a");
  if (!f) {
    Serial.println("Failed to open /stats.txt");
    return;
  }
  if (!f.println(msg)) {
      Serial.println("Failed to write to /stats.txt");
      return;
  }
  unsigned long fsize = f.size();
  f.close();
  unsigned long finish = millis();

  if (start - last_millis > 30000) {
    Serial.print("appending ");
    Serial.print(msg_len);
    Serial.print(" bytes to a file that is ");
    Serial.print(fsize);
    Serial.print(" bytes long took ");
    Serial.print(finish - start);
    Serial.println(" millis");
    last_millis = start;
  }
  
}

To get an idea of the scaling but it seemed to just stop appending after about 1MB or so. I will run it again and see how far it gets.

[devyte]

@pellepl is this incremental execution time for open-append-close expected behavior on SPIFFS side? I understand that a 2MB file is rather big for SPIFFS, so I suspect it's a consequence of the SPIFFS design, but I thought I'd ask you first :)

[brianjmurrell]

Using something similar to the above sketch, here's the scaling of time to append to a file:

appending 29 bytes to a file that is 221712 bytes long took 48 millis
appending 29 bytes to a file that is 311550 bytes long took 50 millis
appending 29 bytes to a file that is 383625 bytes long took 9 millis
appending 29 bytes to a file that is 432109 bytes long took 54 millis
appending 29 bytes to a file that is 469340 bytes long took 515 millis
appending 29 bytes to a file that is 494667 bytes long took 550 millis
appending 29 bytes to a file that is 514972 bytes long took 559 millis
appending 29 bytes to a file that is 532890 bytes long took 469 millis
appending 29 bytes to a file that is 552327 bytes long took 494 millis
appending 29 bytes to a file that is 570493 bytes long took 556 millis
appending 29 bytes to a file that is 587481 bytes long took 440 millis
appending 29 bytes to a file that is 602671 bytes long took 500 millis
appending 29 bytes to a file that is 613335 bytes long took 449 millis
appending 29 bytes to a file that is 620279 bytes long took 1466 millis
appending 29 bytes to a file that is 626014 bytes long took 2326 millis
appending 29 bytes to a file that is 631284 bytes long took 1688 millis
appending 29 bytes to a file that is 635717 bytes long took 497 millis
appending 29 bytes to a file that is 641545 bytes long took 1135 millis
appending 29 bytes to a file that is 646257 bytes long took 2510 millis
appending 29 bytes to a file that is 651961 bytes long took 2222 millis
appending 29 bytes to a file that is 656270 bytes long took 2507 millis
appending 29 bytes to a file that is 661509 bytes long took 2370 millis
appending 29 bytes to a file that is 665911 bytes long took 2448 millis
appending 29 bytes to a file that is 670375 bytes long took 2445 millis
appending 29 bytes to a file that is 675273 bytes long took 2334 millis
appending 29 bytes to a file that is 679613 bytes long took 2378 millis
appending 29 bytes to a file that is 684418 bytes long took 2573 millis
appending 29 bytes to a file that is 688510 bytes long took 2472 millis
appending 29 bytes to a file that is 692354 bytes long took 2423 millis
appending 29 bytes to a file that is 696818 bytes long took 2280 millis
appending 29 bytes to a file that is 700383 bytes long took 2585 millis
stopping, nothing new written to file

at some point after the last write, within 5 minutes, a write to the file resulted in the file not growing in size so the write loop aborts. But even within 700K you can see how badly it scales.

[Hiddenvision]

Does the Spiffs Read the current content and then append and save or does it just paste onto the end and update the pointers.?

[devyte]

@Hiddenvision the open is donein "a" mode, so append mode, which means open file and seek to end. There is no explicit reading through all the file content.
That doesn't mean there isn't an implicit read through the file content done somewhere.
The code in our repo is a relatively thin layer over the spiffs api, which hints at the performance issue being on spiffs side. The only reason I haven't closed it is because I haven't quite finished understanding that thin glue layer yet.
BTW, I said "performance issue", but in truth it could be a consequence of the spiffs design choice, like I mentioned above. Personally, I wouldn't create such large files on spiffs.

@brianjmurrell something to try: replace your code with a normal open, then lseek to the end, then write then close. Time each step, it could hint at which takes incrementally longer. Or maybe done in that way the timing is different and there is no issue.

[AntoTurc]

If you can add deepSleep inside your program you can improve your writing speed by a good amount. I had the same problem as you until I added a deepSleep between my writings.

a file given a filename will have spiffs search all blocks' first pages (the lookup pages) for object index headers - the file headers. Each found file header is then visited to see if the filename matches.
If lucky, the file is found quickly. If unlucky, lots of data needs to be filtered before the file is found.
(From SPIFFS wiki)

So that means that the writing speed variation increase as the memory increases. In my case, they're was some variations above 1mb as I could sometime see 350ms for a writing and 600ms for the next one.
The initial writing speed isn't great, but at least it stays a bit more consistent in the long run.

Hope it helps!

---

file size (mb) ; time to write (ms)
0,1   ;   370
0,3   ;   390
0,5   ;   415
0,7   ;   440
1,0   ;   480
1,1   ;   350-600
1,5   ;   350-670
2,0   ;   350-700

[earlephilhower]

SPIFFS is no longer maintained by the author. There are some weird corner cases when the filesystem is under heavy use involving GC/etc. We have added the ::gc() method which can be called as desired (because it may have a long runtime). The suggestion for issues like this is to mode to LittleFS which is presently under active support by the ARMbed folks.