Seemingly second (very long) validation at the same height

hMsats commented at 9:18 am on October 23, 2025: none

Bitcoin Core 30.0

I automatically measure the verification time between “Saw new header” or “Saw new cmpctblock header” and “UpdateTip:” for the same height in debug.log. Almost always that time difference is 0 or 1 second. However, at block 920139 I see a huge spike of 443 seconds. Turns out there is something strange happening for block 920138. Here’s what debug.log reports for this block:

02025-10-21T17:17:37Z Saw new cmpctblock header hash=00000000000000000000a0eb867d25dd2e5284750888c545607d30aecc48c691 height=920138 peer=96259
12025-10-21T17:17:37Z UpdateTip: new best=00000000000000000000a0eb867d25dd2e5284750888c545607d30aecc48c691 height=920138 version=0x28000000 log2_work=95.892695 tx=1259718316 date='2025-10-21T17:17:24Z' progress=1.000000 cache=276.8MiB(2069960txo)
22025-10-21T17:17:37Z Saw new header hash=000000000000000000002e852c1cb8e698df53a4c2646115fbb73d78298b5b2c height=920138 peer=92507
32025-10-21T17:27:00Z UpdateTip: new best=000000000000000000002e852c1cb8e698df53a4c2646115fbb73d78298b5b2c height=920138 version=0x3227a000 log2_work=95.892695 tx=1259718525 date='2025-10-21T17:17:07Z' progress=0.999995 cache=276.8MiB(2071109txo)

So there’s a “Saw new cmpctblock header” and almost immediately the UpdateTip as usual. However, at the same time a “Saw new header” comes in for that same height and now the verification takes almost 10 minutes and progress falls from 1.000000 to 0.999995. This looks to me like a double verification for the same height where the second verification takes much longer. Maybe it has something to do with a reorg, maybe this is normal behavior but I wanted to report it here just to be sure.

Below what happens around height 920138 in debug.log:

 02025-10-21T16:59:13Z Saw new cmpctblock header hash=00000000000000000000f640d1940946015764ddcc37a631d8aebe69301a79d2 height=920135 peer=99563
 12025-10-21T16:59:13Z UpdateTip: new best=00000000000000000000f640d1940946015764ddcc37a631d8aebe69301a79d2 height=920135 version=0x20052000 log2_work=95.892658 tx=1259707764 date='2025-10-21T16:58:20Z' progress=1.000000 cache=276.8MiB(2053530txo)
 22025-10-21T17:00:56Z New block-relay-only v2 peer connected: version: 70016, blocks=920135, peer=160571
 32025-10-21T17:01:43Z Saw new header hash=00000000000000000001317b451e3306a1b62bb0ceb1b81524f90f95c6c95186 height=920136 peer=15656
 42025-10-21T17:01:44Z UpdateTip: new best=00000000000000000001317b451e3306a1b62bb0ceb1b81524f90f95c6c95186 height=920136 version=0x206b6000 log2_work=95.892671 tx=1259710624 date='2025-10-21T17:00:47Z' progress=1.000000 cache=276.8MiB(2057507txo)
 52025-10-21T17:06:52Z New block-relay-only v2 peer connected: version: 70016, blocks=920136, peer=160814
 62025-10-21T17:12:36Z New block-relay-only v2 peer connected: version: 70016, blocks=920136, peer=161247
 72025-10-21T17:14:46Z [net:info] portmap: Added mapping pcp:95.99.132.155:8333 -> 192.168.1.20:8333 (for 2400s)
 82025-10-21T17:14:46Z AddLocal(95.99.132.155:8333,3)
 92025-10-21T17:15:13Z Saw new cmpctblock header hash=000000000000000000004f08e2501645727550d7474400a3fa0ff7013dcd4ea9 height=920137 peer=21
102025-10-21T17:15:13Z UpdateTip: new best=000000000000000000004f08e2501645727550d7474400a3fa0ff7013dcd4ea9 height=920137 version=0x200de000 log2_work=95.892683 tx=1259713766 date='2025-10-21T17:14:48Z' progress=1.000000 cache=276.8MiB(2065321txo)
112025-10-21T17:17:37Z Saw new cmpctblock header hash=00000000000000000000a0eb867d25dd2e5284750888c545607d30aecc48c691 height=920138 peer=96259
122025-10-21T17:17:37Z UpdateTip: new best=00000000000000000000a0eb867d25dd2e5284750888c545607d30aecc48c691 height=920138 version=0x28000000 log2_work=95.892695 tx=1259718316 date='2025-10-21T17:17:24Z' progress=1.000000 cache=276.8MiB(2069960txo)
132025-10-21T17:17:37Z Saw new header hash=000000000000000000002e852c1cb8e698df53a4c2646115fbb73d78298b5b2c height=920138 peer=92507
142025-10-21T17:19:37Z Saw new header hash=0000000000000000000004f6eb492f1e998b569a1940f690d0b691a2f4ba2d00 height=920139 peer=27652
152025-10-21T17:25:54Z Saw new header hash=00000000000000000000c183ce29bb73ddf8e00419ce437bfc58f0abd8d1b161 height=920140 peer=27652
162025-10-21T17:27:00Z UpdateTip: new best=000000000000000000004f08e2501645727550d7474400a3fa0ff7013dcd4ea9 height=920137 version=0x200de000 log2_work=95.892683 tx=1259713766 date='2025-10-21T17:14:48Z' progress=0.999992 cache=276.8MiB(2066586txo)
172025-10-21T17:27:00Z UpdateTip: new best=000000000000000000002e852c1cb8e698df53a4c2646115fbb73d78298b5b2c height=920138 version=0x3227a000 log2_work=95.892695 tx=1259718525 date='2025-10-21T17:17:07Z' progress=0.999995 cache=276.8MiB(2071109txo)
182025-10-21T17:27:00Z UpdateTip: new best=0000000000000000000004f6eb492f1e998b569a1940f690d0b691a2f4ba2d00 height=920139 version=0x202e2000 log2_work=95.892708 tx=1259722731 date='2025-10-21T17:19:29Z' progress=0.999997 cache=277.3MiB(2074876txo)
192025-10-21T17:27:01Z UpdateTip: new best=00000000000000000000c183ce29bb73ddf8e00419ce437bfc58f0abd8d1b161 height=920140 version=0x2c542000 log2_work=95.892720 tx=1259726559 date='2025-10-21T17:25:32Z' progress=1.000000 cache=277.8MiB(2079466txo)
202025-10-21T17:27:01Z txindex is catching up on block notifications
212025-10-21T17:27:01Z txindex is catching up on block notifications
222025-10-21T17:28:03Z Flushed fee estimates to fee_estimates.dat.
232025-10-21T17:32:07Z Saw new header hash=0000000000000000000005d578e2ed197675684b0e9d57e19081b18879179804 height=920141 peer=105484
242025-10-21T17:32:08Z UpdateTip: new best=0000000000000000000005d578e2ed197675684b0e9d57e19081b18879179804 height=920141 version=0x26000000 log2_work=95.892732 tx=1259730043 date='2025-10-21T17:31:56Z' progress=1.000000 cache=277.8MiB(2037404txo)

