Feature Reduce the amount of I/O wear and tear from writing preferences

Irrat

Member
So while looking at this PR I was a bit surprised to find out that my 150kb prefs file is costing me about 5.4gb of writes a day from my 33k pref changes. We currently write the whole file out every time we change one value. To me that feels unacceptable, I want my drives to last longer than this.

The first thing that comes to mind is changing the settings database format entirely. That's not going to convince anyone and introduces too much complexity, so that's off the list. We're sticking with the key=value flat file format.

So, to fix the I/O problem without breaking backward compatibility, we're given a choice: write less often, or write smaller.

I think there's three options.

Periodic Saves (Writing Less Often)

Instead of writing to the disk immediately on every single change, we just update the properties in memory and write the file periodically.

For example, we only flush the changes to prefs.txt every 5 seconds, or wait until a script finishes running.

The Upside: This is simple. It requires zero changes to the file format and users interacting with prefs.txt won't notice any difference 99% of the time. It collapses rapid writes (like combat) into a single write.
The downside: Unexpected power loss means you lose whatever prefs changed in that 5 second window. Though, realistically, you'd probably be fine.


Append Delta Log (Writing Smaller)

When a pref changes, we still update it in-memory, but instead of rewriting the entire 80kb+ prefs.txt file, we just append key=value\n to a small irrat_prefs_delta.log file.

When the delta log reaches a certain configurable size (e.g 500kb), or when the user logs in / out / exits / scheduled, we flush the current in-memory prefs into prefs.txt and clear the log. When logging in, we load prefs.txt and apply the log if it exists, over it.

The upside: It drops our daily I/O from prefs alone, from gigabytes down to megabytes, but guarantees no data is lost on a crash.
The downside: It might confuse people's existing setups if they are manually editing prefs.txt directly while KoLmafia is closed, or their special backup / copying setups. Because of that, we should probably make this opt-in.
Considerations: There may be some tooling for this, some library or database structure that's not plain text or methodology, I'm not sure. The main idea is that we're appending, it's power loss resistent, and when we load it, we work backwards to apply the last changes and skip any changes that were overwritten later.

Code:
lastRefreshed=10
lastRefreshed=20
lastRefreshed=30
So lastRefreshed=30 is stored in memory, the log is cleared.


A callback to temporary prefs

Whichever approach we take, it's worth bringing up a callback to my old temporary prefs proposal. A huge chunk of these I/O writes are for prefs that simply aren't important across sessions. things like _concoctionDatabaseRefreshes, or _lastCombatActions. If we allow some prefs to persist only in memory and skip writing them to disk entirely, we could lower the amount of writes. Inter-script communication can be solved with temporary prefs, a major reason I've never explored that in my scripts is because every change is written to file, both session and prefs.

Closing thoughts

We could probably expose more tooling that helps minimize the amount of IO, such as appending to a file.
 
Last edited:
Brief comments.

Periodic savings: opposed; we use the file to write daily flags we can't necessarily recover from the game easily (e.g. how many habitat fights you have left), and this makes it worse for people.

