The Tar Pit

Long story short, for those who are still tuned in: following my recent adventures getting a TRB node up and running on Debian, I proceeded to get it to sync with the rest of the network over some period of time. Alas, although syncing with -connect and -nolisten didn't pose any problems, my new node remained consistently behind and eventually got entirely stuck at some height until the next restart. In other words, it exhibited a behaviour that people often refer to as a "wedge"¹, wherein for some reason the node stops asking its peers for new blocks. In this article I'll take a brief look at the problem² and propose a stopgap solution.

For starters, we recall that Bitcoin is a peer-to-peer protocol, from which follows that the structure of the network is flat: as opposed to the hierarchical "client-server" paradigm, where "servers" listen and "clients" initiate new connections, here each of the parties may initiate connections to each other at any moment. Although this is in principle not necessary³ for the parties involved, it is necessary for the overall health of the network, so that the distributed system converges to a relatively stable state at a given point, i.e. the vast majority of the nodes have the same view of the blockchain, at least until the next "best" block is mined.

For this to be possible, nodes may in principle exchange data (transactions, blocks) and metadata, i.e. hashes identifying said data on the network. So for example if a node A wants to see what's new, it's going to connect to another node, B, and ask for its "inventory":

0. A -> B : getblocks
1. B -> A : inv [ block h1, block h2, tx h3, ... ]
2. A -> B : getdata [block h1, block h2]
3. A -> B : getdata [tx h3]
4. B -> A : block h1_data
5. B -> A : block h2_data
6. B -> A : tx    h3_data

At 0, A asks B for its inventory; B then responds (1) with a list of blocks and/or transactions it has available; A follows up on the hashes and sends getdata requests (2, 3), to which B responds with the actual data (4, 5, 6). So for starters, we'll assume that the "wedge" occurs somewhere in, or between steps 1 and (2, 3). Actually, in my observations steps (2, 3) were never reached at all, but I did notice the following detail: after receiving an inventory from the peer, the node doesn't immediately proceed to issue getdata. Instead, it marks the data as being "asked for", for example:

askfor block 0000000000000000000e7f0c37df73c236ed49da75dbf3ce3ed5576137228bb4   0
sending getdata: block 0000000000000000000e7f0c37df73c236ed49da75dbf3ce3ed5576137228bb4
askfor tx 9680cf6c8d585a0257e09101e95b7d8c6a055d5fba8e95c58ec7184d01823640   0
sending getdata: tx 9680cf6c8d585a0257e09101e95b7d8c6a055d5fba8e95c58ec7184d01823640

If we grep for "askfor" in the Bitcoin sources, we get:

$ grep -rw askfor src
$ src/net.h:        printf("askfor %s   %"PRI64d"n", inv.ToString().c_str(), nRequestTime);

Looking at src/net.h, we notice that this printf is part of a function called AskFor, which, by the way, is called from ProcessMessage over in src/main.cpp, in response to inv messages. Let's expose AskFor here in all its nude glory:

void AskFor(const CInv& inv)
{
    // We're using mapAskFor as a priority queue,
    // the key is the earliest time the request can be sent
    int64& nRequestTime = mapAlreadyAskedFor[inv];
    printf("askfor %s   %"PRI64d"n", inv.ToString().c_str(), nRequestTime);

    // Make sure not to reuse time indexes to keep things in the same order
    int64 nNow = (GetTime() - 1) * 1000000;
    static int64 nLastTime;
    ++nLastTime;
    nNow = std::max(nNow, nLastTime);
    nLastTime = nNow;

    // Each retry is 2 minutes after the last
    nRequestTime = std::max(nRequestTime + 2 * 60 * 1000000, nNow);
    mapAskFor.insert(std::make_pair(nRequestTime, inv));
}

So we get an inv, which we use to perform some weird computation related to some timestamps: is it ever possible that nLastTime is bigger than nNow? I couldn't say from reading that piece of code, despite the fact that nLastTime is scoped within the very code that I shared with you. So anyway, the request time and the inventory item are placed together in an object, mapAskFor, which is used the following way:

$ grep -rw mapAskFor src
src/net.h:    std::multimap<int64, CInv> mapAskFor;
src/net.h:        // We're using mapAskFor as a priority queue,
src/net.h:        mapAskFor.insert(std::make_pair(nRequestTime, inv));
src/main.cpp:        while (!pto->mapAskFor.empty() && (*pto->mapAskFor.begin()).first <= nNow)
src/main.cpp:            const CInv& inv = (*pto->mapAskFor.begin()).second;
src/main.cpp:            pto->mapAskFor.erase(pto->mapAskFor.begin());

