[P2P] Staller logic might need revisiting? #9213

issue sdaftuar openend this issue on November 23, 2016

sdaftuar commented at 5:37 pm on November 23, 2016: member

Describe the issue

I need to investigate a bit more, but I just completed a fresh sync from scratch using master, and I noticed some odd behavior with the stalling logic.

I was initially connected to 8 outbound peers (and no others), and then to speed up the sync, I decided to addnode an instance on my local network that was caught up. So in particular, block transfer times to this new node were very quick.

What was unusual was that even though this machine fast, it was getting disconnected repeatedly during IBD for stalling (it would then get readded, since addnode’d it). I started to look through my debug log to see what was going on, and it appears to me that it may have been something like this:

Some other peer X is stalling, gets disconnected.
Connect to some new peer Y.
X’s blocks get assigned to other peers, maybe the local one.
If we’re near the end of the download window, then because Y is available not downloading any blocks, the peer that was reassigned X’s block has 1 second (?) to provide the block, or else that peer is stalling.

So it looked to me like I’d go through periods of time where everyone was getting disconnected for stalling, such as this particularly egregious example:

 02016-11-22 13:08:52 UpdateTip: new best=00000000000000003085d45701cef706396618d68bea4b9551b7442b031d1863 height=313019 version=0x00000002 log2_work=79.946856 tx=43453816 date='2014-07-29 15:40:42' progress=0.218633 cache
 1=1581.8MiB(3793192tx)
 22016-11-22 13:08:54 Peer=290 is stalling block download, disconnecting
 32016-11-22 13:08:56 Peer=282 is stalling block download, disconnecting
 42016-11-22 13:08:58 Peer=291 is stalling block download, disconnecting
 52016-11-22 13:09:06 Peer=292 is stalling block download, disconnecting
 62016-11-22 13:09:08 Peer=286 is stalling block download, disconnecting
 72016-11-22 13:09:11 Peer=293 is stalling block download, disconnecting
 82016-11-22 13:09:15 Peer=294 is stalling block download, disconnecting
 92016-11-22 13:09:17 Peer=295 is stalling block download, disconnecting
102016-11-22 13:09:19 Peer=296 is stalling block download, disconnecting
112016-11-22 13:09:21 Peer=297 is stalling block download, disconnecting
122016-11-22 13:09:23 Peer=298 is stalling block download, disconnecting
132016-11-22 13:09:28 Peer=299 is stalling block download, disconnecting
142016-11-22 13:09:30 Peer=300 is stalling block download, disconnecting
152016-11-22 13:09:32 Peer=301 is stalling block download, disconnecting
162016-11-22 13:09:35 Peer=302 is stalling block download, disconnecting
172016-11-22 13:09:37 Peer=303 is stalling block download, disconnecting
182016-11-22 13:09:39 Peer=304 is stalling block download, disconnecting
192016-11-22 13:09:41 Peer=305 is stalling block download, disconnecting
202016-11-22 13:09:43 Peer=306 is stalling block download, disconnecting
212016-11-22 13:09:45 Peer=307 is stalling block download, disconnecting
222016-11-22 13:09:48 Peer=309 is stalling block download, disconnecting
232016-11-22 13:09:51 Peer=310 is stalling block download, disconnecting
242016-11-22 13:09:53 Peer=311 is stalling block download, disconnecting
252016-11-22 13:09:55 Peer=312 is stalling block download, disconnecting
262016-11-22 13:09:57 Peer=313 is stalling block download, disconnecting
272016-11-22 13:09:59 UpdateTip: new best=00000000000000001291028bceab2639c12c762be3988017cba99fa792b460c4 height=313020 version=0x00000002 log2_work=79.946955 tx=43454953 date='2014-07-29 15:45:18' progress=0.218647 cache=1581.8MiB(3793020tx)

EDIT: forgot to mention that the above snippet is from me grepping for “stalling|UpdateTip” in my debug.log, so the new connections that happened in between those stalling messages aren’t shown.

maflcko commented at 6:08 pm on November 23, 2016: member

Agree that the stalling logic needs some fine tuning. I am pretty sure I hit the scenario you describe above when debugging #8518.
fanquake added the label P2P on Nov 24, 2016
rebroad commented at 3:55 am on December 13, 2016: contributor

