add(log): Log the amount of time it takes to rebuild note commitment trees after a chain fork (#4795)

* Update comments about note commitment tree rebuilds

* Add info-level logs to time note commitment tree rebuilds

* Log the number of rebuilt blocks after a fork, and the time per block

* Move humantime formats to zebra-chain

* Use human-friendly time formatting

Cargo.lock

@@ -6308,6 +6308,7 @@ dependencies = [
  "group",
  "halo2_proofs 0.2.0",
  "hex",
+ "humantime",
  "incrementalmerkletree",
  "itertools",
  "jubjub",

zebra-chain/Cargo.toml

@@ -13,6 +13,8 @@ proptest-impl = ["proptest", "proptest-derive", "zebra-test", "rand", "rand_chac
 bench = ["zebra-test"]
 
 [dependencies]
+
+# Cryptography
 aes = "0.7.5"
 bech32 = "0.9.0"
 bitvec = "1.0.1"
@@ -22,41 +24,54 @@ blake2s_simd = "1.0.0"
 bls12_381 = "0.7.0"
 bs58 = { version = "0.4.0", features = ["check"] }
 byteorder = "1.4.3"
-chrono = { version = "0.4.19", features = ["serde"] }
+equihash = "0.1.0"
-displaydoc = "0.2.3"
 fpe = "0.5.1"
-futures = "0.3.21"
 group = "0.12.0"
-halo2 = { package = "halo2_proofs", version = "0.2.0" }
-hex = { version = "0.4.3", features = ["serde"] }
 incrementalmerkletree = "0.3.0"
-itertools = "0.10.3"
 jubjub = "0.9.0"
 lazy_static = "1.4.0"
 primitive-types = "0.11.1"
 rand_core = "0.6.3"
 ripemd = "0.1.1"
-
-serde = { version = "1.0.137", features = ["serde_derive", "rc"] }
-serde_with = "1.14.0"
-serde-big-array = "0.4.1"
 # Matches version used by hdwallet
 secp256k1 = { version = "0.21.3", features = ["serde"] }
 sha2 = { version = "0.9.9", features=["compress"] }
-static_assertions = "1.1.0"
 subtle = "2.4.1"
-thiserror = "1.0.31"
 uint = "0.9.1"
 x25519-dalek = { version = "1.2.0", features = ["serde"] }
 
+# ECC deps
+halo2 = { package = "halo2_proofs", version = "0.2.0" }
 orchard = "0.2.0"
-
-equihash = "0.1.0"
-zcash_note_encryption = "0.1"
-zcash_primitives = { version = "0.7.0", features = ["transparent-inputs"] }
 zcash_encoding = "0.1.0"
 zcash_history = "0.3.0"
+zcash_note_encryption = "0.1"
+zcash_primitives = { version = "0.7.0", features = ["transparent-inputs"] }
 
+# Time
+chrono = { version = "0.4.19", features = ["serde"] }
+humantime = "2.1.0"
+
+# Error Handling & Formatting
+displaydoc = "0.2.3"
+static_assertions = "1.1.0"
+thiserror = "1.0.31"
+
+# Serialization
+hex = { version = "0.4.3", features = ["serde"] }
+serde = { version = "1.0.137", features = ["serde_derive", "rc"] }
+serde_with = "1.14.0"
+serde-big-array = "0.4.1"
+
+# Processing
+futures = "0.3.21"
+itertools = "0.10.3"
+
+# ZF deps
+ed25519-zebra = "3.0.0"
+redjubjub = "0.5.0"
+
+# Optional testing dependencies
 proptest = { version = "0.10.1", optional = true }
 proptest-derive = { version = "0.3.0", optional = true }
 
@@ -65,19 +80,19 @@ rand_chacha = { version = "0.3.1", optional = true }
 
 tokio = { version = "1.20.0", features = ["tracing"], optional = true }
 
-# ZF deps
-ed25519-zebra = "3.0.0"
-redjubjub = "0.5.0"
-
 zebra-test = { path = "../zebra-test/", optional = true }
 
 [dev-dependencies]
-color-eyre = "0.6.1"
+
+# Benchmarks
 criterion = { version = "0.3.5", features = ["html_reports"] }
-itertools = "0.10.3"
+
+# Error Handling & Formatting
+color-eyre = "0.6.1"
 spandoc = "0.2.2"
 tracing = "0.1.31"
 
+# Make the optional testing dependencies required
 proptest = "0.10.1"
 proptest-derive = "0.3.0"
 

zebra-chain/src/fmt.rs

@@ -7,6 +7,9 @@ use proptest::prelude::*;
 #[cfg(any(test, feature = "proptest-impl"))]
 use proptest_derive::Arbitrary;
 
+pub mod time;
+pub use time::{humantime_milliseconds, humantime_seconds};
+
 /// Wrapper to override `Debug`, redirecting it to only output the type's name.
 #[derive(Copy, Clone, PartialEq, Eq, PartialOrd, Ord, Hash)]
 #[cfg_attr(any(test, feature = "proptest-impl"), derive(Arbitrary))]

zebra-chain/src/fmt/time.rs

@@ -0,0 +1,28 @@
+//! Human-readable formats for times and durations.
+
+use std::time::Duration;
+
+/// Returns a human-friendly formatted string for the whole number of seconds in `duration`.
+pub fn humantime_seconds(duration: impl Into<Duration>) -> String {
+    let duration = duration.into();
+
+    // Truncate fractional seconds.
+    let duration = Duration::from_secs(duration.as_secs());
+
+    let duration = humantime::format_duration(duration);
+
+    format!("{}", duration)
+}
+
+/// Returns a human-friendly formatted string for the whole number of milliseconds in `duration`.
+pub fn humantime_milliseconds(duration: impl Into<Duration>) -> String {
+    let duration = duration.into();
+
+    // Truncate fractional seconds.
+    let duration_secs = Duration::from_secs(duration.as_secs());
+    let duration_millis = Duration::from_millis(duration.subsec_millis().into());
+
+    let duration = humantime::format_duration(duration_secs + duration_millis);
+
+    format!("{}", duration)
+}

zebra-state/src/service/non_finalized_state/chain.rs

@@ -6,6 +6,7 @@ use std::{
     collections::{BTreeMap, BTreeSet, HashMap, HashSet},
     ops::{Deref, RangeInclusive},
     sync::Arc,
+    time::Instant,
 };
 
 use mset::MultiSet;
@@ -14,6 +15,7 @@ use tracing::instrument;
 use zebra_chain::{
     amount::{Amount, NegativeAllowed, NonNegative},
     block::{self, Height},
+    fmt::humantime_milliseconds,
     history_tree::HistoryTree,
     orchard,
     parameters::Network,
@@ -293,11 +295,28 @@ impl Chain {
             forked.pop_tip();
         }
 
+        // Rebuild the note commitment and history trees, starting from the finalized tip tree.
+        //
+        // Note commitments and history trees are not removed from the Chain during a fork,
+        // because we don't support that operation yet. Instead, we recreate the tree
+        // from the finalized tip.
+        //
+        // TODO: remove trees and anchors above the fork, to save CPU time (#4794)
+        let start_time = Instant::now();
+        let rebuilt_block_count = forked.blocks.len();
+        let fork_height = forked.non_finalized_tip_height();
+
+        info!(
+            ?rebuilt_block_count,
+            ?fork_height,
+            ?fork_tip,
+            "starting to rebuild note commitment trees after a non-finalized chain fork",
+        );
+
         let sprout_nct = Arc::make_mut(&mut forked.sprout_note_commitment_tree);
         let sapling_nct = Arc::make_mut(&mut forked.sapling_note_commitment_tree);
         let orchard_nct = Arc::make_mut(&mut forked.orchard_note_commitment_tree);
 
-        // Rebuild the note commitment trees, starting from the finalized tip tree.
         for block in forked.blocks.values() {
             for transaction in block.block.transactions.iter() {
                 for sprout_note_commitment in transaction.sprout_note_commitments() {
@@ -339,6 +358,18 @@ impl Chain {
             )?;
         }
 
+        let rebuild_time = start_time.elapsed();
+        let rebuild_time_per_block =
+            rebuild_time / rebuilt_block_count.try_into().expect("fits in u32");
+        info!(
+            rebuild_time = ?humantime_milliseconds(rebuild_time),
+            rebuild_time_per_block = ?humantime_milliseconds(rebuild_time_per_block),
+            ?rebuilt_block_count,
+            ?fork_height,
+            ?fork_tip,
+            "finished rebuilding note commitment trees after a non-finalized chain fork",
+        );
+
         Ok(Some(forked))
     }
 
@@ -1230,6 +1261,12 @@ impl UpdateWith<Option<transaction::JoinSplitData<Groth16Proof>>> for Chain {
         _position: RevertPosition,
     ) {
         if let Some(joinsplit_data) = joinsplit_data {
+            // Note commitments are not removed from the Chain during a fork,
+            // because we don't support that operation yet. Instead, we
+            // recreate the tree from the finalized tip in Chain::fork().
+            //
+            // TODO: remove trees and anchors above the fork, to save CPU time (#4794)
+
             check::nullifier::remove_from_non_finalized_chain(
                 &mut self.sprout_nullifiers,
                 joinsplit_data.nullifiers(),
@@ -1277,9 +1314,11 @@ where
         _position: RevertPosition,
     ) {
         if let Some(sapling_shielded_data) = sapling_shielded_data {
-            // Note commitments are not removed from the tree here because we
+            // Note commitments are not removed from the Chain during a fork,
-            // don't support that operation yet. Instead, we recreate the tree
+            // because we don't support that operation yet. Instead, we
-            // from the finalized tip in `NonFinalizedState`.
+            // recreate the tree from the finalized tip in Chain::fork().
+            //
+            // TODO: remove trees and anchors above the fork, to save CPU time (#4794)
 
             check::nullifier::remove_from_non_finalized_chain(
                 &mut self.sapling_nullifiers,
@@ -1322,9 +1361,11 @@ impl UpdateWith<Option<orchard::ShieldedData>> for Chain {
         _position: RevertPosition,
     ) {
         if let Some(orchard_shielded_data) = orchard_shielded_data {
-            // Note commitments are not removed from the tree here because we
+            // Note commitments are not removed from the Chain during a fork,
-            // don't support that operation yet. Instead, we recreate the tree
+            // because we don't support that operation yet. Instead, we
-            // from the finalized tip in NonFinalizedState.
+            // recreate the tree from the finalized tip in Chain::fork().
+            //
+            // TODO: remove trees and anchors above the fork, to save CPU time (#4794)
 
             check::nullifier::remove_from_non_finalized_chain(
                 &mut self.orchard_nullifiers,

zebrad/src/components/sync/progress.rs

@@ -8,11 +8,12 @@ use num_integer::div_ceil;
 use zebra_chain::{
     block::Height,
     chain_tip::ChainTip,
+    fmt::humantime_seconds,
     parameters::{Network, NetworkUpgrade, POST_BLOSSOM_POW_TARGET_SPACING},
 };
 use zebra_consensus::CheckpointList;
 
-use crate::components::{sync::SyncStatus, tracing::humantime_seconds};
+use crate::components::sync::SyncStatus;
 
 /// The amount of time between progress logs.
 const LOG_INTERVAL: Duration = Duration::from_secs(60);

zebrad/src/components/tracing.rs

@@ -2,14 +2,12 @@
 
 mod component;
 mod endpoint;
-mod fmt;
 
 #[cfg(feature = "flamegraph")]
 mod flame;
 
 pub use component::Tracing;
 pub use endpoint::TracingEndpoint;
-pub use fmt::humantime_seconds;
 
 #[cfg(feature = "flamegraph")]
 pub use flame::{layer, Grapher};

zebrad/src/components/tracing/fmt.rs

@@ -1,15 +0,0 @@
-//! Formatting for traced values.
-
-use std::time::Duration;
-
-/// Returns a human-friendly formatted string for `duration.as_secs()`.
-pub fn humantime_seconds(duration: impl Into<Duration>) -> String {
-    let duration = duration.into();
-
-    // Truncate fractional seconds.
-    let duration = Duration::from_secs(duration.as_secs());
-
-    let duration = humantime::format_duration(duration);
-
-    format!("{}", duration)
-}