Fixpoint

To whet the appetite, have a look with me at this plot (click through for the underlying data):

What is this, some exercise in audio signal processing featuring the tail end of a glitchy sawtooth wave? The pulse monitor of a patient who didn't make it? Why no; it's the peculiar memory usage pattern of a particular Bitcoin node, both by the broadest measure of total virtual address space mappings ("VIRT") and the narrower resident set size ("RSS"), sampled roughly every 10 seconds over a 14-hour interval.⁽ⁱ⁾ Let's zoom it in to just the first 500 samples or 83 minutes:

So what's going on here? The patient had reported to me with the usual symptom of being stuck, well behind the active blockchain and unable to make progress accepting any new blocks, and thus reduced to a museum piece, frozen in time and unable to participate meaningfully in future activity. The debug log showed it was looping on a failed reorganize attempt. Finding the initial cause was easy: a consistent I/O error when reading a particular block from the filesystem. This was reproducible by a simple cat >/dev/null of the relevant .blk file, indicating an uncorrectable error reported by the storage medium, a Samsung SSD. The recommendation was thus to restore from the last backup. That wasn't even too time-consuming since the affected file happened to be a long completed block collection file,⁽ⁱⁱ⁾ then the node passed a full readback test using -checkblocks=0 and proceeded with its reorganization.

But then things got interesting. The reorganization ran, and ran... and ran... and failed, with an

************************
EXCEPTION: 11DbException
Db::get: Out of memory
bitcoin in ProcessMessages()

after which it would go right back and try again, triggered by receipt of a new catchup block from the network. It didn't look like the machine was that low on memory, but I had the parts on hand to upgrade the Thinkpad from 4 to 8 GB, so I lent them to the cause; still no dice. So we started collecting the memory log, on the idea that we simply weren't checking at the right time. The steady increase, particularly in RSS, through the course of a cycle certainly pointed to some runaway memory usage, yet at no point did it come anywhere close to the available capacity of the machine. Another question was why each cycle took so long; the debug log offered no clues whatsoever to the shape or progress of the lengthy reorg process. So adding some new log messages was an obvious first step.

Unfortunately, on restarting with the new code, the node received no new relevant blocks from the network by which to re-trigger the reorganize, only unconnectable "bastard" blocks. Basically, due to the behavior of the broken block download process, the peer node will only announce some limited number of blocks ahead of the requesting node's current tip; if it "already has" them - notwithstanding that it failed to connect them for its own transient reasons - it concludes that there's nothing to do. This is also why the sawtooth pattern stops in the memory plot; it ran out of "free preview" blocks to look at. So we had to bypass the network protocol by looking up the height of the block hash that triggered the last reorg attempt, dumping the subsequent block from a healthier node, and feeding it into the afflicted node using eatblock. At least this made for a "cleaner" run, with a freshly started bitcoind process going through a single reorg attempt with no network connections:

The now much more helpful debug log revealed the shape of the fork causing the reorg: not actually a fork at all, with no blocks to disconnect and 501 to connect. It just happens that in this situation where the node previously stored but failed to fully connect a block (perhaps due to external error or interruption), the fact that the next block it sees doesn't directly connect to its tip means it can't do a simple ConnectBlock, so it dispatches to the more general Reorganize routine. This handles all the pending blocks in one shot - specifically, in one database transaction as well as one critical section (see also ye olde map). This certainly explained the long cycle duration. Further, there was an obvious memory drain in the form of temporary transaction lists - built up by Reorganize so as to later update the in-memory transaction pool if the reorg proves successful i.e. the proposed longer chain is valid - which could account for at least part of the near-linear ramps observed in RSS.

That all may suggest some possible improvements; but so far none of it is fatal and we seem no closer to finding the cause of the failure. Further, the situation made for a rare and valuable test of node resilience under deep blockchain fork conditions. Even if this particular case could be optimized to connect blocks incrementally and avoid the need to reorganize, the more general and quite important case cannot, as things currently stand. A node that fails to follow the longest valid proof-of-work chain, howsoever inconvenient or costly that may be, is not an honest Bitcoin node and does not implement the protocol, as widely understood and as required to maintain consistency, distributed consensus, a single fungible currency without trusted third parties and all that. In short, given enough time, Reorganize must either succeed or else prove the proposed chain invalid, without requiring significantly more working memory than is normally available to the node, no matter how many blocks there are to disconnect or reconnect.