#9337 shows some additional debug which may help here. Esssentially the current timeout logic is completely ignoring the fact that blocks are being downloaded, albeit more slowly than expected, and the current timeout on stallers is only 2 seconds - i.e. if it remains the node that is being waited on for more than 2 seconds (which is very likely) it gets disconnected. What is needed is extra logic to determine the speed of each peer and factor this in to the number of blocks being requested from each peer. I wrote code back in 2012 which did this, but it wasn’t up to the standards needed to get it merged. (probably “layer violations”).

Without the logic I am suggesting then it is often likely that nodes will become staller nodes. Part of the problem is that blocks are not “striped” amongst nodes, but instead are tasked with a bunch of consequtive blocks which makes occurrence of “staller nodes” far more likely.

What I propose is that when the node starts up , as soon as it has calculated how many blocks behind it is, it works out how to spread these blocks over the nodes it will download them from. E.g. if it will be downlaoding from 6 peers, then it could skip 5 blocks for block height it requests from each node. This could be the initial logic, but if there is a lot to download, additional logic would also factor in the speed of each connection.
rebroad referenced this in commit 1913318e7e on Dec 13, 2016
rebroad referenced this in commit 407b72d2e5 on Dec 13, 2016
rebroad referenced this in commit 5a80993a1e on Dec 13, 2016
rebroad referenced this in commit e94213dfb0 on Dec 14, 2016
rebroad referenced this in commit 543c7892e7 on Dec 16, 2016
dooglus commented at 7:12 am on August 1, 2017: contributor

I’m running v0.14.2 and attempting to sync testnet on a slow Internet connection.

I’m seeing lots of these ‘stalling’ messages. See this attachment, created using:

grep -e 'Bitcoin version' -e 'height=' -e 'is stalling block' testnet3/debug.log

StopAndDecrypt commented at 4:06 am on December 30, 2020: none

I’m running v0.20.1 and performing mainnet IBD over Tor. This issue keeps occurring for me intermittently. It does eventually stop on its own, but keeps resurfacing:

Edit: ~~I think I managed to “resolve” the issue, although I’m not sure that what I did should be necessary to prevent this.~~ I realized a similarity between my configuration and sdaftuar’s: We both had addnodes configured. The difference is mine were added because my node was configured to only connect over Tor, and needed .onion seeds. ~~After removing the seeds from bitcoin.conf and relaunching, the intermittent batches of stalling errors seem to have completely stopped.~~

Edit 2: Removing the addnodes did not resolve the issue, but it does stop the node from connecting to the same peers again right after it just disconnected them (which would delay recovery).

