fix: events: sqlite db improvements

[rvagg]

• fix two unclosed multi-row queries
• tune options to limit wal growth

Ref: #12089

--

This is a draft for now while I test it out. I've manually truncated my current, massive wal file (sqlite3 /path/to/sqlite/events.db followed by PRAGMA wal_checkpoint(TRUNCATE);) so I'm starting from zero again and will watch its behaviour with this and report back.

[github-actions]

All checks have passed

[rvagg]

I think I've cracked it!

This line, right at the beginning of initialising the database checks whether we need to make the database or not:

lotus/chain/events/filter/index.go

Line 440 in 63b9577

q, err := db.QueryContext(ctx, "SELECT name FROM sqlite_master WHERE type='table' AND name='_meta';")

In normal operation, we end up at q.Next() which gives us a row that just contains "_meta", but because it's an *sql.Rows, which holds on to a read operation until closed, and we never call q.Next() again (which would return false and close it) or just q.Close(), we hold on to a read operation.

I believe this is the read operation that's left open for the entirety of the lifetime of the database so the checkpoint never gets to run and the WAL just grows and grows. This could also explain performance problems too if we have a mammoth WAL that we need to process when doing queries too.

The changes in here force a WAL truncation on checkpoint, and I've lowered the checkpoints to 256 pages. Our page size is unfortunately set quite large for this db (set on db create), so 256 gets us to ~8MiB WAL size before checkpoint and then truncate. The default is 1000, which would land us closer to 32MiB.

Watching the chain as I write this, I'm seeing it truncate every 3-4 epochs where it hits around the 8MiB mark. So it's ~2MiB of events per epoch, although it's extremely variable. There'll probably be epochs where we easily blow past the 8MiB mark.

So, we could increase this number, but compacting the write-ahead log every epoch or 4 doesn't seem like such a bad thing.

[rvagg]

Here's the WAL for my mainnet node using this patch, every 30 seconds, compacting every 2-4 epochs.

[Stebalien]

❤️

[snissn]

@rvagg does this ticket close #12081 ?

[rvagg]

Continuing to monitor my wal file and the behaviour is not what I expected: mostly it seems to hover around what I showed above, but it has long stretches where it gets stuck at a particular, overly large, size. A few hours at 42MiB; the next day a stretch of ~5h at 44MiB, down again for 2 epochs then up to 37MiB for another ~6h, up from there to 41MiB for a couple of hours, then back down again; later the same day it grew up to 140MiB for a few hours but now it's running normal again.

The most important thing is that it eventually shrinks. However the behaviour of growing and getting stuck at a size well above the set maximum is strange because I can't reconcile it with what the docs suggest and what I know of the access patterns. Like we have long-running read locks that eventually free up after hours; but that doesn't square with how we run this thing. Perhaps this is just internal sqlite behaviour that's not clearly documented.