Logging to LittleFS looses all data unless close() is called

[tve]

I'm putting together a little data logger class that uses files on an esp32 to save log records. I'm using LittleFS. One issue I'm encountering is that LittleFS only updates the filesystem data structures when sync() or close() is called. In a logging context the natural thing to do is to keep the file open and periodically perform a write. This means that a spontaneous reset causes all logged data to be lost (I tested this).
The moddable File class does not export a sync() method, which means the only option is closing and reopening, which isn't terribly attractive (but I haven't tested the actual overhead). I'm thinking about adding a sync() method to File but am wondering whether I'm overlooking something...

Update: I just tested closing and reopening. It's a no-go. Here are some performance stats using an esp32-c3 with built-in flash:

• Just writing takes 7ms for 512 bytes when no flash block erase is required and 45-50ms when it is
• A separate repeating time running every 10ms has a worst-case interval of 60-65ms due tot the erase
• Closing and reopening after every write makes each write take 300-500ms
• The worst case hiccup to the timer is ~500ms (this could be improved by running the logger in a worker)
• Of course I don't know what the overhead of sync() is yet...

Update 2: for completeness, the note about committing to flash can be found in the Usage section of the LittleFS readme:

All POSIX operations, such as remove and rename, are atomic, even in event of power-loss. Additionally, file updates are not actually committed to the filesystem until sync or close is called on the file.

[phoddie]

Adding a flush/sync method seems reasonable. It wouldn't be supported everywhere though, so there's some thought to avoid misleading developers.

Another approach could be to build the sync into write. The write call already accepts a list of items to write. One of those could be a signal to flush.

file.write("one two three", file.flush);

flush could be a Symbol to guarantee it is unique. It would throw on file systems that don't support it, which would be a very clear indication that it isn't supported. ;)

[tve]

Another performance update:

• I moved the logger into its own worker, and I'm doing a close-reopen in a task 1ms after each regular log flush write. The result is that flushing now takes ~50ms (perhaps that's what it is after a fresh open and seek?) and the max hiccup to the 10ms timer in the main VM is ~120ms
• I then added a lfs_file_sync call at the end of the modLittlefs write function (i.e. always sync after write) and I'm not really seeing a big difference compared to close and reopen (the values are perhaps 50ms lower on avg but it's still in the 300-460ms range

(Some clarification about system impact: moving the data logger to a worker reduces the worst case impact of consecutive expensive flash operations on the main VM. However, when a flash block erase happens the entire CPU is essentially halted 'cause the flash chip is busy and the CPU can't fetch instructions. Digging further, the esp32-c3 has a way to suspend an erase operation for instruction fetch but it apparently lengthens the erase time and is only enabled for high priority freertos tasks, i.e., it's only usable for occasional high priority interrupts whose code doesn't fit into ram).

Logging to flash is tricky... I wonder whether I should just make a minimal PCB module with an esp32-c3 dedicated to nothing but logging...

[phoddie]

Yes, erase flash is a stop-the-world thing on ESP32 (for all practical purposes). That creates some challenges. OTA is where I usually run into them. That said, 300-500 ms is much longer than I would expect. It shouldn't be doing that many erases and they aren't that slow. (My experience is mostly ESP32 & ESP32-S3. Maybe the C3 is significantly different?)

[tve]

An erase seems to take 40-50ms. I assume that write+sync ends up being 2-3 erases plus 2-3 writes (data + metadata + perhaps root metadata). It's been a while since I've read the littlefs docs... The good news for now is that when done in a worker the impact is ~120ms, which I can tolerate in my current app.
Going forward, I should test spiffs and see how it compares. But ultimately, I'll probably write a logger that writes to raw pre-erased flash blocks. My main use-case is recording stuff while out and about and then uploading automatically over wifi when coming home. The upload can then also do the erase, getting everything ready for the next outing.

[phoddie]

Glad the worker gets you in a good place for now. For simple logging, a file system is unnecessary overhead. Just managing the flash yourself, as you describe, will perform much better.

Another approach, while we're on the topic, would be an additional external flash. It wouldn't be used for execution, so it shouldn't be impacted by the ESP-IDF blocking. It wouldn't be a big deal to reroute littlefs to use that. Using that plus your worker should never block main. That's kind of like your C3 logger idea above, but without the C3.