Log output looks identical every time: UpdateTip stops, eventually all peers stall and get disconnected, new set of peers connect, UpdateTip resumes (for however long until the issue resurfaces).

  02020-12-30T03:44:33Z UpdateTip: new best=000000000000000000397ed285257b8eae9d557e7e98f2781ebdc47669e79f37 height=505292 version=0x20000000 log2_work=87.924262 tx=294245342 date='2018-01-21T04:58:15Z' progress=0.494541 cache=656.1MiB(4998848txo)
  12020-12-30T03:44:34Z UpdateTip: new best=0000000000000000000133886c99831806048ea59ed03641639cf236c5eb0c5c height=505293 version=0x20000000 log2_work=87.924309 tx=294248265 date='2018-01-21T05:02:25Z' progress=0.494546 cache=656.9MiB(5005432txo)
  22020-12-30T03:44:36Z UpdateTip: new best=0000000000000000003fcbe0f81181430fd34ff04bd19305256c38a865e72be9 height=505294 version=0x20000000 log2_work=87.924356 tx=294249359 date='2018-01-21T05:02:39Z' progress=0.494548 cache=657.7MiB(5012410txo)
  32020-12-30T03:44:37Z UpdateTip: new best=0000000000000000001fcda7b794e8bc548a3b993c83da73da48f460f6ab2c47 height=505295 version=0x20000000 log2_work=87.924403 tx=294251172 date='2018-01-21T05:16:23Z' progress=0.494551 cache=658.2MiB(5015949txo)
  42020-12-30T03:44:38Z UpdateTip: new best=0000000000000000000a150ab009ec10d90a31ad1eed18a93516ca72c076a47a height=505296 version=0x20000000 log2_work=87.92445 tx=294252464 date='2018-01-21T05:23:32Z' progress=0.494553 cache=658.8MiB(5021255txo)
  52020-12-30T03:44:38Z UpdateTip: new best=000000000000000000128713e4cb3cbb1da8def1c29da796143f069a81f6b1fd height=505297 version=0x20000000 log2_work=87.924497 tx=294254396 date='2018-01-21T05:43:43Z' progress=0.494556 cache=659.0MiB(5023008txo)
  62020-12-30T03:44:39Z UpdateTip: new best=0000000000000000004b73cd573a37396257144289274338c91ab633b57bab4c height=505298 version=0x20000000 log2_work=87.924544 tx=294255159 date='2018-01-21T05:45:16Z' progress=0.494557 cache=659.5MiB(5027049txo)
  72020-12-30T03:44:40Z Pre-allocating up to position 0x600000 in rev01148.dat
  82020-12-30T03:44:40Z UpdateTip: new best=0000000000000000004770f72a2a02a8d518a1acd1e2261036e50bcc51fc4c03 height=505299 version=0x20000000 log2_work=87.924591 tx=294255920 date='2018-01-21T05:52:51Z' progress=0.494559 cache=659.7MiB(5028413txo)
  92020-12-30T03:44:40Z UpdateTip: new best=00000000000000000054fd43bfab7d9c7479172f8a3f4e62a243118a41e9f449 height=505300 version=0x20000000 log2_work=87.924638 tx=294257498 date='2018-01-21T06:11:01Z' progress=0.494561 cache=660.5MiB(5034942txo)
 102020-12-30T03:44:41Z UpdateTip: new best=0000000000000000006ca8d5c8863ee71f11cffde7bfc4725479f030de3832ab height=505301 version=0x20000000 log2_work=87.924685 tx=294258640 date='2018-01-21T06:21:40Z' progress=0.494563 cache=661.2MiB(5040558txo)
 112020-12-30T03:44:42Z UpdateTip: new best=00000000000000000050b25a5f412954d590e0cddcf2a4fb4b023b268e758597 height=505302 version=0x20000000 log2_work=87.924732 tx=294260563 date='2018-01-21T06:41:42Z' progress=0.494566 cache=661.5MiB(5043064txo)
 122020-12-30T03:44:42Z UpdateTip: new best=0000000000000000003dc2ae6ce48079901bb9f9d8df0122a6ef6d795be67a87 height=505303 version=0x20000000 log2_work=87.924779 tx=294261253 date='2018-01-21T06:46:30Z' progress=0.494568 cache=662.0MiB(5047234txo)
 132020-12-30T03:44:43Z UpdateTip: new best=00000000000000000055c8b06ef4537248819119ea5af32b1c02b17212cb027b height=505304 version=0x20000000 log2_work=87.924826 tx=294262281 date='2018-01-21T06:47:25Z' progress=0.494569 cache=662.6MiB(5052418txo)
 142020-12-30T03:44:43Z FlushStateToDisk: write coins cache to disk (5052418 coins, 694817kB) started
 152020-12-30T03:44:59Z FlushStateToDisk: write coins cache to disk (5052418 coins, 694817kB) completed (16.26s)
 162020-12-30T03:45:00Z Leaving block file 1148: CBlockFileInfo(blocks=124, size=133147038, heights=505222...505571, time=2018-01-20...2018-01-22)
 172020-12-30T03:45:00Z Pre-allocating up to position 0x1000000 in blk01149.dat
 182020-12-30T03:45:00Z New outbound peer connected: version: 70015, blocks=663603, peer=952 (full-relay)
 192020-12-30T03:45:00Z New outbound peer connected: version: 70015, blocks=663603, peer=953 (full-relay)
 202020-12-30T03:45:00Z Pre-allocating up to position 0x2000000 in blk01149.dat
 212020-12-30T03:45:01Z Pre-allocating up to position 0x3000000 in blk01149.dat
 222020-12-30T03:45:01Z Pre-allocating up to position 0x4000000 in blk01149.dat
 232020-12-30T03:45:02Z Pre-allocating up to position 0x5000000 in blk01149.dat
 242020-12-30T03:45:02Z Pre-allocating up to position 0x6000000 in blk01149.dat
 252020-12-30T03:45:02Z Pre-allocating up to position 0x7000000 in blk01149.dat
 262020-12-30T03:45:03Z Pre-allocating up to position 0x8000000 in blk01149.dat
 272020-12-30T03:45:03Z Leaving block file 1149: CBlockFileInfo(blocks=126, size=133679477, heights=505323...505631, time=2018-01-21...2018-01-23)
 282020-12-30T03:45:03Z Pre-allocating up to position 0x1000000 in blk01150.dat
 292020-12-30T03:45:04Z Pre-allocating up to position 0x2000000 in blk01150.dat
 302020-12-30T03:45:04Z Pre-allocating up to position 0x3000000 in blk01150.dat
 312020-12-30T03:45:10Z Pre-allocating up to position 0x4000000 in blk01150.dat
 322020-12-30T03:45:14Z Pre-allocating up to position 0x5000000 in blk01150.dat
 332020-12-30T03:45:18Z Pre-allocating up to position 0x6000000 in blk01150.dat
 342020-12-30T03:45:22Z Pre-allocating up to position 0x7000000 in blk01150.dat
 352020-12-30T03:45:26Z Pre-allocating up to position 0x8000000 in blk01150.dat
 362020-12-30T03:45:31Z Leaving block file 1150: CBlockFileInfo(blocks=123, size=133780047, heights=505373...505762, time=2018-01-21...2018-01-23)
 372020-12-30T03:45:31Z Pre-allocating up to position 0x1000000 in blk01151.dat
 382020-12-30T03:45:36Z Pre-allocating up to position 0x2000000 in blk01151.dat
 392020-12-30T03:45:41Z Pre-allocating up to position 0x3000000 in blk01151.dat
 402020-12-30T03:45:45Z New outbound peer connected: version: 70015, blocks=663603, peer=954 (full-relay)
 412020-12-30T03:45:47Z Pre-allocating up to position 0x4000000 in blk01151.dat
 422020-12-30T03:45:48Z New outbound peer connected: version: 70015, blocks=663603, peer=955 (full-relay)
 432020-12-30T03:45:54Z Pre-allocating up to position 0x5000000 in blk01151.dat
 442020-12-30T03:46:00Z Pre-allocating up to position 0x6000000 in blk01151.dat
 452020-12-30T03:46:04Z Pre-allocating up to position 0x7000000 in blk01151.dat
 462020-12-30T03:46:10Z Pre-allocating up to position 0x8000000 in blk01151.dat
 472020-12-30T03:46:17Z Leaving block file 1151: CBlockFileInfo(blocks=126, size=134074627, heights=505534...505922, time=2018-01-22...2018-01-24)
 482020-12-30T03:46:17Z Pre-allocating up to position 0x1000000 in blk01152.dat
 492020-12-30T03:46:24Z Pre-allocating up to position 0x2000000 in blk01152.dat
 502020-12-30T03:46:30Z Pre-allocating up to position 0x3000000 in blk01152.dat
 512020-12-30T03:46:31Z New outbound peer connected: version: 70015, blocks=663603, peer=956 (full-relay)
 522020-12-30T03:46:33Z New outbound peer connected: version: 70015, blocks=663603, peer=957 (full-relay)
 532020-12-30T03:46:34Z Pre-allocating up to position 0x4000000 in blk01152.dat
 542020-12-30T03:46:39Z Pre-allocating up to position 0x5000000 in blk01152.dat
 552020-12-30T03:46:43Z Pre-allocating up to position 0x6000000 in blk01152.dat
 562020-12-30T03:46:47Z Pre-allocating up to position 0x7000000 in blk01152.dat
 572020-12-30T03:46:51Z Pre-allocating up to position 0x8000000 in blk01152.dat
 582020-12-30T03:46:56Z Leaving block file 1152: CBlockFileInfo(blocks=124, size=133848423, heights=505677...506078, time=2018-01-23...2018-01-25)
 592020-12-30T03:46:56Z Pre-allocating up to position 0x1000000 in blk01153.dat
 602020-12-30T03:47:03Z Pre-allocating up to position 0x2000000 in blk01153.dat
 612020-12-30T03:47:09Z Pre-allocating up to position 0x3000000 in blk01153.dat
 622020-12-30T03:47:16Z Pre-allocating up to position 0x4000000 in blk01153.dat
 632020-12-30T03:47:22Z Pre-allocating up to position 0x5000000 in blk01153.dat
 642020-12-30T03:47:27Z Pre-allocating up to position 0x6000000 in blk01153.dat
 652020-12-30T03:47:35Z Pre-allocating up to position 0x7000000 in blk01153.dat
 662020-12-30T03:47:35Z New outbound peer connected: version: 70015, blocks=663603, peer=958 (full-relay)
 672020-12-30T03:47:38Z New outbound peer connected: version: 70015, blocks=663603, peer=959 (full-relay)
 682020-12-30T03:47:40Z Pre-allocating up to position 0x8000000 in blk01153.dat
 692020-12-30T03:47:45Z Leaving block file 1153: CBlockFileInfo(blocks=121, size=133856284, heights=505450...506178, time=2018-01-22...2018-01-26)
 702020-12-30T03:47:45Z Pre-allocating up to position 0x1000000 in blk01154.dat
 712020-12-30T03:47:50Z Pre-allocating up to position 0x2000000 in blk01154.dat
 722020-12-30T03:47:54Z Pre-allocating up to position 0x3000000 in blk01154.dat
 732020-12-30T03:47:58Z Pre-allocating up to position 0x4000000 in blk01154.dat
 742020-12-30T03:48:02Z Pre-allocating up to position 0x5000000 in blk01154.dat
 752020-12-30T03:48:07Z Pre-allocating up to position 0x100000 in rev01154.dat
 762020-12-30T03:48:07Z UpdateTip: new best=0000000000000000000f16e008f5e2810f7aadd268d71f1dd5b23d4df51ef3d7 height=505305 version=0x20000000 log2_work=87.924873 tx=294263855 date='2018-01-21T06:59:11Z' progress=0.494571 cache=46.7MiB(9336txo)
 772020-12-30T03:48:08Z Pre-allocating up to position 0x6000000 in blk01154.dat
 782020-12-30T03:48:15Z Pre-allocating up to position 0x7000000 in blk01154.dat
 792020-12-30T03:48:20Z Pre-allocating up to position 0x8000000 in blk01154.dat
 802020-12-30T03:48:21Z New outbound peer connected: version: 70015, blocks=663603, peer=960 (full-relay)
 812020-12-30T03:48:23Z New outbound peer connected: version: 70015, blocks=663603, peer=961 (full-relay)
 822020-12-30T03:48:24Z Peer=896 is stalling block download, disconnecting
 832020-12-30T03:48:25Z Leaving block file 1154: CBlockFileInfo(blocks=126, size=134052493, heights=505305...506277, time=2018-01-21...2018-01-27)
 842020-12-30T03:48:26Z Pre-allocating up to position 0x1000000 in blk01155.dat
 852020-12-30T03:48:28Z Peer=861 is stalling block download, disconnecting
 862020-12-30T03:48:31Z Peer=862 is stalling block download, disconnecting
 872020-12-30T03:48:33Z Pre-allocating up to position 0x2000000 in blk01155.dat
 882020-12-30T03:48:34Z Peer=890 is stalling block download, disconnecting
 892020-12-30T03:48:36Z Peer=889 is stalling block download, disconnecting
 902020-12-30T03:48:38Z Peer=893 is stalling block download, disconnecting
 912020-12-30T03:48:40Z Peer=891 is stalling block download, disconnecting
 922020-12-30T03:48:44Z Pre-allocating up to position 0x3000000 in blk01155.dat
 932020-12-30T03:48:54Z New outbound peer connected: version: 70015, blocks=663603, peer=962 (full-relay)
 942020-12-30T03:48:56Z New outbound peer connected: version: 70015, blocks=663603, peer=963 (full-relay)
 952020-12-30T03:48:57Z Pre-allocating up to position 0x4000000 in blk01155.dat
 962020-12-30T03:48:57Z Peer=900 is stalling block download, disconnecting
 972020-12-30T03:48:59Z Peer=892 is stalling block download, disconnecting
 982020-12-30T03:49:08Z Pre-allocating up to position 0x5000000 in blk01155.dat
 992020-12-30T03:49:19Z New outbound peer connected: version: 70015, blocks=663603, peer=964 (full-relay)
