Skip to content

Commit 835212c

Browse files
committed
Merge bitcoin/bitcoin#25880: p2p: Make stalling timeout adaptive during IBD
39b9364 test: add functional test for IBD stalling logic (Martin Zumsande) 0565951 p2p: Make block stalling timeout adaptive (Martin Zumsande) Pull request description: During IBD, there is the following stalling mechanism if we can't proceed with assigning blocks from a 1024 lookahead window because all of these blocks are either already downloaded or in-flight: We'll mark the peer from which we expect the current block that would allow us to advance our tip (and thereby move the 1024 window ahead) as a possible staller. We then give this peer 2 more seconds to deliver a block (`BLOCK_STALLING_TIMEOUT`) and if it doesn't, disconnect it and assign the critical block we need to another peer. Now the problem is that this second peer is immediately marked as a potential staller using the same mechanism and given 2 seconds as well - if our own connection is so slow that it simply takes us more than 2 seconds to download this block, that peer will also be disconnected (and so on...), leading to repeated disconnections and no progress in IBD. This has been described in #9213, and I have observed this when doing IBD on slower connections or with Tor - sometimes there would be several minutes without progress, where all we did was disconnect peers and find new ones. The `2s` stalling timeout was introduced in #4468, when blocks weren't full and before Segwit increased the maximum possible physical size of blocks - so I think it made a lot of sense back then. But it would be good to revisit this timeout now. This PR makes the timout adaptive (idea by sipa): If we disconnect a peer for stalling, we now double the timeout for the next peer (up to a maximum of 64s). If we connect a block, we half it again up to the old value of 2 seconds. That way, peers that are comparatively slower will still get disconnected, but long phases of disconnecting all peers shouldn't happen anymore. Fixes #9213 ACKs for top commit: achow101: ACK 39b9364 RandyMcMillan: Strong Concept ACK 39b9364 vasild: ACK 39b9364 naumenkogs: ACK 39b9364 Tree-SHA512: 85bc57093b2fb1d28d7409ed8df5a91543909405907bc129de7c6285d0810dd79bc05219e4d5aefcb55c85512b0ad5bed43a4114a17e46c35b9a3f9a983d5754
2 parents ffc22b7 + 39b9364 commit 835212c

File tree

3 files changed

+193
-4
lines changed

3 files changed

+193
-4
lines changed

src/net_processing.cpp

Lines changed: 28 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -113,8 +113,11 @@ static constexpr auto GETDATA_TX_INTERVAL{60s};
113113
static const unsigned int MAX_GETDATA_SZ = 1000;
114114
/** Number of blocks that can be requested at any given time from a single peer. */
115115
static const int MAX_BLOCKS_IN_TRANSIT_PER_PEER = 16;
116-
/** Time during which a peer must stall block download progress before being disconnected. */
117-
static constexpr auto BLOCK_STALLING_TIMEOUT{2s};
116+
/** Default time during which a peer must stall block download progress before being disconnected.
117+
* the actual timeout is increased temporarily if peers are disconnected for hitting the timeout */
118+
static constexpr auto BLOCK_STALLING_TIMEOUT_DEFAULT{2s};
119+
/** Maximum timeout for stalling block download. */
120+
static constexpr auto BLOCK_STALLING_TIMEOUT_MAX{64s};
118121
/** Number of headers sent in one getheaders result. We rely on the assumption that if a peer sends
119122
* less than this number, we reached its tip. Changing this value is a protocol upgrade. */
120123
static const unsigned int MAX_HEADERS_RESULTS = 2000;
@@ -774,6 +777,9 @@ class PeerManagerImpl final : public PeerManager
774777
/** Number of preferable block download peers. */
775778
int m_num_preferred_download_peers GUARDED_BY(cs_main){0};
776779

780+
/** Stalling timeout for blocks in IBD */
781+
std::atomic<std::chrono::seconds> m_block_stalling_timeout{BLOCK_STALLING_TIMEOUT_DEFAULT};
782+
777783
bool AlreadyHaveTx(const GenTxid& gtxid)
778784
EXCLUSIVE_LOCKS_REQUIRED(cs_main, !m_recent_confirmed_transactions_mutex);
779785

@@ -1812,7 +1818,8 @@ void PeerManagerImpl::StartScheduledTasks(CScheduler& scheduler)
18121818
/**
18131819
* Evict orphan txn pool entries based on a newly connected
18141820
* block, remember the recently confirmed transactions, and delete tracked
1815-
* announcements for them. Also save the time of the last tip update.
1821+
* announcements for them. Also save the time of the last tip update and
1822+
* possibly reduce dynamic block stalling timeout.
18161823
*/
18171824
void PeerManagerImpl::BlockConnected(const std::shared_ptr<const CBlock>& pblock, const CBlockIndex* pindex)
18181825
{
@@ -1835,6 +1842,16 @@ void PeerManagerImpl::BlockConnected(const std::shared_ptr<const CBlock>& pblock
18351842
m_txrequest.ForgetTxHash(ptx->GetWitnessHash());
18361843
}
18371844
}
1845+
1846+
// In case the dynamic timeout was doubled once or more, reduce it slowly back to its default value
1847+
auto stalling_timeout = m_block_stalling_timeout.load();
1848+
Assume(stalling_timeout >= BLOCK_STALLING_TIMEOUT_DEFAULT);
1849+
if (stalling_timeout != BLOCK_STALLING_TIMEOUT_DEFAULT) {
1850+
const auto new_timeout = std::max(std::chrono::duration_cast<std::chrono::seconds>(stalling_timeout * 0.85), BLOCK_STALLING_TIMEOUT_DEFAULT);
1851+
if (m_block_stalling_timeout.compare_exchange_strong(stalling_timeout, new_timeout)) {
1852+
LogPrint(BCLog::NET, "Decreased stalling timeout to %d seconds\n", new_timeout.count());
1853+
}
1854+
}
18381855
}
18391856