The enhanced log output also revealed that the crash came after connecting 210 blocks of the 501 total, ruling out at least the fairly opaque step of the Berkeley DB transaction commit as the culprit, since the code never got that far.

Could it be that we still weren't looking "fast enough", that there was some single ginormous allocation request or else a rapid succession of large ones just prior to raising the exception? Not knowing where exactly the exception was coming from was one obstacle, and adding an exception handler at a higher level wouldn't necessarily help, because the stack would already unwind with C++ destructors freeing everything up by the time control entered the handler. So I found the magic gdb syntax for breaking at the exact point an exception is raised/thrown. Documentation was sparse, and it was supposed to allow filtering for a specific type of exception but that didn't work. Fortunately there weren't any exceptions arising during normal operation of the code to get in the way, so it ran until hitting the out of memory (OOM) and yielded up a gdb prompt.

I poked around, gathering information about execution state at various levels, and saved the relevant log messages for good measure. The memory data proved that there was not in fact any such narrow spike just before death:

This left no choice but to dig into what I'd been rather hoping to avoid: Berkeley DB or the related code, following the clue that the error consistently originated there. This revealed the true problem surprisingly quickly. It had been hiding in plain sight, in BDB's own separate ~/.bitcoin/db.log : "Lock table is out of available object entries". That's a straight flashback to nine years ago, to what was arguably the single most impactful change to come out of "The Real Bitcoin" project: asciilifeform_maxint_locks_corrected.vpatch. So it's time to settle in for a little history lesson.

Some years prior, a cast of Github-based muppets (calling themselves "The Bitcoin Developers", or "The Bitcoin Core Developers" for long, but better known in civilized parts as the Power Rangers), as part of a steady stream of reckless changes in their fork of Satoshi's code, had swapped out databases, replacing (partially!) the relatively mature BDB with some fashion-of-the-day Google thing. They then pushed miners to raise their "soft" block size limit (i.e. what size of blocks to produce, as opposed to the "hard" limit of what size is accepted as valid from others), because The People needed it, you know. These new, bigger blocks had disastrous unforeseen consequences, causing nodes still running the BDB implementation to exhaust self-imposed limits on lock resources and fail to accept certain blocks, reportedly even in a non-deterministic way i.e. depending on the exact history of each node's database. This resulted in relatively long-lived forks in the network, and fed into the propaganda that you "had to upgrade" - to the version pushed by the very ones who broke it in the first place through their aggressive changes to things they didn't understand.⁽ⁱⁱⁱ⁾

On the contrary, you could simply adjust the BDB configuration and set larger limits. But how large was "larger" ? Too high and it would suck up so much memory that it couldn't run at all; too low and it might appear to work today but fail again tomorrow. So the problem kept recurring, for TRB nodes along with any others running old code, up until Mircea Popescu condescended to share the magic numbers that he'd been using, reportedly based on the theoretical maximums of a 1MB block. The TRB project, carrying the baton of maintaining the unfucked codebase from before the database switch, took the numbers at face value, codified them and declared victory. And indeed, no single block has been seen to run afoul of the limits ever since, despite ample attempted spamming attacks against the network.

But now we see the gap. What is enough for a single block is not enough for a series of blocks processed in a single database transaction; as the docs note,

transactions accumulate locks over the transaction lifetime, and the lock objects required by a single transaction is the total lock objects required by all of the database operations in the transaction.

Since there is no limit on the number of blocks in a reorg and thus the number of database pages touched in the transaction, there can be no sufficient values for the limits on locks and lock objects.

At this point the question practically screams out loud: what possible need is there to be locking millions of distinct items, in an application which uses only a handful of threads, doing only a handful of distinct tasks, of which the heaviest are infrequent, and nearly everything is blocked out in a critical section anyway? Basically, BDB is trying to provide fine-grained locking, so that you know, there COULD be a high degree of concurrency, with multiple readers and even writers as long as they're touching different parts of the database. Alternatively, it provides the simpler, multiple reader/single writer model through the Concurrent Data Store "product"; but for whatever stupid reasons, this cannot be combined with the required transaction subsystem.

