No new UpdateTip. Just "Pre-allocating up to position ..."

Question

I'm IBD'ing a new testnet node 0.21.0

Why are there long periods of no UpdateTip messages? I have 10 connected peers.

Excerpt starting at 00:13:

2021-04-05T00:13:17Z UpdateTip: new best=000000000000005b0a40663b50cf4588f8dfd9c18bbbe8696fe2b549c893fbe4 height=1382700 ...

Then there are lots of pre-alloc messages and no UpdateTip messages:

2021-04-05T00:36:32Z ping timeout: 1200.048936s
2021-04-05T00:36:55Z New outbound peer connected: version: 70015, blocks=1969990, peer=737 (full-relay)
2021-04-05T00:39:17Z Pre-allocating up to position 0x7000000 in blk00112.dat
2021-04-05T00:43:15Z Pre-allocating up to position 0x8000000 in blk00112.dat
2021-04-05T00:44:59Z Socks5() connect to 165.231.163.24:18333 failed: general failure
2021-04-05T00:46:22Z Leaving block file 112: CBlockFileInfo(blocks=167, size=133222507, heights=1382791...1383090, time=2018-08-10...2018-08-11)
2021-04-05T00:46:22Z Pre-allocating up to position 0x1000000 in blk00113.dat
2021-04-05T00:47:43Z New outbound peer connected: version: 70016, blocks=1969991, peer=738 (full-relay)
2021-04-05T00:47:46Z Synchronizing blockheaders, height: 1969991 (~100.00%)
2021-04-05T00:49:10Z Pre-allocating up to position 0x2000000 in blk00113.dat
2021-04-05T00:50:18Z Socks5() connect to 2001:19f0:6001:3bf2:5400:2ff:febc:2f63:18333 failed: general failure
2021-04-05T00:51:03Z Pre-allocating up to position 0x3000000 in blk00113.dat
2021-04-05T00:51:43Z ping timeout: 1200.026721s
2021-04-05T00:51:44Z ping timeout: 1200.029607s
2021-04-05T00:51:57Z New outbound peer connected: version: 70015, blocks=1969991, peer=740 (block-relay)
2021-04-05T00:52:50Z Pre-allocating up to position 0x100000 in rev00113.dat

After about 40 minutes (why?), there is a new UpdateTip finally:

2021-04-05T00:52:50Z UpdateTip: new best=00000000000000c771e3ffe2108fe02768164469d366e2f48c9e8b4ef7eeae54 height=1382701 version=0x20000000 log2_work=71.161934 tx=28150831 date='2018-08-10T05:40:01Z' progress=0.470404 cache=2824.5MiB(20668057txo)

2021-04-05T00:52:50Z UpdateTip: new best=00000000000000ad0e7806e25ae3628c709cbfd1eb100e8b4aeebf326fc603d9 height=1382702 version=0x20000000 log2_work=71.161974 tx=28152664 date='2018-08-10T05:44:22Z' progress=0.470435 cache=2824.6MiB(20668080txo)

I inspected machine health: Very little io-wait, and cpu is quite idle:

procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 2  0 1523548 477268 133600 5865132    0    0    18    29    4    3  6  0 93  1  0
 4  0 1523548 477836 133600 5866108    0    0     0   580 3894 7616  2  1 91  6  0
 1  2 1523548 477648 133600 5866140    0    0    32   400 3650 6994  2  1 88  9  0
 0  1 1523548 477420 133600 5866140    0    0     0   452 4403 8249  1  2 91  6  0
 1  2 1523548 477696 133600 5866140    0    0     0   700 4414 8394  1  1 92  6  0
 0  1 1523548 477004 133616 5866140    0    0     0  1512 3007 4780  1  1 80 19  0
 2  1 1523548 476420 133616 5866144    0    0     0   460 4536 8690  2  2 92  5  0
 0  1 1523548 475532 133616 5866220    0    0     0   480 4616 9066  1  2 93  4  0
 2  1 1523548 475428 133616 5866220    0    0     0   480 4568 8689  1  2 92  5  0

Quad-core, Intel i7-3740QM CPU @ 2.70GHz. I am using conventional hard disk (platters).

I'm curious what might cause the delay. Reviewed the log and IBD seemed to progress steadily until this time. I searched here and google but could not find an answer.

Update: I thought the multiple pre-alloc messages was a symptom of an issue. But now I'm thinking that's a red herring, and the real issue might have been instability (or other network issue) in the Testnet network at that time. A few hours later, I was seeing a steady pace of UpdateTip messages again.

Answer 1

If you're seeing pre-alloc messages but no UpdateTip messages, it means that you're receiving blocks from peers, but not the next block you need.

Bitcoin Core tries to spread downloading of blocks among multiple peers. However, once a block has been requested, it won't get requested again as long as that request is still outstanding with the peer it's already requested from - until that peer goes offline, or the request times out (at which point the peer is disconnected too).

However, validation requires consecutive blocks, eventually. If we've processed all blocks until number N, we need block number N+1 to continue. It's possible that the request for block N+1 was sent to a non-responsive peer, while other blocks (N+2, N+3, ...) are requested from other peers who are responding. Validation won't proceed until N+1 is received. There are some heuristics to detect such straggling peers and disconnect them (you'd see "Peer X is stalling block download" messages when this happens, I believe), but it's not perfect.