[WIP] Implement a UTXO cache #1168
Conversation
stevenroose
force-pushed
the
utxocache
branch
3 times, most recently
from
724484e
to
92fdab1
Compare
stevenroose
force-pushed
the
utxocache
branch
2 times, most recently
from
3a6f495
to
7298dde
Compare
There was a problem hiding this comment.
@stevenroose great work on this! I took an initial pass at review.
I tried running locally, and indeed there does seem to be an improvement in initial sync. I synced up testnet to about 700k so w/ no errors.
On mainnet, I found that the current PR reproducibly fails and falls out of consensus around block 93k. It seems one of the entries is not properly held in the cache, here are some info logs https://pastebin.com/4cN8XnZQ
Lmk if you want me to crank up the debug level.
blockchain/chain.go
Outdated
| @@ -785,6 +801,12 @@ func (b *BlockChain) disconnectBlock(node *blockNode, block *btcutil.Block, view | |||
| b.sendNotification(NTBlockDisconnected, block) | |||
| b.chainLock.Lock() | |||
|
|
|||
| // Since we just changed the UTXO cache, we make sure it didn't excee its | |||
blockchain/chain.go
Outdated
| @@ -673,6 +691,12 @@ func (b *BlockChain) connectBlock(node *blockNode, block *btcutil.Block, view *U | |||
| b.sendNotification(NTBlockConnected, block) | |||
| b.chainLock.Lock() | |||
|
|
|||
| // Since we just changed the UTXO cache, we make sure it didn't excee its | |||
| // It returns 0 for the nil element. | ||
| func (entry *UtxoEntry) memoryUsage() uint64 { | ||
| if entry == nil { | ||
| return 0 |
There was a problem hiding this comment.
this should return 8, as a nil ptr isn't free :)
There was a problem hiding this comment.
I realize nil's aren't free. At first I thought it wouldn't work easy with adding and removing them, but I think right now it might. Let me make sure. Thanks for starting to look at this, though!
There was a problem hiding this comment.
I think it might make sense to instead have totalMemoryUsage add 8 bytes per entry.
There was a problem hiding this comment.
I went for that approach. Let me know if you think it makes more sense to add the 8 here instead of in the other method.
| // later lookups for the entry know that the entry does not exist in the | ||
| // database. | ||
| s.cachedEntries[outpoint] = nil | ||
| s.totalEntryMemory -= entry.memoryUsage() |
There was a problem hiding this comment.
See previous comment.
blockchain/utxocache.go
Outdated
| func (s *utxoCache) FetchEntryByHash(hash *chainhash.Hash) (*UtxoEntry, error) { | ||
| s.mtx.Lock() | ||
| entry, err := s.getEntryByHash(hash) | ||
| defer s.mtx.Unlock() |
| // This method should be called with the state lock held. | ||
| func (s *utxoCache) addEntry(outpoint wire.OutPoint, entry *UtxoEntry, overwrite bool) error { | ||
| // Don't add provably unspendable outputs. | ||
| if txscript.IsUnspendable(entry.pkScript) { |
blockchain/chainio.go
Outdated
| func dbPutUtxoView(dbTx database.Tx, view *UtxoViewpoint) error { | ||
| // dbPutUtxoEntry uses an existing database transaction to update the utxo entry | ||
| // in the database. | ||
| func dbPutUtxoEntry(dbTx database.Tx, outpoint wire.OutPoint, entry *UtxoEntry) error { |
There was a problem hiding this comment.
consider batching this, so that it can write an entire map[wire.OutPoint]*UtxoEntry, similar comment for deletion.
in profiling I found that the call to retrieve the utxoset bucket was taking as much time as writing the elements, so batching should amortize this
There was a problem hiding this comment.
Hmm, so retrieving the bucket is costly? What about just having the bucket in a variable (using sync.Once to make it safe)?
I could batch it, though.
| return flushBatch(dbTx) | ||
| }) | ||
| if err != nil { | ||
| return err |
There was a problem hiding this comment.
roll back to latest stable state?
There was a problem hiding this comment.
That error means a disk error of some sort. Likely that all further IO operations would also error. Besides, there is logic to recover on startup when shut down in the middle of a flush.
blockchain/utxocache.go
Outdated
| } | ||
|
|
||
| // newUtxoState initiates a new utxo state instance. | ||
| func newUtxoState(db database.DB, maxTotalMemoryUsage uint64) *utxoCache { |
There was a problem hiding this comment.
True that. Had a totally different implementation at first that was called utxoState :)
| func (entry *UtxoEntry) Spend() { | ||
| // Nothing to do if the output is already spent. | ||
| if entry.IsSpent() { | ||
| return |
There was a problem hiding this comment.
This seems like it could be dangerous, as we would silently "accept" a double spend. Are there cases where we can safely call Spend() more than once?
There was a problem hiding this comment.
Yeah that's only called in the methods that have overwrite=true, which are used to roll forward changes when the state was left in the middle of a flush. They might be on the disk in a spent state, and while "force roll forward" blocks aka applying them with overwrite=true, they could be marked spent again.
I do recognize that the method might be better renamed to MarkSpent of some kind, so that it's more clear it doesn't actually "spend" the entry. That would break the existing public interface, though.
|
I followed up last night and tried to get debug logs for this event, but it seems the debug logs slowed it down enough to get past the 93k block range. This seems like it would point to some kind of concurrency issue. I tried the cache with various sizes and found that 100MB worked pretty well OMM. I was getting 100-200 blocks/10s well into 2014. When I had the cache size cranked up to 8GB, 85% of the runtime was spent garbage collecting. I think this was being caused by the map itself as it continually grows, as well as the serialization of output scripts in Here are some profiles with the 100MB cache w/ modest internet connection: |
|
As a feature request, it would also be great if the log msgs printed out the current size of utxocache :) |
|
I bumped in the If you're interested in following up on this, I can give you commit access to my repo so you can push to the branch. I'll push changes regarding your remarks right now though. |
|
I noticed that I was tracking down a specific bug. You can see that one of the unit tests fails. I was baffled by what was happening there: the result of that test are not deterministic while they definitely should be. It should end with 5 elements in the cache and ends with either 3 or 4. These are the extra prints that I added to get a better view on what happens: |
Done. |
|
@stevenroose are you still working on this? This is a key feature and I would love to assist in getting it completed and tested. |
|
I kinda quite btcd development for now. So no, not working on it anymore, sadly. It's mostly finished, but there is a bug I didn't find. Somehow I introduced an inconsistency. I think the culprit is the It's been some time, I'd say take a look and compare with Core's |
|
@stevenroose thank you for responding. We are going to work on this for bchd. Do you mind if I ping you with questions if we have issues? Once it is complete I will happily post a completed PR for btcd as well. I want everyone to benefit from this. =) |
Any chance you also tested this with a 2GB cache size? Would like to know where the sweet spot is in terms of performance. |
|
Yeah since something didn't work with keeping things consistent, I mostly ran with a small cache to trigger the write-through behavior etc. You can always reach out to me on Jabber: steven@konuro.net. I'm on IRC as well (stevenroose@Freenode (but I don't see private messages well, better ping me in #btcd) or stevenroose@Gitter bridge (same with private messages)). |
| // avoid redoing the work when interrupted. | ||
| rollforwardBatch := func(dbTx database.Tx, node *blockNode) (*blockNode, error) { | ||
| nbBatchBlocks := 0 | ||
| for ; node.height <= tip.height; node = node.parent { |
There was a problem hiding this comment.
you are rolling back nodes here rather than rolling them forward.
Should be something more like:
for e := attachNodes.Front(); e != nil; e = e.Next() {
node = e.Value.(*blockNode)
attachNodes.Remove(e)
| if !overwrite { | ||
| // Prevent overwriting not-fully-spent entries. Note that this is not | ||
| // a consensus check. | ||
| if cachedEntry != nil && !cachedEntry.IsSpent() { |
There was a problem hiding this comment.
The reason this code is failing at block 94804 is because there are two coinbases in the chain which share the same txid with previous coinbases and this line errors when adding the duplicate coinbase. There error bubbles up to the commit() function but you don't handle the error there.
Ultimately the commit terminates and a later transaction fails to validate when the utxos that failed to be committed don't exist.
There was a problem hiding this comment.
Oh god damnit Bitcoin historical bugs :D Yeah that makes sense. Any idea how Core handles this? Does it just have two if-clauses here? :/
| // the best chain. | ||
| var statusNode *blockNode | ||
| var statusNodeNext *blockNode // the first one higher than the statusNode | ||
| for node := tip; node.height > 0; node = node.parent { |
There was a problem hiding this comment.
node.height > 0 wont enter this loop if the tip is the genesis block.
There was a problem hiding this comment.
Suggesting it should be >= 0? That doesn't make sense, though, will need another check.
There was a problem hiding this comment.
This has been fixed. I was debugging yesterday and you are 100% correct.
|
We've been working on this in the Bitcoin Cash version. I think we've got most of the bugs worked out and it seems to be working good if you guys want to take a look gcash/bchd#21 Only real changes are related to the canonical transaction ordering. |
|
Do you guys plan to backport the fixes? A PR to my fork would be very much appreciated so I can include your fixes in this PR. |
|
We can probably port the fixes here. One other issue of note is we believe because the database has its own cache the One possible fix is to always attempt to rollback the chain when inconsistent regardless of whether the shutdown happened while flushing or not. That seems to be working pretty reliably on our end. |
|
Picked back up here #1373 |
|
@jcvernaleo (as per #1530)
Can probably close in favor of #1373 |
|
Yeah #1373 is the more updated version, so this one can be closed. There's still a lingering BIP 30 related bug, and a re-org rewind bug. Aside from those, with that PR and some of the other optimization PRs, we've been able to get sync down to < 24 hours which is a massive win. |
This PR requires #1045. Ignore the commit(s) from #1045 when reviewing this PR.
This PR adds an in-memory UTXO cache.
UtxoViewpointis trimmed of the block (dis)connection methods, as they now can be applied also to the cache (for reverting and forwarding blocks).The database keeps track of the consistency of the UTXO state with the rest of the chainstate (block index and blocks). When the node starts with the UTXO state lagging behind, it replays blocks to catch up. Since flushing the cache cannot be done in a single LevelDB transaction, it is done in batches. Before a flush starts, the db is updated to indicate a flush is ongoing. When the node shuts down in the middle of a flush and restarts, it does not know where it left of with flushing. Therefore, it first rolls back changes that had already been applied and then replays all blocks to catch up with the chain state.
Yet to be done:
UtxoViewpointandutxoCachein acachedUtxoView.