write performance (esp8266)

[pljakobs]

I'll just drop a few notes and findings here for us to work on

so I tried to look at performance a bit:

GDB_IRAM_ATTR void checkPerformance(BasicConfig& db)
{
	Serial <<endl << _F("** Performance **") << endl;
	BasicConfig::Color color(db);
	BasicConfig::Color::Brightness bri(db);
	const int rounds=256;
	int start_time=millis();
	for(int i=0;i<rounds;i++){
		int inner_start_time=millis();
		bri.setRed(i);
		bri.setGreen(i);
		bri.setBlue(i);
		bri.setWw(i);
		bri.setCw(i);
		int inner_intermediate_time=millis();
		color.commit();
		int inner_end_time=millis();
        Serial << _F("Time taken to set values: ") << inner_intermediate_time-inner_start_time << "ms" << endl;
		Serial << _F("Time to write to Storage: ") << inner_end_time-inner_intermediate_time << "ms" << endl;
	}
	int end_time=millis();
	
	start_time=millis();
	for(int i=0;i<rounds;i++){
		int inner_start_time=millis();
		Serial << _F("read:")<<i<<_F("{r:")<<bri.getRed()<<_F(",g:")<<bri.getGreen()<<_F(",b:")<<bri.getBlue()<<_F(",cw:")<<bri.getCw()<<_F(",ww:")<<bri.getWw()<<_F("}")<<endl;
		Serial << _F("Time taken: ")<<millis()-inner_start_time<<endl;
	}
	Serial << _F("Total time: ")<<millis()-start_time<<endl;

	//Serial << bri.getPath() << ".Blue = " << bri.getBlue() << endl;
		
}

trying to assess what to expect from this.
In it's current form (with double buffered writes, so the .new / .old files), a commit takes between 500 and 700ms, that's a lot of time if it has to be a synchronous call.
Removing the double buffering, this comes down to 400-500ms which is still a long time, but better.
This tells me that commits should really only be once all changes to a store have been made.

On the double buffering: as said in the issue earlier, I'm not sure that's something I want to do as I believe it costs more than it brings benefits:

• it circumvents the copy on write functionality, unnecessarily re-writing blocks that may not have been changed (ok, only relevant in stores that have more than one block and all changes are local in one block)
• it is considerably slower
• I'm not sure it solves a problem - but you know LittleFS better than I do - if the write fails, won't the old file stay in tact? (I guess the answer depends on what part of the write fails) - I would assume that the CoW reads the block, writes it as a new block (I would assume not in place) and then adapts the pointers - am I wrong?

[mikee47]

Thank you for this. I've added profiling to the sample. (This and other stuff will end up in the test application I suspect.)

You're right about the cost/benefit of double-writing. It could be useful for debugging at some point, but have removed it for now: can always add it back with an option flag if needed later.

Here's what I get with two runs of the sample, for comparison. Wipe flash before each run for consistency (make flashinit flash).

Normal store saving:

** Performance **
Evaluating setValue / commit ...
Set Value only: count=64, total=13865us, min=213us, max=436us, average=217us
Set Value + commit: count=64, total=21906539us, min=329312us, max=529575us, average=342290us
Evaluating getValue ...
getValue [simple]: count=64, total=16226us, min=242us, max=990us, average=253us
getValue [build string]: count=64, total=26196us, min=406us, max=537us, average=409us
getValue [Print]: count=64, total=20812us, min=321us, max=487us, average=325us

With file double-writing added back in:

** Performance **
Evaluating setValue / commit ...
Set Value only: count=64, total=10832us, min=166us, max=374us, average=169us
Set Value + commit: count=64, total=32055045us, min=372778us, max=940823us, average=500860us
Evaluating getValue ...
getValue [simple]: count=64, total=17667us, min=264us, max=1005us, average=276us
getValue [build string]: count=64, total=27634us, min=429us, max=552us, average=432us
getValue [Print]: count=64, total=22251us, min=344us, max=502us, average=348us

[mikee47]

Just realised why writes are so slow: I'm serialising directly to the file stream. As mentioned under performance, ArduinoJson serialises byte-by-byte so file writes will be affected badly. The mentioned StreamUtils libray is a bit much so have rustled up a set of PrintBuffer classes which I'll get commited to Sming.

Using an intermediate 256-byte buffer we get:

** Performance **
Evaluating setValue / commit ...
Set Value only: count=64, total=10653us, min=163us, max=388us, average=166us
Set Value + commit: count=64, total=4343458us, min=54065us, max=280605us, average=67866us
Evaluating getValue ...
getValue [simple]: count=64, total=10034us, min=144us, max=978us, average=157us
getValue [build string]: count=64, total=20015us, min=310us, max=425us, average=313us
getValue [Print]: count=64, total=14541us, min=223us, max=378us, average=227us

[pljakobs]