18401857
void PeerManagerImpl::BlockDisconnected(const std::shared_ptr<const CBlock> &block, const CBlockIndex* pindex)
@@ -5713,12 +5730,19 @@ bool PeerManagerImpl::SendMessages(CNode* pto)
57135730
m_connman.PushMessage(pto, msgMaker.Make(NetMsgType::INV, vInv));
57145731

57155732
// Detect whether we're stalling
5716-
if (state.m_stalling_since.count() && state.m_stalling_since < current_time - BLOCK_STALLING_TIMEOUT) {
5733+
auto stalling_timeout = m_block_stalling_timeout.load();
5734+
if (state.m_stalling_since.count() && state.m_stalling_since < current_time - stalling_timeout) {
57175735
// Stalling only triggers when the block download window cannot move. During normal steady state,
57185736
// the download window should be much larger than the to-be-downloaded set of blocks, so disconnection
57195737
// should only happen during initial block download.
57205738
LogPrintf("Peer=%d is stalling block download, disconnecting\n", pto->GetId());
57215739
pto->fDisconnect = true;
5740+
// Increase timeout for the next peer so that we don't disconnect multiple peers if our own
5741+
// bandwidth is insufficient.
5742+
const auto new_timeout = std::min(2 * stalling_timeout, BLOCK_STALLING_TIMEOUT_MAX);
5743+
if (stalling_timeout != new_timeout && m_block_stalling_timeout.compare_exchange_strong(stalling_timeout, new_timeout)) {
5744+
LogPrint(BCLog::NET, "Increased stalling timeout temporarily to %d seconds\n", m_block_stalling_timeout.load().count());
5745+
}
57225746
return true;
57235747
}
57245748
// In case there is a block that has been in flight from this peer for block_interval * (1 + 0.5 * N)

test/functional/p2p_ibd_stalling.py

Lines changed: 164 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,164 @@
1+
#!/usr/bin/env python3
2+
# Copyright (c) 2022- The Bitcoin Core developers
3+
# Distributed under the MIT software license, see the accompanying
4+
# file COPYING or http://www.opensource.org/licenses/mit-license.php.
5+
"""
6+
Test stalling logic during IBD
7+
"""
8+
9+
import time
10+
11+
from test_framework.blocktools import (
12+
create_block,
13+
create_coinbase
14+
)
15+
from test_framework.messages import (
16+
MSG_BLOCK,
17+
MSG_TYPE_MASK,
18+
)
19+
from test_framework.p2p import (
20+
CBlockHeader,
21+
msg_block,
22+
msg_headers,
23+
P2PDataStore,
24+
)
25+
from test_framework.test_framework import BitcoinTestFramework
26+
from test_framework.util import (
27+
assert_equal,
28+
)
29+
30+
31+
class P2PStaller(P2PDataStore):
32+
def __init__(self, stall_block):
33+
self.stall_block = stall_block
34+
super().__init__()
35+
36+
def on_getdata(self, message):
37+
for inv in message.inv:
38+
self.getdata_requests.append(inv.hash)
39+
if (inv.type & MSG_TYPE_MASK) == MSG_BLOCK:
40+
if (inv.hash != self.stall_block):
41+
self.send_message(msg_block(self.block_store[inv.hash]))
42+
43+
def on_getheaders(self, message):
44+
pass
45+
46+
47+
class P2PIBDStallingTest(BitcoinTestFramework):
48+
def set_test_params(self):
49+
self.setup_clean_chain = True
50+
self.num_nodes = 1
51+
52+
def run_test(self):
53+
NUM_BLOCKS = 1025
54+
NUM_PEERS = 4
55+
node = self.nodes[0]
56+
tip = int(node.getbestblockhash(), 16)
57+
blocks = []
58+
height = 1
59+
block_time = node.getblock(node.getbestblockhash())['time'] + 1
60+
self.log.info("Prepare blocks without sending them to the node")
61+
block_dict = {}
62+
for _ in range(NUM_BLOCKS):
63+
blocks.append(create_block(tip, create_coinbase(height), block_time))
64+
blocks[-1].solve()
65+
tip = blocks[-1].sha256
66+
block_time += 1
67+
height += 1
68+
block_dict[blocks[-1].sha256] = blocks[-1]
69+
stall_block = blocks[0].sha256
70+
71+
headers_message = msg_headers()
72+
headers_message.headers = [CBlockHeader(b) for b in blocks[:NUM_BLOCKS-1]]
73+
peers = []
74+
75+
self.log.info("Check that a staller does not get disconnected if the 1024 block lookahead buffer is filled")
76+
for id in range(NUM_PEERS):
77+
peers.append(node.add_outbound_p2p_connection(P2PStaller(stall_block), p2p_idx=id, connection_type="outbound-full-relay"))
78+
peers[-1].block_store = block_dict
79+
peers[-1].send_message(headers_message)
80+
81+
# Need to wait until 1023 blocks are received - the magic total bytes number is a workaround in lack of an rpc
82+
# returning the number of downloaded (but not connected) blocks.
83+
self.wait_until(lambda: self.total_bytes_recv_for_blocks() == 172761)
84+
85+
self.all_sync_send_with_ping(peers)
86+
# If there was a peer marked for stalling, it would get disconnected
87+
self.mocktime = int(time.time()) + 3
88+
node.setmocktime(self.mocktime)
89+
self.all_sync_send_with_ping(peers)
90+
assert_equal(node.num_test_p2p_connections(), NUM_PEERS)
91+
92+
self.log.info("Check that increasing the window beyond 1024 blocks triggers stalling logic")
93+
headers_message.headers = [CBlockHeader(b) for b in blocks]
94+
with node.assert_debug_log(expected_msgs=['Stall started']):
95+
for p in peers:
96+
p.send_message(headers_message)
97+
self.all_sync_send_with_ping(peers)
98+
99+
self.log.info("Check that the stalling peer is disconnected after 2 seconds")
100+
self.mocktime += 3
101+
node.setmocktime(self.mocktime)
102+
peers[0].wait_for_disconnect()
103+
assert_equal(node.num_test_p2p_connections(), NUM_PEERS - 1)
104+
self.wait_until(lambda: self.is_block_requested(peers, stall_block))
105+
# Make sure that SendMessages() is invoked, which assigns the missing block
106+
# to another peer and starts the stalling logic for them
107+
self.all_sync_send_with_ping(peers)
108+
109+
self.log.info("Check that the stalling timeout gets doubled to 4 seconds for the next staller")
110+
# No disconnect after just 3 seconds
111+
self.mocktime += 3
112+
node.setmocktime(self.mocktime)
113+
self.all_sync_send_with_ping(peers)
114+
assert_equal(node.num_test_p2p_connections(), NUM_PEERS - 1)
115+
116+
self.mocktime += 2
117+
node.setmocktime(self.mocktime)
118+
self.wait_until(lambda: node.num_test_p2p_connections() == NUM_PEERS - 2)
119+
self.wait_until(lambda: self.is_block_requested(peers, stall_block))
120+
self.all_sync_send_with_ping(peers)
121+
122+
self.log.info("Check that the stalling timeout gets doubled to 8 seconds for the next staller")
123+
# No disconnect after just 7 seconds
124+
self.mocktime += 7
125+
node.setmocktime(self.mocktime)
126+
self.all_sync_send_with_ping(peers)
127+
assert_equal(node.num_test_p2p_connections(), NUM_PEERS - 2)
128+
129+
self.mocktime += 2
130+
node.setmocktime(self.mocktime)
131+
self.wait_until(lambda: node.num_test_p2p_connections() == NUM_PEERS - 3)
132+
self.wait_until(lambda: self.is_block_requested(peers, stall_block))
133+
self.all_sync_send_with_ping(peers)
134+
135+
self.log.info("Provide the withheld block and check that stalling timeout gets reduced back to 2 seconds")
136+
with node.assert_debug_log(expected_msgs=['Decreased stalling timeout to 2 seconds']):
137+
for p in peers:
138+
if p.is_connected and (stall_block in p.getdata_requests):
139+
p.send_message(msg_block(block_dict[stall_block]))
140+
141+
self.log.info("Check that all outstanding blocks get connected")
142+
self.wait_until(lambda: node.getblockcount() == NUM_BLOCKS)
143+
144+
def total_bytes_recv_for_blocks(self):
145+
total = 0
146+
for info in self.nodes[0].getpeerinfo():
147+
if ("block" in info["bytesrecv_per_msg"].keys()):
148+
total += info["bytesrecv_per_msg"]["block"]
149+
return total
150+
151+
def all_sync_send_with_ping(self, peers):
152+
for p in peers:
153+
if p.is_connected:
154+
p.sync_send_with_ping()
155+
156+
def is_block_requested(self, peers, hash):
157+
for p in peers:
158+
if p.is_connected and (hash in p.getdata_requests):
159+
return True
160+
return False
161+
162+
163+
if __name__ == '__main__':
164+
P2PIBDStallingTest().main()

test/functional/test_runner.py

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -254,6 +254,7 @@
254254
'wallet_importprunedfunds.py --descriptors',
255255
'p2p_leak_tx.py',
256256
'p2p_eviction.py',
257+
'p2p_ibd_stalling.py',
257258
'wallet_signmessagewithaddress.py',
258259
'rpc_signmessagewithprivkey.py',
259260
'rpc_generate.py',

0 commit comments

Comments
 (0)