Journal: support, this looks great tbh, and I think it makes it even easier to update a pref (whose name you know) because you can just throw it at the end of the journal file. As an advantage, this means you can update a pref by editing a file even while Mafia is running, which I remember people wanting (though I don't remember why, and you can just use 'set').
Cons: need to worry about backups for the journal file too.
Design:
* I think we don't need to have a "write when it reaches X file size", we can just do open / close / force-logout-because-rollover. At all other points the preferences are in memory anyway (right?).
* The dumbass implementation where you just update the in-memory prefs with each line in order seems less complex and might be more performant than the "read backwards, store updated prefs, skip already-updated prefs". Or it might not.

Memoryonly prefs: reading the temporary prefs proposal I had concerns about complexity, but I see no issue in tagging a known pref "memoryonly" (in the same style as our existing "ld", "rof", "roa" tags) and having those prefs not be written to disk. Scripts can't create tagged prefs, though.
 
Last edited:
Yeah I'm not really sure about periodic saving either. Its really not great in comparison.

I'm not sure if you meant kolmafia backups or private backups. I don't think there's much reason to be doing kolmafia backups as a log file is never being rewritten, only appended. We don't have to modify the data already written. We only delete after it's successfully processed.

If you meant player backups, yeah, opt in would be better in that perspective. Maybe with a nagging reminder that needs them to confirm they want the old system, nagging can be ignored if you don't notice it.
 
Technically there's no need for the journal to be separate from the pref file, right? If the journaling were done within the pref file, any existing schemes for backing up the prefs should Just Work(TM).
 
So while looking at this PR I was a bit surprised to find out that my 150kb prefs file is costing me about 5.4gb of writes a day from my 33k pref changes.
Important question: where is this measured?

Because your filesystem should probably already be doing a version of what you describe as periodic saves (tells the application that everything has been saved to the disk, but saves only to RAM ... and a few seconds later stores to disk the result of all of the "writes" that happened since last real disk-store .. or something like that). And a good SSD is probably also doing a version of that on its own (that's why some of them have up to several gigabytes of ram).
Did you look into the drive's SMART data?
5.4GB looks like straight up multiplying number of full file writes by full file size. I doubt that this is accurate measure of the actual wear-and-tear done on the drive.

--

Additional implementation note: any journaling has to be done only for preferences whose values actually changed, otherwise you might be *forcing* all those 5.4GB to be actually written sequentially (into the log) - that would completely defeat the whole purpose, and likely make everything much worse than it really is.
 
People are throwing numbers around that do not match my experience. If the numbers are being used to justify a change (or not) it would be helpful to know how those numbers are being generated so that someone else can try and generate them.

If we are going to micromanage disk I/O we should consider saveSettingsOnSet and whether the amount of data lost when it is false is acceptable.

My solution to corrupted files is an uninterruptible power supply and I never run KolMafia unless I am actually sitting at the computer. So corruption due to power glitches is not something I see. But someone running multiple, unattended instances that restart after rollover is going to have different concerns.

A 150KB preferences file is twice is big as any of my preferences files. Perhaps a script is using preferences and rewriting it to use data files might change overall conditions and performance for the better?

We are only backing up preferences files because they were being corrupted. We have eliminated most of those sources of corruptions so maybe we stop backing them up and trying to restore from them? Power failure corruption could be a a user problem to deal with. At some level disk IO and backup management need to have operating system specific solutions.

If this is a problem that KoLmafia needs to solve then I'd lean towards some version of journaling,
 
Important question: where is this measured?

Because your filesystem should probably already be doing a version of what you describe as periodic saves (tells the application that everything has been saved to the disk, but saves only to RAM ... and a few seconds later stores to disk the result of all of the "writes" that happened since last real disk-store .. or something like that). And a good SSD is probably also doing a version of that on its own (that's why some of them have up to several gigabytes of ram).
Did you look into the drive's SMART data?
5.4GB looks like straight up multiplying number of full file writes by full file size. I doubt that this is accurate measure of the actual wear-and-tear done on the drive.
People are throwing numbers around that do not match my experience. If the numbers are being used to justify a change (or not) it would be helpful to know how those numbers are being generated so that someone else can try and generate them.
I believe I had tested against linux stats, not smartctl. I'll check those numbers later today after my day has run, can compare the smartctl then. I had forgotten to compare it originally, and the final numbers upset me enough that I ended up deleting the script I used to test. I hated the results.

Though I was wrong, was 4.7gb and not 5.4gb. 5.4gb was the result after implementing the stream.getFD().sync() to compare it against.

Worth noting that prefs are flatfile, not a database. It hits IO differently.

My script restarts kolmafia daily, and I've already run todays stuff.
My /proc/<pid>/io of kolmafia from the last day is;

Code:
:~$ ps -p 4172449 -o etime=
   18:27:08
That's the uptime.

Code:
:~$ cat /proc/4172449/io
rchar: 2831743465
wchar: 9339385937
syscr: 418160
syscw: 24903265
read_bytes: 544768
write_bytes: 9439498240
cancelled_write_bytes: 12288
Code:
rchar: 2.7GiB
wchar: 8.7GiB
syscr: 418167
syscw: 24903271
read_bytes: 532KiB
write_bytes: 8.8GiB
cancelled_write_bytes: 12KiB

I know the above is not a 100% representative of actual disk usage, I just don't plan to put more wear and tear on my disk for no reason, so this can wait for today's run.
I didn't use the above stats obviously, in my numbers.
And my settings file is inflated because I didn't cleanup old settings.

We are only backing up preferences files because they were being corrupted. We have eliminated most of those sources of corruptions so maybe we stop backing them up and trying to restore from them? Power failure corruption could be a a user problem to deal with. At some level disk IO and backup management need to have operating system specific solutions.

If this is a problem that KoLmafia needs to solve then I'd lean towards some version of journaling,
This post isn't about corruption. It's about unneeded IO. A periodic save which you were likely responding to, yes it wasn't that good a suggestion.
 
Last edited:
Yeah, I agree with irrat that backing up the journal file isn't necessary, because writes are append-only so we should see the same corruption we see with the preference file, which is completely rewritten.

I would prefer to keep the journal file separate to the preferences file for comprehensibility.
 
Important question: where is this measured?

Because your filesystem should probably already be doing a version of what you describe as periodic saves (tells the application that everything has been saved to the disk, but saves only to RAM ... and a few seconds later stores to disk the result of all of the "writes" that happened since last real disk-store .. or something like that). And a good SSD is probably also doing a version of that on its own (that's why some of them have up to several gigabytes of ram).
Did you look into the drive's SMART data?
5.4GB looks like straight up multiplying number of full file writes by full file size. I doubt that this is accurate measure of the actual wear-and-tear done on the drive.
People are throwing numbers around that do not match my experience. If the numbers are being used to justify a change (or not) it would be helpful to know how those numbers are being generated so that someone else can try and generate them.
Monitoring with csysdig, or sudo csysdig -d 10000 and changing view + sort by, there's one file that always topped the results with a refresh time of 10 seconds. irrat_prefs.txt
About 3-4mb on average per 10s based over a ten minute sample. Sometimes it dropped below 1mb, and sometimes it went up to 5mb.

Probably be higher on your machines if you measure it, as my internet is slower.

My day is a scripted "autoscend, break prism, garbo, ascend, autoscend" (looping hardcore)
Autoscend sets a lot of properties during its run, most of them can doubtlessly be reduced.

The smartctl stats are

before:
Code:
246 Total_LBAs_Written      0x0032   100   100   050    Old_age   Always       -       166202600715
247 Host_Program_Page_Count 0x0032   100   100   050    Old_age   Always       -       5193831272
248 FTL_Program_Page_Count  0x0032   100   100   050    Old_age   Always       -       6076994424

Device Statistics (GP Log 0x04)
Page  Offset Size        Value Flags Description
0x01  =====  =               =  ===  == General Statistics (rev 1) ==
0x01  0x008  4              99  ---  Lifetime Power-On Resets
0x01  0x010  4           57770  ---  Power-on Hours
0x01  0x018  6      2993843467  ---  Logical Sectors Written
0x01  0x020  6      2530664651  ---  Number of Write Commands
0x01  0x028  6       854668075  ---  Logical Sectors Read
0x01  0x030  6      1963700548  ---  Number of Read Commands
0x07  =====  =               =  ===  == Solid State Device Statistics (rev 1) ==
0x07  0x008  1             254  ---  Percentage Used Endurance Indicator
                                |||_ C monitored condition met
                                ||__ D supports DSN
                                |___ N normalized value

after:
Code:
246 Total_LBAs_Written      0x0032   100   100   050    Old_age   Always       -       166223587266
247 Host_Program_Page_Count 0x0032   100   100   050    Old_age   Always       -       5194487102
248 FTL_Program_Page_Count  0x0032   100   100   050    Old_age   Always       -       6077399928
Device Statistics (GP Log 0x04)
Page  Offset Size        Value Flags Description
0x01  =====  =               =  ===  == General Statistics (rev 1) ==
0x01  0x008  4              99  ---  Lifetime Power-On Resets
0x01  0x010  4           57780  ---  Power-on Hours
0x01  0x018  6      3014830018  ---  Logical Sectors Written
0x01  0x020  6      2530890427  ---  Number of Write Commands
0x01  0x028  6       907914275  ---  Logical Sectors Read
0x01  0x030  6      1965363970  ---  Number of Read Commands
0x07  =====  =               =  ===  == Solid State Device Statistics (rev 1) ==
0x07  0x008  1             254  ---  Percentage Used Endurance Indicator
                                |||_ C monitored condition met
                                ||__ D supports DSN
                                |___ N normalized value

which is a result of

Code:
246 Total_LBAs_Written      0x0032   100   100   050    Old_age   Always       -       20986551
247 Host_Program_Page_Count 0x0032   100   100   050    Old_age   Always       -       655830
248 FTL_Program_Page_Count  0x0032   100   100   050    Old_age   Always       -       405504

Device Statistics (GP Log 0x04)
Page  Offset Size        Value Flags Description
0x01  =====  =               =  ===  == General Statistics (rev 1) ==
0x01  0x008  4              99  ---  Lifetime Power-On Resets
0x01  0x010  4           10  ---  Power-on Hours
0x01  0x018  6      20986551  ---  Logical Sectors Written
0x01  0x020  6      225776  ---  Number of Write Commands
0x01  0x028  6       53246200  ---  Logical Sectors Read
0x01  0x030  6      1663422  ---  Number of Read Commands
0x07  =====  =               =  ===  == Solid State Device Statistics (rev 1) ==
0x07  0x008  1             254  ---  Percentage Used Endurance Indicator
                                |||_ C monitored condition met
                                ||__ D supports DSN
                                |___ N normalized value

So 10 hour period.

Total_LBAs_Written = 10gb or so.

Code:
:~$ cat /proc/335918/io
rchar: 2846818015
wchar: 8347308609
syscr: 407857
syscw: 25216969
read_bytes: 507904
write_bytes: 8405557248
cancelled_write_bytes: 8192

Which is about 8.4gb.

You almost certainly will be getting less writes than me, because I'm running a larger loop than most users. Autoscend in particular does a lot of property usage.
This day had 32197 properties set.
This should be reproducible.
 
Last edited:
Back
Top