1002020-12-30T03:49:19Z Pre-allocating up to position 0x6000000 in blk01155.dat
1012020-12-30T03:49:26Z New outbound peer connected: version: 70015, blocks=663603, peer=965 (full-relay)
1022020-12-30T03:49:27Z New outbound peer connected: version: 70015, blocks=663603, peer=966 (full-relay)
1032020-12-30T03:49:28Z Peer=941 is stalling block download, disconnecting
1042020-12-30T03:49:30Z Peer=894 is stalling block download, disconnecting
1052020-12-30T03:49:31Z Pre-allocating up to position 0x7000000 in blk01155.dat
1062020-12-30T03:49:33Z Peer=899 is stalling block download, disconnecting
1072020-12-30T03:49:36Z Peer=942 is stalling block download, disconnecting
1082020-12-30T03:49:38Z Peer=949 is stalling block download, disconnecting
1092020-12-30T03:49:40Z Peer=963 is stalling block download, disconnecting
1102020-12-30T03:49:46Z Pre-allocating up to position 0x8000000 in blk01155.dat
1112020-12-30T03:49:49Z Pre-allocating up to position 0x100000 in rev01155.dat
1122020-12-30T03:49:49Z UpdateTip: new best=000000000000000000142b299c40885463b35d4887b81c2cb5012d6445becb56 height=505306 version=0x20000000 log2_work=87.92492 tx=294265370 date='2018-01-21T07:11:21Z' progress=0.494574 cache=47.7MiB(18105txo)
1132020-12-30T03:49:50Z New outbound peer connected: version: 70015, blocks=663603, peer=967 (full-relay)
1142020-12-30T03:49:53Z Peer=946 is stalling block download, disconnecting
1152020-12-30T03:50:05Z Leaving block file 1155: CBlockFileInfo(blocks=127, size=132983136, heights=505306...506329, time=2018-01-21...2018-01-27)
1162020-12-30T03:50:05Z Pre-allocating up to position 0x1000000 in blk01156.dat
1172020-12-30T03:50:08Z New outbound peer connected: version: 70015, blocks=663603, peer=968 (full-relay)
1182020-12-30T03:50:15Z Peer=962 is stalling block download, disconnecting
1192020-12-30T03:50:28Z New outbound peer connected: version: 70015, blocks=663603, peer=969 (full-relay)
1202020-12-30T03:50:31Z New outbound peer connected: version: 70015, blocks=663603, peer=970 (full-relay)
1212020-12-30T03:50:33Z Pre-allocating up to position 0x2000000 in blk01156.dat
1222020-12-30T03:50:34Z New outbound peer connected: version: 70015, blocks=663603, peer=971 (full-relay)
1232020-12-30T03:50:35Z New outbound peer connected: version: 70015, blocks=663603, peer=972 (full-relay)
1242020-12-30T03:50:36Z Peer=965 is stalling block download, disconnecting
1252020-12-30T03:50:38Z New outbound peer connected: version: 70015, blocks=663603, peer=973 (full-relay)
1262020-12-30T03:50:38Z Peer=969 is stalling block download, disconnecting
1272020-12-30T03:50:40Z Peer=970 is stalling block download, disconnecting
1282020-12-30T03:50:41Z New outbound peer connected: version: 70015, blocks=663603, peer=974 (full-relay)
1292020-12-30T03:50:43Z Peer=971 is stalling block download, disconnecting
1302020-12-30T03:50:45Z Peer=972 is stalling block download, disconnecting
1312020-12-30T03:50:46Z New outbound peer connected: version: 70015, blocks=663603, peer=975 (full-relay)
1322020-12-30T03:50:56Z Pre-allocating up to position 0x100000 in rev01156.dat
1332020-12-30T03:50:56Z UpdateTip: new best=00000000000000000043773fd64aa6a904b93bd7cd1065626a5dc43fbadd4356 height=505307 version=0x20000000 log2_work=87.924967 tx=294266957 date='2018-01-21T07:27:54Z' progress=0.494576 cache=48.8MiB(26394txo)
1342020-12-30T03:51:02Z UpdateTip: new best=00000000000000000042b98e9afc74f9fd3c0b1eb606ce7811905f5c45d9ecee height=505308 version=0x20000000 log2_work=87.925014 tx=294268281 date='2018-01-21T07:33:03Z' progress=0.494578 cache=49.6MiB(33643txo)
1352020-12-30T03:51:02Z New outbound peer connected: version: 70015, blocks=663603, peer=976 (full-relay)
1362020-12-30T03:51:06Z New outbound peer connected: version: 70015, blocks=663603, peer=977 (full-relay)
1372020-12-30T03:51:30Z New outbound peer connected: version: 70015, blocks=663603, peer=979 (full-relay)
1382020-12-30T03:51:32Z Pre-allocating up to position 0x3000000 in blk01156.dat
1392020-12-30T03:51:32Z New outbound peer connected: version: 70015, blocks=663603, peer=980 (full-relay)
1402020-12-30T03:51:33Z Peer=964 is stalling block download, disconnecting
1412020-12-30T03:51:35Z Peer=945 is stalling block download, disconnecting
1422020-12-30T03:51:38Z Peer=977 is stalling block download, disconnecting
1432020-12-30T03:51:55Z New outbound peer connected: version: 70015, blocks=663603, peer=981 (full-relay)
1442020-12-30T03:51:58Z New outbound peer connected: version: 70015, blocks=663603, peer=982 (full-relay)
1452020-12-30T03:52:01Z Peer=979 is stalling block download, disconnecting
1462020-12-30T03:52:21Z New outbound peer connected: version: 70015, blocks=663603, peer=983 (full-relay)
1472020-12-30T03:52:23Z New outbound peer connected: version: 70015, blocks=663603, peer=984 (full-relay)
1482020-12-30T03:52:24Z Pre-allocating up to position 0x4000000 in blk01156.dat
1492020-12-30T03:52:25Z Peer=981 is stalling block download, disconnecting
1502020-12-30T03:52:25Z New outbound peer connected: version: 70015, blocks=663603, peer=985 (full-relay)
1512020-12-30T03:52:27Z Peer=982 is stalling block download, disconnecting
1522020-12-30T03:52:29Z Peer=983 is stalling block download, disconnecting
1532020-12-30T03:52:31Z Peer=984 is stalling block download, disconnecting
1542020-12-30T03:52:31Z New outbound peer connected: version: 70015, blocks=663603, peer=986 (full-relay)
1552020-12-30T03:52:34Z UpdateTip: new best=0000000000000000001c98592ad5cb91111ed81ac4fa3059259597f336f9fc8d height=505309 version=0x20000000 log2_work=87.925061 tx=294270565 date='2018-01-21T07:58:17Z' progress=0.494582 cache=50.7MiB(42674txo)
1562020-12-30T03:52:37Z UpdateTip: new best=00000000000000000060a317b0a92e5f32a27b8d1ff06f9d339da307dfe5e378 height=505310 version=0x20000000 log2_work=87.925108 tx=294271465 date='2018-01-21T07:58:33Z' progress=0.494583 cache=51.6MiB(49531txo)
1572020-12-30T03:52:42Z UpdateTip: new best=000000000000000000468910a9d7f2bf0d13579dc20ee951dc56dcddf07dc268 height=505311 version=0x20000000 log2_work=87.925155 tx=294272783 date='2018-01-21T08:02:23Z' progress=0.494586 cache=52.4MiB(56549txo)
1582020-12-30T03:52:47Z UpdateTip: new best=00000000000000000040f27142a1e240e73981d7bb3e17b78bd2b2689723cde1 height=505312 version=0x20000000 log2_work=87.925202 tx=294273442 date='2018-01-21T08:03:17Z' progress=0.494587 cache=53.3MiB(63406txo)
1592020-12-30T03:52:50Z UpdateTip: new best=0000000000000000000b6ca764ca69af5678b5de65e901b774d4223db8af789d height=505313 version=0x20000000 log2_work=87.925249 tx=294273697 date='2018-01-21T08:04:22Z' progress=0.494587 cache=53.7MiB(67162txo)
1602020-12-30T03:52:53Z UpdateTip: new best=000000000000000000279d549b0758f9765dc85a2c6dcc52612e57fa2df79cd3 height=505314 version=0x20000000 log2_work=87.925296 tx=294275075 date='2018-01-21T08:14:02Z' progress=0.494589 cache=54.5MiB(73275txo)
1612020-12-30T03:52:58Z UpdateTip: new best=000000000000000000395ed23776a6991df49c00cbbde16fe215090fed035b14 height=505315 version=0x20000000 log2_work=87.925343 tx=294275689 date='2018-01-21T08:18:50Z' progress=0.494590 cache=55.6MiB(82073txo)
1622020-12-30T03:52:59Z UpdateTip: new best=00000000000000000020fb49e6516b796fb2944e3b3f004dcc695939e21db797 height=505316 version=0x20000000 log2_work=87.92539 tx=294277903 date='2018-01-21T08:48:42Z' progress=0.494594 cache=56.4MiB(88983txo)
1632020-12-30T03:53:01Z Pre-allocating up to position 0x200000 in rev01155.dat
1642020-12-30T03:53:01Z UpdateTip: new best=0000000000000000002f43d9a037f26554ad7236be78c36caeabdb07fc439b0f height=505317 version=0x20000000 log2_work=87.925436 tx=294278813 date='2018-01-21T08:49:52Z' progress=0.494596 cache=57.2MiB(95393txo)
1652020-12-30T03:53:06Z UpdateTip: new best=0000000000000000003f6e6d1b864f4577e1cbb8957ff9d70e8fa8f8a692021a height=505318 version=0x20000000 log2_work=87.925483 tx=294279904 date='2018-01-21T08:50:16Z' progress=0.494598 cache=58.2MiB(103701txo)
1662020-12-30T03:53:09Z UpdateTip: new best=00000000000000000075fe4e199a5b870cbc03f2e1f5981bde9fedaabb9c55d0 height=505319 version=0x20000000 log2_work=87.92553 tx=294281062 date='2018-01-21T08:58:07Z' progress=0.494599 cache=59.0MiB(110128txo)
1672020-12-30T03:53:10Z UpdateTip: new best=00000000000000000038ad31c7e64aaeacab7bb76684cd6c0a737ebce6bf0ecf height=505320 version=0x20000000 log2_work=87.925577 tx=294282721 date='2018-01-21T09:16:46Z' progress=0.494602 cache=59.7MiB(116199txo)
1682020-12-30T03:53:13Z UpdateTip: new best=0000000000000000006a44e4e38494d9934ca6c8f18a1e5185e9ee02417c509f height=505321 version=0x20000000 log2_work=87.925624 tx=294284529 date='2018-01-21T09:35:47Z' progress=0.494605 cache=60.5MiB(122676txo)