as a general thought here: could the commit() call be asynchronous or maybe have an asynchronous version?
The scope of a commit is a store, right? (also with the new object structure you laid out) so in most cases, you wouldn't call it very often and it taking a few 100ms may not be a huge issue - I just feel that it's an eternity in any code path.

[mikee47]

Most of the time will be due to flash erase. The ideal backing store would only need to erase when required, so most commits would only perform a flash write which is much faster. This isn't how LittleFS works though.

So if you need this to work faster then a different filing system is required; I briefly talked about this here https://github.com/mikee47/IFS#configuration-filesystem. The esp-idf NVS component is essentially a flash-based database specifically for lots of small values. I attempted a port to Sming https://github.com/mikee47/Sming-NVS but it's just too complicated and requires too much RAM for the esp8266. My preference would be to start from scratch and write it in C++, but the principle is sound.

[mikee47]

Something else which might be relevant is https://github.com/mikee47/DataLog. It could be used in a ConfigDB backend for fast updates to mitigate data loss. Basically a log-structured filing system.

Could work something like this:

• The storage would have three elements: A FIFO (log) and two storage blocks (A and B)
• Blocks A and B would be versioned such that only one is marked as active, the other is inactive.
• Writes go directly to the log
• At some point, the log requires defragmenting:
  • Erase the inactive block
  • Replay the log into the inactive block, skipping old data
  • Mark the inactive block as active.
• A read operation must start by looking in the log, so performance will depending on fragmentation level.

[mikee47]

As for 'asynchronous' well it's got to do a commit sometime and it's really got to be down to the application when that happens. It could be handled using a db.flush() operation which the application calls when convenient, assuming a flush doesn't happen earlier. A flag to control this behaviour would also be required since in many situations we'd expect commit to only return once the data is safely stored.

[pljakobs]

I think it's not so much about speed but about blocking a thread for almost half a second. But it might just be something I think of as problematic. After all, in my case, this will almost always be in a code path that started with a http request, so it's "slow" by definition. In other situations, like when storing time series data, I don't envision this to be called in ms intervals either as that would surely overwhelm storage quickly. (maybe there should be a note on performance and flash life time in the docs later)

[mikee47]

OK, so basically lazy commit would handle this. That's pretty easy to implement.

[mikee47]

... although to do it properly we'd need to know when the system is idle... so perhaps after a request has completed. But if there's a flurry of requests then it gets deferred... but if there's a flurry of requests then an OOM could reset the system and we'd lose data... which compromise would you like?

[pljakobs]

I'm thinking about it, one of my ideas was we could call commit with a callback function, but that would, at some level, lose the context between the data written and the success/fail from the actual commit if we don't introduce something like commit ids that then the application would have to track, way too complicated I think.
When I go all the way up to my frontend application, I think what I would be interested in is: is my database dirty or clean, so does it have unwritten data or not.
But honestly, this is far downstream from here, I'm perfectly happy to accept a synchronous 400ms call for the functionality right now. Maybe in the future, every store could have a dirty flag and some handling built around it.

• a class managing a store emits some sort of signal / callback when the store is dirty (to the db class?)
• depending on configuration, the db class could enumerate all stores and itself emit a signal to the app showing overal status (I would use that to generate a websocket message to the front end, notifying it of status)
• there might be a global commit function that enumerates all stores and calls the corresponding local commit. When storing / updating config data, I would probably commit the smallest logical scope (so, write all properties that are in one store then commit - as it is today) but in other situations, I might call commit from a timer.
  but I also notice that I might be overthinking this - let's not invest too much time into it now, this is far from core functionality.

[mikee47]

Time series data can you elaborate?

[mikee47]

Just realised the DataLog test application is running slow. In a real application a table header only needs writing at application startup and maybe once a day, depending on how much data gets written. Timings are better:

Log Entry: count=257, total=1720286us, min=6062us, max=148589us, average=6694us

[mikee47]

Best to think of DataLog in standard database terms as a set of flat tables.
For example, your data could be structured as follows:

TABLE Vessels
    INT id
    TEXT name
TABLE Positions
    INT vessel_id
    FLOAT latitude
    FLOAT longitude
TABLE Batteries
    INT id
    INT vessel_id
    TEXT name
TABLE BatteryValues
    INT battery_id
    FLOAT voltage
    FLOAT current
    FLOAT charge

[mikee47]

The Vessels and Battery tables could be stored as regular JSON, with Positions and BatteryValues using DataLog tables.

[pljakobs]

you (and Sming) keep amazing me. Sometimes I wonder why the framework seems to be used so relatively rarely. There are so many cool things. Thanks for the pointer to DataLog. I will have a look.
btw: I will be travelling for the week, so I won't be able to provide feedback or testing for a while.

[mikee47]

Thank for you getting the ball rolling on this - I've been wanting to deal with configuration since forever!