Skip to content

Commit 1fc7a81

Browse files
l0rincajtownsvasild
committed
log: reduce excessive messages during block replay
After an incomplete reindex the blocks will need to be replayed. This results in excessive `Rolling back` and `Rolling forward` messages which quickly triggers the recently introduced log rate limiter. Change the logging strategy to: - Add single `LogInfo` messages showing the full range being replayed for both rollback and roll forward; - Log progress at `LogInfo` level only every 10,000 blocks to track the long operations. Reproducer: * Start a normal IBD, stop after some progress * Do a reindex, stop before it finishes * Restart the node normally without specifying the reindex parameter It should start rolling the blocks forward. Before this change the excessive logging would show: ``` [*] Rolling forward 000000002f4f55aecfccc911076dc3f73ac0288c83dc1d79db0a026441031d40 (46245) [*] Rolling forward 0000000017ffcf34c8eac010c529670ba6745ea59cf1edf7b820928e3b40acf6 (46246) ``` After the change it shows: ``` Replaying blocks Rolling forward to 00000000000000001034012d7e4facaf16ca747ea94b8ea66743086cfe298ef8 (326223 to 340991) Rolling forward 00000000000000000faabab19f17c0178c754dbed023e6c871dcaf74159c5f02 (330000) Rolling forward 00000000000000000d9b2508615d569e18f00c034d71474fc44a43af8d4a5003 (340000) ... Rolled forward to 00000000000000001034012d7e4facaf16ca747ea94b8ea66743086cfe298ef8 ``` (similarly to rolling back) Co-authored-by: Anthony Towns <[email protected]> Co-authored-by: Vasil Dimov <[email protected]>
1 parent d41b503 commit 1fc7a81

File tree

1 file changed

+35
-23
lines changed

1 file changed

+35
-23
lines changed

src/validation.cpp

Lines changed: 35 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -4889,35 +4889,47 @@ bool Chainstate::ReplayBlocks()
48894889
}
48904890

48914891
// Rollback along the old branch.
4892-
while (pindexOld != pindexFork) {
4893-
if (pindexOld->nHeight > 0) { // Never disconnect the genesis block.
4894-
CBlock block;
4895-
if (!m_blockman.ReadBlock(block, *pindexOld)) {
4896-
LogError("RollbackBlock(): ReadBlock() failed at %d, hash=%s\n", pindexOld->nHeight, pindexOld->GetBlockHash().ToString());
4897-
return false;
4898-
}
4899-
LogInfo("Rolling back %s (%i)", pindexOld->GetBlockHash().ToString(), pindexOld->nHeight);
4900-
DisconnectResult res = DisconnectBlock(block, pindexOld, cache);
4901-
if (res == DISCONNECT_FAILED) {
4902-
LogError("RollbackBlock(): DisconnectBlock failed at %d, hash=%s\n", pindexOld->nHeight, pindexOld->GetBlockHash().ToString());
4903-
return false;
4892+
const int nForkHeight{pindexFork ? pindexFork->nHeight : 0};
4893+
if (pindexOld != pindexFork) {
4894+
LogInfo("Rolling back from %s (%i to %i)", pindexOld->GetBlockHash().ToString(), pindexOld->nHeight, nForkHeight);
4895+
while (pindexOld != pindexFork) {
4896+
if (pindexOld->nHeight > 0) { // Never disconnect the genesis block.
4897+
CBlock block;
4898+
if (!m_blockman.ReadBlock(block, *pindexOld)) {
4899+
LogError("RollbackBlock(): ReadBlock() failed at %d, hash=%s\n", pindexOld->nHeight, pindexOld->GetBlockHash().ToString());
4900+
return false;
4901+
}
4902+
if (pindexOld->nHeight % 10'000 == 0) {
4903+
LogInfo("Rolling back %s (%i)", pindexOld->GetBlockHash().ToString(), pindexOld->nHeight);
4904+
}
4905+
DisconnectResult res = DisconnectBlock(block, pindexOld, cache);
4906+
if (res == DISCONNECT_FAILED) {
4907+
LogError("RollbackBlock(): DisconnectBlock failed at %d, hash=%s\n", pindexOld->nHeight, pindexOld->GetBlockHash().ToString());
4908+
return false;
4909+
}
4910+
// If DISCONNECT_UNCLEAN is returned, it means a non-existing UTXO was deleted, or an existing UTXO was
4911+
// overwritten. It corresponds to cases where the block-to-be-disconnect never had all its operations
4912+
// applied to the UTXO set. However, as both writing a UTXO and deleting a UTXO are idempotent operations,
4913+
// the result is still a version of the UTXO set with the effects of that block undone.
49044914
}
4905-
// If DISCONNECT_UNCLEAN is returned, it means a non-existing UTXO was deleted, or an existing UTXO was
4906-
// overwritten. It corresponds to cases where the block-to-be-disconnect never had all its operations
4907-
// applied to the UTXO set. However, as both writing a UTXO and deleting a UTXO are idempotent operations,
4908-
// the result is still a version of the UTXO set with the effects of that block undone.
4915+
pindexOld = pindexOld->pprev;
49094916
}
4910-
pindexOld = pindexOld->pprev;
4917+
LogInfo("Rolled back to %s", pindexFork->GetBlockHash().ToString());
49114918
}
49124919

49134920
// Roll forward from the forking point to the new tip.
4914-
int nForkHeight = pindexFork ? pindexFork->nHeight : 0;
4915-
for (int nHeight = nForkHeight + 1; nHeight <= pindexNew->nHeight; ++nHeight) {
4916-
const CBlockIndex& pindex{*Assert(pindexNew->GetAncestor(nHeight))};
4921+
if (nForkHeight < pindexNew->nHeight) {
4922+
LogInfo("Rolling forward to %s (%i to %i)", pindexNew->GetBlockHash().ToString(), nForkHeight, pindexNew->nHeight);
4923+
for (int nHeight = nForkHeight + 1; nHeight <= pindexNew->nHeight; ++nHeight) {
4924+
const CBlockIndex& pindex{*Assert(pindexNew->GetAncestor(nHeight))};
49174925

4918-
LogInfo("Rolling forward %s (%i)", pindex.GetBlockHash().ToString(), nHeight);
4919-
m_chainman.GetNotifications().progress(_("Replaying blocks…"), (int)((nHeight - nForkHeight) * 100.0 / (pindexNew->nHeight - nForkHeight)), false);
4920-
if (!RollforwardBlock(&pindex, cache)) return false;
4926+
if (nHeight % 10'000 == 0) {
4927+
LogInfo("Rolling forward %s (%i)", pindex.GetBlockHash().ToString(), nHeight);
4928+
}
4929+
m_chainman.GetNotifications().progress(_("Replaying blocks…"), (int)((nHeight - nForkHeight) * 100.0 / (pindexNew->nHeight - nForkHeight)), false);
4930+
if (!RollforwardBlock(&pindex, cache)) return false;
4931+
}
4932+
LogInfo("Rolled forward to %s", pindexNew->GetBlockHash().ToString());
49214933
}
49224934

49234935
cache.SetBestBlock(pindexNew->GetBlockHash());

0 commit comments

Comments
 (0)