Practically speaking, this left us with two options. Either we stop using BDB's locking system altogether, or else we break the reorganize algorithm down to do a limited amount of work per transaction. There's a lot to be said for the second route: massive long-lived transactions are the enemy of concurrency and response time in a database; further, at present the process can't be interrupted during a lengthy reorg or else it "loses its place" and has to restart from the beginning. On a closer look though it gets thorny. If the reorg is split up, then external queries can actually see the blockchain rewinding into the past, "getting worse before it gets better", with consequences unclear. What's more, in the current implementation it's not possible to know up front whether the proposed chain is even valid and thus whether the reorg will succeed. If it fails, then all the externally-visible noise and reversed transactions were for naught and we have to explicitly retrace our steps, hopping back to where we started one block at a time. I had some thoughts on how one could resolve at least the uncertainty:

jfw: this could perhaps be assured by fully checking blocks prior to admitting them into the database, i.e. no more hopeful blocks
jfw: which might require changes to how transactions are indexed, at minimum indexing also the transactions from accepted but inactive blocks off the main chain, so that downstream blocks have what to reference
jfw: and "where a transaction is spent" would no longer be an atom but a list of potentially many downstream blocks^(iv)
jfw: further there's the spamming issue where any number of transactions & blocks could be spewed downstream of the early chain where difficulty is low, and the node now has to index all those transactions rather than just storing the block data as it does already
jfw: this together with the unreliable block download does seem to point to headers-first sync, i.e. show me the full proof of work chain that puts your blocks in the lead before I'm interested in what they contain

jfw: with the contemplated change to transaction indexing, the reorg itself might get a lot faster, if all that's needed is updating the block index flags for which blocks are active
jfw: and mempool updates

Even if all the details can be dealt with acceptably, it's clear that this would be quite an involved and invasive change, requiring perhaps a rewrite of the full transaction database (confusingly stored in blkindex.dat) on first run to update the structure, breaking compatibility. Moreover, the codebase is still such a long way from clean and comprehensible that the costs of validating such a change are likely to be significant.

On the other hand, if BDB's locks can be disabled and suitably replaced without giving up transaction support, it would solve the immediate problem without making things any worse. It might further entrench the lack of concurrency in the threading code, but then, nothing stops us from turning them back on later if sufficient need arises to justify a more refined solution.

As it turns out, they can indeed be so disabled. The catch is that we then become responsible for ensuring that no thread can access the database while another is working with it. What exactly "working with it" means is not fully clear, so we can take a broad approach: any code that constructs a CDB object, or one its derived classes CTxDB, CAddrDB, or CWalletDB, must be mutually excluded from other threads doing the same for the full scope of that object. On exit from such scope the ~CDB destructor runs, calling CDB::Close and aborting any unfinished transaction. This suggests an automated solution, acquiring a global lock in the constructor and releasing it in the destructor. Unfortunately this would not be a "leaf" lock, that is, the calling code might attempt to acquire other locks while it is held, raising the possibility of deadlock (suppose thread A holds cs_main then attempts to construct a database handle, while thread B has a database handle then attempts to acquire cs_main; neither can progress because each waits for the other). So it doesn't spare us the need to look at how the locks are actually used. Further, we also need to consider direct calls to dbenv, the global database environment handle.

The good news, such as it is, is that mutex locks (in the form of "critical sections") are used so coarsely throughout the bitcoind code that we're most of the way there already. First, observe that all calls to ProcessMessage, ProcessBlock, SendMessages, and RPC commands are fully guarded by cs_main. Then, anything done in the body of AppInit2 (prior to its final CreateThread calls) is running at startup in the main thread before there are any other threads. Intuitively, this covers almost everything because what else is there to cause the daemon to wake up and do anything at all? But intuition alone and "almosts" aren't going to cut it here.

Stay tuned for the deep dive!

1. I really just meant "let it run for at least one or two full cycles", not "let it run overnight" but I guess I didn't make that fully clear or else attention turned to other things, and so we get the whole picture. [^]
2. The blk####.dat files don't change, only grow by appending until full; blkindex.dat is another story entirely. [^]
3. I must confess I was among those hoodwinked at the time, not having realized that the project had been hijacked and figuring it was simply a bug in the old code. [^]
4. In this expanded index structure, to "pre-check" a candidate block off the main chain, it's more complex to check whether a previous output is spent: you have to check each block in its "spent-by" list to see if that block is on the branch being extended. The naive way to do that is to walk the block index back from the branch tip in question; but since this is required for potentially multiple referenced blocks for each input of each transaction in the candidate block, such a linear algorithm on the full blockchain height is prohibitive. However, it can be optimized by precomputation: walk that block index branch once up front for the block, setting a temporary flag on each visited node, similar to the current "is on the active chain" status. [^]