The first is the definition within the CNode class; the second and the third are part of AskFor; so we need to look further at src/main.cpp -- more precisely, at SendMessages, more precisely at the portion that issues getdata commands to peers:

    //
    // Message: getdata
    //
    vector<CInv> vGetData;
    int64 nNow = GetTime() * 1000000;
    CTxDB txdb("r");
    while (!pto->mapAskFor.empty() && (*pto->mapAskFor.begin()).first <= nNow)
    {
        const CInv& inv = (*pto->mapAskFor.begin()).second;
        if (!AlreadyHave(txdb, inv))
        {
            printf("sending getdata: %sn", inv.ToString().c_str());
            vGetData.push_back(inv);
            if (vGetData.size() >= 1000)
            {
                pto->PushMessage("getdata", vGetData);
                vGetData.clear();
            }
        }
        mapAlreadyAskedFor[inv] = nNow;
        pto->mapAskFor.erase(pto->mapAskFor.begin());
    }
    if (!vGetData.empty())
        pto->PushMessage("getdata", vGetData);

This piece of code is what's supposed to turn inv items into getdata requests, by grabbing items from the mapAskFor priority queue and trying to push them on the wire. The more interesting part to my eye is the:

!pto->mapAskFor.empty() && (*pto->mapAskFor.begin()).first <= nNow

condition, which not only expects that there are items in the queue, but it also expects that the so-called time index of the first item in the queue indicates that the message must be sent earlier than now... which sorta makes sense, since messages may be scheduled to be sent sometime in the future. This is how we realize that this whole consumer/producer thing is the implementation of an algorithm for scheduling getdata requests⁴. The algorithm, as far as I can tell so far, is:

# Upon receiving an inv...
1. Compute nRequestTime based on previous occurences of inv;
2. Update nLastTime based on nNow and previous nLastTime value;
3. Compute schedule time as
   a. nRequestTime + 2 minutes,
   b. or now, whichever is higher;
3. Place (schedule time, inv) in priority queue mapAskFor.

# mapAskFor is required to be:
# - traversable; and
# - sorted by schedule time, from oldest to newest?

# On transmit
1. while (mapAskFor has items and first item is schedulable)
   a. schedule getdata

The problem, as far as I could tell from my observation, and please do correct me if I'm wrong, is that either a. mapAskFor is not persistent between connections, so invs get lost; or b. mapAskFor does in fact not keep items sorted, which would be just plain weird, because that's as far as C++'s std::multimap guarantee goes⁵.

Anyway, in the common case mapAskFor will end up populated with hashes for a few blocks (as they come) and a whole shitload for relayed transactions, and the latter for some reason get prioritized over the former. This is why on my setup -connect (in conjunction with -nolisten) works just fine: no one connects to the node, so this scheduling queue doesn't get all filled up, so eventually the node will eventually send all getdata messages. Really, no extra "aggression" required, at least not more than is provided in Stan's "aggressive pushgetblocks" patch.

Alas, I see only one solution to this issue, and that is a complete rewrite of this getdata-scheduler, which I suppose would require a complete redesign of TRB's current multithreaded model. I'm not keen to dive into all that at the moment, so I am going to propose the following change⁶ in AskFor:

diff -uNr a/bitcoin/src/net.h b/bitcoin/src/net.h
--- a/bitcoin/src/net.h 492c9cc92a504bb8174d75fafcbee6980986182a459efc9bfa1d64766320d98ba2fa971d78d00a777c6cc50f82a5d424997927378e99738b1b3b550bdaa727f7
+++ b/bitcoin/src/net.h b83e0fe060dd237715ea511de804aebc49b0868614ef368673cb6ddd2014fc8126b92ee4cacc3d158862904d778f0adb50b6e19751ef4b9f22a4ca93e591402f
@@ -266,8 +266,11 @@
         nNow = std::max(nNow, nLastTime);
         nLastTime = nNow;

-        // Each retry is 2 minutes after the last
-        nRequestTime = std::max(nRequestTime + 2 * 60 * 1000000, nNow);
+       // Queue requests for TX later on to prioritize getting new blocks
+        if (inv.type == MSG_TX)
+            nRequestTime += 2 * 60 * 1000000;
+
+        nRequestTime = std::max(nRequestTime, nNow);
         mapAskFor.insert(std::make_pair(nRequestTime, inv));
     }

This programs the scheduling policy to prioritize "block" inv hashes over "tx" ones. As I was saying, I'm skeptical that this is an actual solution, but so far it's managed to help bring my node up to speed really quickly without any noticeable damage. Now, why I experienced this issue and others didn't, and why the magic numbers were chosen as they are, this is an entire mystery to me at the moment.

Meanwhile, my changes are available (along with all the others) in the following V patch:

• spyked_prio_askfor_msg_block.vpatch (seal)

Some relevant bits:

635283 spyked_prio_askfor_msg_block spyked

• Prioritize MSG_BLOCK hashes in the askfor priority queue;
• Print askfor debug data when -debug is passed;
• Removes max connection/IP address retardation, stolen from ben_vulpes_increase_aggression_levels experimental vpatch

Comments and questions are, as usual, welcome.

Filed under: computing.
RSS 2.0 feed. Comment. Send trackback.