mzumsande commented at 12:50 pm on January 18, 2022: contributor

I have experienced this too recently on a not very fast connection:

I think the issue is (as partly described above) that when we have exhausted the download window because of a legitimate slow peer that stalls, we disconnect them for stalling and assign the required block to another peer - that peer will get marked as a possible staller almost immediately and has 2 seconds (BLOCK_STALLING_TIMEOUT) to deliver a block or it will get disconnected too.

When our connection is not so fast (so that a block will take more than 2 seconds to arrive) this can lead to several subsequent disconnects.

This will self-correct in many cases where our connection would be fast enough to download a block in 2s in isolation, but not fast enough when simultaneously downloading other blocks from up to 9 other outbound peers - so when the other peers either get disconnected or have sent us all of the blocks assigned to them, it would be possible to catch up again - but this still leads to churn - good and fast peers are being disconnected just because our own connection is not fast enough, which seems not ideal.

As for possible solutions: Just raising BLOCK_STALLING_TIMEOUT moderately might be possible (and might be justified by the increasing physical block sizes after Segwit), but comes at the cost of making IBD slower for high-bandwidth nodes by waiting longer before disconnecting a legitimate staller. Maybe it could make sense to have BLOCK_STALLING_TIMEOUT adjusted dynamically based on past averaged times to download blocks?
jlopp commented at 3:07 pm on January 22, 2022: contributor

I recently spent a lot of time looking into this issue because I’ve noticed my IBD performance drop significantly year over year. While I haven’t found a smoking gun, I do believe there’s room for improvement in this stalling logic.

My findings: https://blog.lopp.net/is-bitcoin-network-slowing-down/

One key takeaway regarding the 2 second timeout: A full block is over 8 megabits of data which means the new peer needs to send it faster than 4 megabits per second. But according to Bitnodes’ peer bandwidth stats, 96% of reachable IPV4 peers are slower than 4 megabits per second! So it’s easy to see how your node could get stuck in a “stalled peer” loop for a minute while it desperately cycles through peers trying to find one that’s faster than 4 Mbps.
maflcko commented at 10:59 am on January 24, 2022: member

To get a stable performance while benchmarking IBD, it might be best to run a dedicated node with ssd on the (local) network and exclusively connect to that one. (-connect=localhost)
achow101 closed this on Jan 27, 2023
sidhujag referenced this in commit bbcf59ea73 on Jan 27, 2023
bitcoin locked this on Jan 27, 2024

Contributors
sdaftuar maflcko rebroad dooglus StopAndDecrypt mzumsande jlopp

Labels
P2P