blckbx commented at 3:35 pm on October 23, 2025: none

Maybe it has something to do with a reorg, maybe this is normal behavior but I wanted to report it here just to be sure.

https://mempool.space/block/00000000000000000000a0eb867d25dd2e5284750888c545607d30aecc48c691

There was a stale block which has been replaced.

hMsats commented at 3:53 pm on October 23, 2025: none

@blckbx great, thanks a lot. But why did the second verification take so long? Is that because all the transactions were removed from the mempool when the first one was verified?

instagibbs commented at 3:57 pm on October 23, 2025: member

@hMsats It appears your peer was unable or unwilling to give the block for about 6 minutes.

Eventually the block was received and processed as usual. Taking a harder look at the scenario to see what we can do to overcome this during reorg scenarios.

fanquake added the label P2P on Oct 24, 2025

hMsats commented at 8:47 am on October 24, 2025: none

@instagibbs I think this problem of a peer unable or unwilling to give a block occasionally happens independent of reorgs, which was just an extreme example. Occasionally (not often) there are spikes which are so much larger than usual (for example: 191 seconds for block 920057 instead of the usual 0 or 1 seconds):

02025-10-21T05:16:07Z Saw new cmpctblock header hash=00000000000000000000d7a021b12e8660fbb5914cab65f17a25e20e3de80e3a height=920057 peer=15656
12025-10-21T05:19:18Z UpdateTip: new best=00000000000000000000d7a021b12e8660fbb5914cab65f17a25e20e3de80e3a height=920057 version=0x20090000 log2_work=95.891694 tx=1259474079 date='2025-10-21T05:15:33Z' progress=1.000000 cache=263.2MiB(1960087txo)

In this case there is no reorg. A general solution would really improve the network in my opinion.

instagibbs commented at 8:58 am on October 24, 2025: member

Typically a warmed-up node will have up to three “high bandwidth” peers who are allowed to hand block data, even if one of them is being slow. During this reorg, it appears likely that all the high bandwidth peers were on the “losing side” of this reorg along with your node, and were unable to help unstuck the node. There is a fallback 10 minute timeout that would have eventually helped if the slow peer doesn’t give you the block in time (you may see “Timeout downloading block” log)

hMsats commented at 3:04 pm on October 25, 2025: none

I’m now running/testing my node (starting cold) with:

0std::chrono::seconds{consensusParams.nPowTargetSpacing}/10 * (BLOCK_DOWNLOAD_TIMEOUT_BASE + BLOCK_DOWNLOAD_TIMEOUT_PER_PEER * nOtherPeersWithValidatedDownloads))

in net_processing.cpp, where I introduced the division by a factor of 10. So based on 1 minute timeout instead of 10 minutes. When my node was warm, I could even base it on a 6 seconds timeout without problems (I’ve tested with 1 second to see if the timeout message was visible in debug.log, and it was).

This value of 10 is a bit extreme but my gut feeling is that a factor of 5 (2 minute timeout) would still be conservative these days and a factor of 2 (5 minute timeout) would at least be an improvement.

Of course, more sophisticated solutions are possible.

I will report back whether I see any timeouts for a 1 minute timeout starting cold (meaning I removed anchors.dat, banlist.json, fee_estimates.dat, mempool.dat, peers.dat)

hMsats commented at 2:59 pm on October 27, 2025: none

After more than 48 hours, not a single timeout for a division by 10 (based on 1 minute or 600/10=60 seconds) and a cold start. For height, verification time, time and date and peer see here.

mzumsande commented at 4:08 pm on October 27, 2025: contributor

One reason why we haven’t simply lowered the timeout from 10 minutes is to not change the minimum required bandwidth to keep up with the network. In principle, a synced -blocksonly node with a bandwith so slow that they can only download ~2-4MB every 10minutes should be able to keep up with the tip today. If we changed the timeout, the minimum required bandwidth would change. I also encountered this argument in #29664 (which is a slightly different scenario than the reorg here).

In my opinion, this is more of an ideological than a practical argument though, and it is becoming increasingly unrealistic for the huge majority of cases. Maybe it could make sense to both lower the default, and make it possible to provide the timeout as a startup option, so that nodes on normal connections don’t run into this, while extremely slow nodes still have an option to sync.

Seemingly second (very long) validation at the same height #33687