SpifFS, newlib, logging and fprintf

[ndjurov]

Hi,

Our ESP32 WROVER application is a multitasking one and it is using NewLib. We have 16MG of flash, so we decided to use half of it for a debug log file, using spifFS.
Instead of using vprintf redirection, we use fprintf(), where we change the file pointer to either stdio or to a log file pointer. It mostly works well.
Similar to IDF, we have various log levels and the macro for this is:

Code: Select all

#define EIM_DBG_E(...) {\
                         if (DBG_LVL >= DBG_LVL_E) \
                         { \
                           fprintf(fpCurOutFile, "E: %s: ", TAG); \
                           fprintf(fpCurOutFile, __VA_ARGS__); \
                         } \
                       }

When Verbose mode is defined there is a lot of logging, and it all works OK when flash usage is below about 2.5MB. After that it becomes super slow – a procedure that normally, when flash usage is low, takes about 3 seconds, when log file is above 2.5MB all of a sudden it takes about 30 seconds – 10x longer. If the debug level is then changed to E(rror), the same procedure takes only about 0.3 seconds.
When everything is slow, at some point we even start getting exceptions in newlib, which disappear once debug level is set to E(rror).
It looks like the main reason for this is the usage of fprintf() for logging although I still don’t understand how come it is initially all OK and all of a sudden it becomes very slow. I just wanted to ask if fprintf() is really the reason and if there is there that can be done about this. Is fprinf() implementation safe to be used in the multitasking environment or should we rather go back and use esp_log_set_vprintf().
Thank you.

[ESP_Sprite]

I'm guessing the fact that you're writing to spiffs is the culprit... I can't imagine that that filesystem is intended for high writes like you do, at some point you're just filling up the journal and the filesystem needs to collect garbage.

[ndjurov]

Thanks a lot.
I'll try the same with littleFS and let you know which file system is better for this task.

[ESP_Sprite]

I'm not sure if I'd use a filesystem for that to begin with, to be entirely honest... may be better to start off with the raw flash and write a journalling-type logger that way.