diff --git a/prdoc/pr_5103.prdoc b/prdoc/pr_5103.prdoc new file mode 100644 index 000000000000..b0f72bf531f1 --- /dev/null +++ b/prdoc/pr_5103.prdoc @@ -0,0 +1,18 @@ +title: Skip genesis leaf to unblock syncing + +doc: + - audience: + - Node Operator + - Node Dev + description: | + This PR skips over the genesis block reported as leaf when calculating displaced branches. + In those cases, when the genesis block is reported as leaf, the node would compute the path + from the current finalized block to the genesis block. This operation is time consuming and + is enough to block syncing. In the current state, the genesis block is assumed to always be + part of the finalized chain. + +crates: +- name: sc-client-db + bump: none +- name: sp-blockchain + bump: patch diff --git a/substrate/client/db/src/lib.rs b/substrate/client/db/src/lib.rs index acd165d91613..ba0cbc09d53d 100644 --- a/substrate/client/db/src/lib.rs +++ b/substrate/client/db/src/lib.rs @@ -3169,7 +3169,7 @@ pub(crate) mod tests { let displaced = blockchain.displaced_leaves_after_finalizing(a3_hash, a3_number).unwrap(); assert_eq!(blockchain.leaves().unwrap(), vec![a4_hash, genesis_hash]); - assert_eq!(displaced.displaced_leaves, vec![]); + assert_eq!(displaced.displaced_leaves, vec![(genesis_number, genesis_hash)]); assert_eq!(displaced.displaced_blocks, vec![]); } @@ -3177,7 +3177,7 @@ pub(crate) mod tests { let displaced = blockchain.displaced_leaves_after_finalizing(a4_hash, a4_number).unwrap(); assert_eq!(blockchain.leaves().unwrap(), vec![a4_hash, genesis_hash]); - assert_eq!(displaced.displaced_leaves, vec![]); + assert_eq!(displaced.displaced_leaves, vec![(genesis_number, genesis_hash)]); assert_eq!(displaced.displaced_blocks, vec![]); } diff --git a/substrate/primitives/blockchain/src/backend.rs b/substrate/primitives/blockchain/src/backend.rs index 2accd4dad12c..fd0c5795cbfd 100644 --- a/substrate/primitives/blockchain/src/backend.rs +++ b/substrate/primitives/blockchain/src/backend.rs @@ -255,10 +255,11 @@ pub trait Backend: ) -> std::result::Result, Error> { let leaves = self.leaves()?; + let now = std::time::Instant::now(); debug!( target: crate::LOG_TARGET, ?leaves, - %finalized_block_hash, + ?finalized_block_hash, ?finalized_block_number, "Checking for displaced leaves after finalization." ); @@ -277,11 +278,21 @@ pub trait Backend: debug!( target: crate::LOG_TARGET, hash = ?finalized_block_hash, - "Tried to fetch unknown block, block ancestry has gaps." + elapsed = ?now.elapsed(), + "Tried to fetch unknown block, block ancestry has gaps.", ); return Ok(DisplacedLeavesAfterFinalization::default()); }, - Err(e) => Err(e)?, + Err(e) => { + debug!( + target: crate::LOG_TARGET, + hash = ?finalized_block_hash, + err = ?e, + elapsed = ?now.elapsed(), + "Failed to fetch block.", + ); + return Err(e); + }, }; finalized_chain.push_front(MinimalBlockMetadata::from(¤t_finalized)); @@ -296,11 +307,42 @@ pub trait Backend: let mut displaced_blocks_candidates = Vec::new(); + let genesis_hash = self.info().genesis_hash; + for leaf_hash in leaves { let mut current_header_metadata = - MinimalBlockMetadata::from(&self.header_metadata(leaf_hash)?); + MinimalBlockMetadata::from(&self.header_metadata(leaf_hash).map_err(|err| { + debug!( + target: crate::LOG_TARGET, + ?leaf_hash, + ?err, + elapsed = ?now.elapsed(), + "Failed to fetch leaf header.", + ); + err + })?); let leaf_number = current_header_metadata.number; + // The genesis block is part of the canonical chain. + if leaf_hash == genesis_hash { + result.displaced_leaves.push((leaf_number, leaf_hash)); + debug!( + target: crate::LOG_TARGET, + ?leaf_hash, + elapsed = ?now.elapsed(), + "Added genesis leaf to displaced leaves." + ); + continue + } + + debug!( + target: crate::LOG_TARGET, + ?leaf_number, + ?leaf_hash, + elapsed = ?now.elapsed(), + "Handle displaced leaf.", + ); + // Collect all block hashes until the height of the finalized block displaced_blocks_candidates.clear(); while current_header_metadata.number > finalized_block_number { @@ -312,8 +354,20 @@ pub trait Backend: current_header_metadata = *metadata_header; }, None => { - current_header_metadata = - MinimalBlockMetadata::from(&self.header_metadata(parent_hash)?); + current_header_metadata = MinimalBlockMetadata::from( + &self.header_metadata(parent_hash).map_err(|err| { + debug!( + target: crate::LOG_TARGET, + ?err, + ?parent_hash, + ?leaf_hash, + elapsed = ?now.elapsed(), + "Failed to fetch parent header during leaf tracking.", + ); + + err + })?, + ); // Cache locally in case more branches above finalized block reference // the same block hash local_cache.insert(parent_hash, current_header_metadata); @@ -324,6 +378,13 @@ pub trait Backend: // If points back to the finalized header then nothing left to do, this leaf will be // checked again later if current_header_metadata.hash == finalized_block_hash { + debug!( + target: crate::LOG_TARGET, + ?leaf_hash, + elapsed = ?now.elapsed(), + "Leaf points to the finalized header, skipping for now.", + ); + continue; } @@ -332,6 +393,15 @@ pub trait Backend: // check for this gap later. displaced_blocks_candidates.push(current_header_metadata.hash); + debug!( + target: crate::LOG_TARGET, + current_hash = ?current_header_metadata.hash, + current_num = ?current_header_metadata.number, + ?finalized_block_number, + elapsed = ?now.elapsed(), + "Looking for path from finalized block number to current leaf number" + ); + // Collect the rest of the displaced blocks of leaf branch for distance_from_finalized in 1_u32.. { // Find block at `distance_from_finalized` from finalized block @@ -348,11 +418,22 @@ pub trait Backend: distance_from_finalized, hash = ?to_fetch.parent, number = ?to_fetch.number, + elapsed = ?now.elapsed(), "Tried to fetch unknown block, block ancestry has gaps." ); break; }, - Err(e) => Err(e)?, + Err(err) => { + debug!( + target: crate::LOG_TARGET, + hash = ?to_fetch.parent, + number = ?to_fetch.number, + ?err, + elapsed = ?now.elapsed(), + "Failed to fetch header for parent hash.", + ); + return Err(err); + }, }; let metadata = MinimalBlockMetadata::from(&metadata); let result = (metadata.number, metadata.hash); @@ -361,6 +442,19 @@ pub trait Backend: }, }; + if current_header_metadata.hash == finalized_chain_block_hash { + // Found the block on the finalized chain, nothing left to do + result.displaced_leaves.push((leaf_number, leaf_hash)); + + debug!( + target: crate::LOG_TARGET, + ?leaf_hash, + elapsed = ?now.elapsed(), + "Leaf is ancestor of finalized block." + ); + break; + } + if current_header_metadata.number <= finalized_chain_block_number { // Skip more blocks until we get all blocks on finalized chain until the height // of the parent block @@ -372,13 +466,36 @@ pub trait Backend: // Reached finalized chain, nothing left to do result.displaced_blocks.extend(displaced_blocks_candidates.drain(..)); result.displaced_leaves.push((leaf_number, leaf_hash)); + + debug!( + target: crate::LOG_TARGET, + ?leaf_hash, + elapsed = ?now.elapsed(), + "Found displaced leaf." + ); break; } // Store displaced block and look deeper for block on finalized chain + debug!( + target: crate::LOG_TARGET, + ?parent_hash, + elapsed = ?now.elapsed(), + "Found displaced block. Looking further.", + ); displaced_blocks_candidates.push(parent_hash); - current_header_metadata = - MinimalBlockMetadata::from(&self.header_metadata(parent_hash)?); + current_header_metadata = MinimalBlockMetadata::from( + &self.header_metadata(parent_hash).map_err(|err| { + debug!( + target: crate::LOG_TARGET, + ?err, + ?parent_hash, + elapsed = ?now.elapsed(), + "Failed to fetch header for parent during displaced block collection", + ); + err + })?, + ); } } @@ -386,6 +503,15 @@ pub trait Backend: result.displaced_blocks.sort_unstable(); result.displaced_blocks.dedup(); + debug!( + target: crate::LOG_TARGET, + %finalized_block_hash, + ?finalized_block_number, + ?result, + elapsed = ?now.elapsed(), + "Finished checking for displaced leaves after finalization.", + ); + return Ok(result); } } diff --git a/substrate/zombienet/0001-basic-warp-sync/test-warp-sync.toml b/substrate/zombienet/0001-basic-warp-sync/test-warp-sync.toml index f4586ba69d00..d40da6d64370 100644 --- a/substrate/zombienet/0001-basic-warp-sync/test-warp-sync.toml +++ b/substrate/zombienet/0001-basic-warp-sync/test-warp-sync.toml @@ -27,4 +27,4 @@ chain_spec_path = "chain-spec.json" [[relaychain.nodes]] name = "dave" validator = false - args = ["--sync warp"] + args = ["--sync warp -ldb::blockchain"] diff --git a/substrate/zombienet/0001-basic-warp-sync/test-warp-sync.zndsl b/substrate/zombienet/0001-basic-warp-sync/test-warp-sync.zndsl index c5644797321e..26c9fac60735 100644 --- a/substrate/zombienet/0001-basic-warp-sync/test-warp-sync.zndsl +++ b/substrate/zombienet/0001-basic-warp-sync/test-warp-sync.zndsl @@ -22,6 +22,7 @@ dave: reports block height is at least 1 within 60 seconds dave: reports block height is at least {{DB_BLOCK_HEIGHT}} within 60 seconds dave: log line matches "Warp sync is complete" within 60 seconds +dave: log line matches "Checking for displaced leaves after finalization\. leaves\=\[0xc5e7b4cfd23932bb930e859865430a35f6741b4732d677822d492ca64cc8d059\]" within 10 seconds # State sync is logically part of warp sync dave: log line matches "State sync is complete" within 60 seconds dave: log line matches "Block history download is complete" within 10 seconds