From a07e567fe11e4e94e268606c7e92b1672b2f5fdf Mon Sep 17 00:00:00 2001 From: Arkadiy Paronyan Date: Tue, 17 Sep 2019 20:42:15 +0200 Subject: [PATCH] Storage tracing (#3614) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * Storage tracing * Whitepsaces Co-Authored-By: Sergei Pepyakin * Apply suggestions from code review Co-Authored-By: Bastian Köcher * Update Cargo.lock --- substrate/Cargo.lock | 25 +-- substrate/core/client/db/src/lib.rs | 6 + substrate/core/client/db/src/storage_cache.rs | 6 + substrate/core/client/src/light/backend.rs | 9 + substrate/core/primitives/src/hexdisplay.rs | 21 ++- substrate/core/primitives/src/lib.rs | 2 +- substrate/core/state-machine/Cargo.toml | 1 + substrate/core/state-machine/src/backend.rs | 8 +- substrate/core/state-machine/src/ext.rs | 159 +++++++++++++++--- substrate/core/state-machine/src/lib.rs | 15 +- .../core/state-machine/src/proving_backend.rs | 6 + .../core/state-machine/src/trie_backend.rs | 6 + 12 files changed, 223 insertions(+), 41 deletions(-) diff --git a/substrate/Cargo.lock b/substrate/Cargo.lock index 68a2e1bf41..4ae6d38280 100644 --- a/substrate/Cargo.lock +++ b/substrate/Cargo.lock @@ -473,7 +473,7 @@ version = "0.1.6" source = "registry+https://github.com/rust-lang/crates.io-index" dependencies = [ "proc-macro-hack 0.5.8 (registry+https://github.com/rust-lang/crates.io-index)", - "rand 0.7.0 (registry+https://github.com/rust-lang/crates.io-index)", + "rand 0.7.2 (registry+https://github.com/rust-lang/crates.io-index)", ] [[package]] @@ -3188,13 +3188,13 @@ dependencies = [ [[package]] name = "rand" -version = "0.7.0" +version = "0.7.2" source = "registry+https://github.com/rust-lang/crates.io-index" dependencies = [ "getrandom 0.1.6 (registry+https://github.com/rust-lang/crates.io-index)", "libc 0.2.60 (registry+https://github.com/rust-lang/crates.io-index)", "rand_chacha 0.2.1 (registry+https://github.com/rust-lang/crates.io-index)", - "rand_core 0.5.0 (registry+https://github.com/rust-lang/crates.io-index)", + "rand_core 0.5.1 (registry+https://github.com/rust-lang/crates.io-index)", "rand_hc 0.2.0 (registry+https://github.com/rust-lang/crates.io-index)", ] @@ -3213,7 +3213,7 @@ version = "0.2.1" source = "registry+https://github.com/rust-lang/crates.io-index" dependencies = [ "c2-chacha 0.2.2 (registry+https://github.com/rust-lang/crates.io-index)", - "rand_core 0.5.0 (registry+https://github.com/rust-lang/crates.io-index)", + "rand_core 0.5.1 (registry+https://github.com/rust-lang/crates.io-index)", ] [[package]] @@ -3231,7 +3231,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" [[package]] name = "rand_core" -version = "0.5.0" +version = "0.5.1" source = "registry+https://github.com/rust-lang/crates.io-index" dependencies = [ "getrandom 0.1.6 (registry+https://github.com/rust-lang/crates.io-index)", @@ -3250,7 +3250,7 @@ name = "rand_hc" version = "0.2.0" source = "registry+https://github.com/rust-lang/crates.io-index" dependencies = [ - "rand_core 0.5.0 (registry+https://github.com/rust-lang/crates.io-index)", + "rand_core 0.5.1 (registry+https://github.com/rust-lang/crates.io-index)", ] [[package]] @@ -3840,7 +3840,7 @@ dependencies = [ "parity-scale-codec 1.0.5 (registry+https://github.com/rust-lang/crates.io-index)", "paste 0.1.5 (registry+https://github.com/rust-lang/crates.io-index)", "primitive-types 0.5.0 (registry+https://github.com/rust-lang/crates.io-index)", - "rand 0.7.0 (registry+https://github.com/rust-lang/crates.io-index)", + "rand 0.7.2 (registry+https://github.com/rust-lang/crates.io-index)", "serde 1.0.97 (registry+https://github.com/rust-lang/crates.io-index)", "serde_json 1.0.40 (registry+https://github.com/rust-lang/crates.io-index)", "sr-io 2.0.0", @@ -5054,7 +5054,7 @@ dependencies = [ "log 0.4.7 (registry+https://github.com/rust-lang/crates.io-index)", "parity-scale-codec 1.0.5 (registry+https://github.com/rust-lang/crates.io-index)", "parking_lot 0.9.0 (registry+https://github.com/rust-lang/crates.io-index)", - "rand 0.7.0 (registry+https://github.com/rust-lang/crates.io-index)", + "rand 0.7.2 (registry+https://github.com/rust-lang/crates.io-index)", "sr-primitives 2.0.0", "substrate-client 2.0.0", "substrate-client-db 2.0.0", @@ -5100,7 +5100,7 @@ dependencies = [ name = "substrate-phragmen" version = "2.0.0" dependencies = [ - "rand 0.7.0 (registry+https://github.com/rust-lang/crates.io-index)", + "rand 0.7.2 (registry+https://github.com/rust-lang/crates.io-index)", "sr-io 2.0.0", "sr-primitives 2.0.0", "sr-std 2.0.0", @@ -5333,6 +5333,7 @@ dependencies = [ "num-traits 0.2.8 (registry+https://github.com/rust-lang/crates.io-index)", "parity-scale-codec 1.0.5 (registry+https://github.com/rust-lang/crates.io-index)", "parking_lot 0.9.0 (registry+https://github.com/rust-lang/crates.io-index)", + "rand 0.7.2 (registry+https://github.com/rust-lang/crates.io-index)", "substrate-panic-handler 2.0.0", "substrate-primitives 2.0.0", "substrate-trie 2.0.0", @@ -5582,7 +5583,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" dependencies = [ "cfg-if 0.1.9 (registry+https://github.com/rust-lang/crates.io-index)", "libc 0.2.60 (registry+https://github.com/rust-lang/crates.io-index)", - "rand 0.7.0 (registry+https://github.com/rust-lang/crates.io-index)", + "rand 0.7.2 (registry+https://github.com/rust-lang/crates.io-index)", "redox_syscall 0.1.56 (registry+https://github.com/rust-lang/crates.io-index)", "remove_dir_all 0.5.2 (registry+https://github.com/rust-lang/crates.io-index)", "winapi 0.3.7 (registry+https://github.com/rust-lang/crates.io-index)", @@ -6769,12 +6770,12 @@ dependencies = [ "checksum rand 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)" = "552840b97013b1a26992c11eac34bdd778e464601a4c2054b5f0bff7c6761293" "checksum rand 0.5.6 (registry+https://github.com/rust-lang/crates.io-index)" = "c618c47cd3ebd209790115ab837de41425723956ad3ce2e6a7f09890947cacb9" "checksum rand 0.6.5 (registry+https://github.com/rust-lang/crates.io-index)" = "6d71dacdc3c88c1fde3885a3be3fbab9f35724e6ce99467f7d9c5026132184ca" -"checksum rand 0.7.0 (registry+https://github.com/rust-lang/crates.io-index)" = "d47eab0e83d9693d40f825f86948aa16eff6750ead4bdffc4ab95b8b3a7f052c" +"checksum rand 0.7.2 (registry+https://github.com/rust-lang/crates.io-index)" = "3ae1b169243eaf61759b8475a998f0a385e42042370f3a7dbaf35246eacc8412" "checksum rand_chacha 0.1.1 (registry+https://github.com/rust-lang/crates.io-index)" = "556d3a1ca6600bfcbab7c7c91ccb085ac7fbbcd70e008a98742e7847f4f7bcef" "checksum rand_chacha 0.2.1 (registry+https://github.com/rust-lang/crates.io-index)" = "03a2a90da8c7523f554344f921aa97283eadf6ac484a6d2a7d0212fa7f8d6853" "checksum rand_core 0.3.1 (registry+https://github.com/rust-lang/crates.io-index)" = "7a6fdeb83b075e8266dcc8762c22776f6877a63111121f5f8c7411e5be7eed4b" "checksum rand_core 0.4.0 (registry+https://github.com/rust-lang/crates.io-index)" = "d0e7a549d590831370895ab7ba4ea0c1b6b011d106b5ff2da6eee112615e6dc0" -"checksum rand_core 0.5.0 (registry+https://github.com/rust-lang/crates.io-index)" = "615e683324e75af5d43d8f7a39ffe3ee4a9dc42c5c701167a71dc59c3a493aca" +"checksum rand_core 0.5.1 (registry+https://github.com/rust-lang/crates.io-index)" = "90bde5296fc891b0cef12a6d03ddccc162ce7b2aff54160af9338f8d40df6d19" "checksum rand_hc 0.1.0 (registry+https://github.com/rust-lang/crates.io-index)" = "7b40677c7be09ae76218dc623efbf7b18e34bced3f38883af07bb75630a21bc4" "checksum rand_hc 0.2.0 (registry+https://github.com/rust-lang/crates.io-index)" = "ca3129af7b92a17112d59ad498c6f81eaf463253766b90396d39ea7a39d6613c" "checksum rand_isaac 0.1.1 (registry+https://github.com/rust-lang/crates.io-index)" = "ded997c9d5f13925be2a6fd7e66bf1872597f759fd9dd93513dd7e92e5a5ee08" diff --git a/substrate/core/client/db/src/lib.rs b/substrate/core/client/db/src/lib.rs index 4acb178506..1a0b2331d3 100644 --- a/substrate/core/client/db/src/lib.rs +++ b/substrate/core/client/db/src/lib.rs @@ -110,6 +110,12 @@ impl Drop for RefTrackingState { } } +impl std::fmt::Debug for RefTrackingState { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!(f, "Block {:?}", self.parent_hash) + } +} + impl StateBackend for RefTrackingState { type Error = >::Error; type Transaction = >::Transaction; diff --git a/substrate/core/client/db/src/storage_cache.rs b/substrate/core/client/db/src/storage_cache.rs index 09c0f71fdd..af8c9e379c 100644 --- a/substrate/core/client/db/src/storage_cache.rs +++ b/substrate/core/client/db/src/storage_cache.rs @@ -285,6 +285,12 @@ pub struct CachingState, B: BlockT> { pub cache: CacheChanges } +impl, B: BlockT> std::fmt::Debug for CachingState { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!(f, "Block {:?}", self.cache.parent_hash) + } +} + impl CacheChanges { /// Propagate local cache into the shared cache and synchronize /// the shared cache with the best block state. diff --git a/substrate/core/client/src/light/backend.rs b/substrate/core/client/src/light/backend.rs index 336e4cba70..5f44c03e21 100644 --- a/substrate/core/client/src/light/backend.rs +++ b/substrate/core/client/src/light/backend.rs @@ -325,6 +325,15 @@ where } } +impl std::fmt::Debug for GenesisOrUnavailableState { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + match *self { + GenesisOrUnavailableState::Genesis(ref state) => state.fmt(f), + GenesisOrUnavailableState::Unavailable => write!(f, "Unavailable"), + } + } +} + impl StateBackend for GenesisOrUnavailableState where H::Out: Ord, diff --git a/substrate/core/primitives/src/hexdisplay.rs b/substrate/core/primitives/src/hexdisplay.rs index cd2b6c18cb..87be587a7d 100644 --- a/substrate/core/primitives/src/hexdisplay.rs +++ b/substrate/core/primitives/src/hexdisplay.rs @@ -21,28 +21,37 @@ pub struct HexDisplay<'a>(&'a [u8]); impl<'a> HexDisplay<'a> { /// Create new instance that will display `d` as a hex string when displayed. - pub fn from(d: &'a dyn AsBytesRef) -> Self { HexDisplay(d.as_bytes_ref()) } + pub fn from(d: &'a R) -> Self { HexDisplay(d.as_bytes_ref()) } } impl<'a> ::core::fmt::Display for HexDisplay<'a> { - fn fmt(&self, fmtr: &mut ::core::fmt::Formatter) -> Result<(), ::core::fmt::Error> { + fn fmt(&self, f: &mut core::fmt::Formatter) -> Result<(), core::fmt::Error> { if self.0.len() < 1027 { for byte in self.0 { - fmtr.write_fmt(format_args!("{:02x}", byte))?; + f.write_fmt(format_args!("{:02x}", byte))?; } } else { for byte in &self.0[0..512] { - fmtr.write_fmt(format_args!("{:02x}", byte))?; + f.write_fmt(format_args!("{:02x}", byte))?; } - fmtr.write_str("...")?; + f.write_str("...")?; for byte in &self.0[self.0.len() - 512..] { - fmtr.write_fmt(format_args!("{:02x}", byte))?; + f.write_fmt(format_args!("{:02x}", byte))?; } } Ok(()) } } +impl<'a> core::fmt::Debug for HexDisplay<'a> { + fn fmt(&self, f: &mut core::fmt::Formatter) -> Result<(), core::fmt::Error> { + for byte in self.0 { + f.write_fmt(format_args!("{:02x}", byte))?; + } + Ok(()) + } +} + /// Simple trait to transform various types to `&[u8]` pub trait AsBytesRef { /// Transform `self` into `&[u8]`. diff --git a/substrate/core/primitives/src/lib.rs b/substrate/core/primitives/src/lib.rs index 144aa7b997..8086c9832a 100644 --- a/substrate/core/primitives/src/lib.rs +++ b/substrate/core/primitives/src/lib.rs @@ -159,7 +159,7 @@ pub enum NativeOrEncoded { #[cfg(feature = "std")] impl ::std::fmt::Debug for NativeOrEncoded { fn fmt(&self, f: &mut ::std::fmt::Formatter) -> ::std::fmt::Result { - self.as_encoded().as_ref().fmt(f) + hexdisplay::HexDisplay::from(&self.as_encoded().as_ref()).fmt(f) } } diff --git a/substrate/core/state-machine/Cargo.toml b/substrate/core/state-machine/Cargo.toml index 94aff8b078..d9fb592bab 100644 --- a/substrate/core/state-machine/Cargo.toml +++ b/substrate/core/state-machine/Cargo.toml @@ -16,6 +16,7 @@ primitives = { package = "substrate-primitives", path = "../primitives" } panic-handler = { package = "substrate-panic-handler", path = "../panic-handler" } codec = { package = "parity-scale-codec", version = "1.0.0" } num-traits = "0.2" +rand = "0.7.1" [dev-dependencies] hex-literal = "0.2.0" diff --git a/substrate/core/state-machine/src/backend.rs b/substrate/core/state-machine/src/backend.rs index 86d415de1c..e2f398ef7c 100644 --- a/substrate/core/state-machine/src/backend.rs +++ b/substrate/core/state-machine/src/backend.rs @@ -30,7 +30,7 @@ use trie::{ /// to it. /// /// The clone operation (if implemented) should be cheap. -pub trait Backend { +pub trait Backend: std::fmt::Debug { /// An error type when fetching data is not possible. type Error: super::Error; @@ -254,6 +254,12 @@ pub struct InMemory { _hasher: PhantomData, } +impl std::fmt::Debug for InMemory { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + write!(f, "InMemory ({} values)", self.inner.len()) + } +} + impl Default for InMemory { fn default() -> Self { InMemory { diff --git a/substrate/core/state-machine/src/ext.rs b/substrate/core/state-machine/src/ext.rs index 6ce5b12085..c4a2bd7f63 100644 --- a/substrate/core/state-machine/src/ext.rs +++ b/substrate/core/state-machine/src/ext.rs @@ -17,7 +17,7 @@ //! Concrete externalities implementation. use std::{error, fmt, cmp::Ord}; -use log::warn; +use log::{warn, trace}; use crate::{ backend::Backend, OverlayedChanges, changes_trie::{ @@ -28,6 +28,7 @@ use hash_db::Hasher; use primitives::{ offchain, storage::well_known_keys::is_child_storage_key, traits::{BareCryptoStorePtr, Externalities}, child_storage_key::ChildStorageKey, + hexdisplay::HexDisplay, }; use trie::{MemoryDB, default_child_trie_root}; use trie::trie_types::Layout; @@ -91,6 +92,8 @@ where offchain_externalities: Option<&'a mut O>, /// The keystore that manages the keys of the node. keystore: Option, + /// Pseudo-unique id used for tracing. + pub id: u16, /// Dummy usage of N arg. _phantom: ::std::marker::PhantomData, } @@ -120,6 +123,7 @@ where changes_trie_transaction: None, offchain_externalities, keystore, + id: rand::random(), _phantom: Default::default(), } } @@ -183,66 +187,137 @@ where H: Hasher, { fn storage(&self, key: &[u8]) -> Option> { let _guard = panic_handler::AbortGuard::force_abort(); - self.overlay.storage(key).map(|x| x.map(|x| x.to_vec())).unwrap_or_else(|| - self.backend.storage(key).expect(EXT_NOT_ALLOWED_TO_FAIL)) + let result = self.overlay.storage(key).map(|x| x.map(|x| x.to_vec())).unwrap_or_else(|| + self.backend.storage(key).expect(EXT_NOT_ALLOWED_TO_FAIL)); + trace!(target: "state-trace", "{:04x}: Get {}={:?}", + self.id, + HexDisplay::from(&key), + result.as_ref().map(HexDisplay::from) + ); + result } fn storage_hash(&self, key: &[u8]) -> Option { let _guard = panic_handler::AbortGuard::force_abort(); - self.overlay.storage(key).map(|x| x.map(|x| H::hash(x))).unwrap_or_else(|| - self.backend.storage_hash(key).expect(EXT_NOT_ALLOWED_TO_FAIL)) + let result = self.overlay.storage(key).map(|x| x.map(|x| H::hash(x))).unwrap_or_else(|| + self.backend.storage_hash(key).expect(EXT_NOT_ALLOWED_TO_FAIL)); + trace!(target: "state-trace", "{:04x}: Hash {}={:?}", + self.id, + HexDisplay::from(&key), + result, + ); + result } fn original_storage(&self, key: &[u8]) -> Option> { let _guard = panic_handler::AbortGuard::force_abort(); - self.backend.storage(key).expect(EXT_NOT_ALLOWED_TO_FAIL) + let result = self.backend.storage(key).expect(EXT_NOT_ALLOWED_TO_FAIL); + trace!(target: "state-trace", "{:04x}: GetOriginal {}={:?}", + self.id, + HexDisplay::from(&key), + result.as_ref().map(HexDisplay::from) + ); + result } fn original_storage_hash(&self, key: &[u8]) -> Option { let _guard = panic_handler::AbortGuard::force_abort(); - self.backend.storage_hash(key).expect(EXT_NOT_ALLOWED_TO_FAIL) + let result = self.backend.storage_hash(key).expect(EXT_NOT_ALLOWED_TO_FAIL); + trace!(target: "state-trace", "{:04x}: GetOriginalHash {}={:?}", + self.id, + HexDisplay::from(&key), + result, + ); + result } fn child_storage(&self, storage_key: ChildStorageKey, key: &[u8]) -> Option> { let _guard = panic_handler::AbortGuard::force_abort(); - self.overlay.child_storage(storage_key.as_ref(), key).map(|x| x.map(|x| x.to_vec())).unwrap_or_else(|| - self.backend.child_storage(storage_key.as_ref(), key).expect(EXT_NOT_ALLOWED_TO_FAIL)) + let result = self.overlay.child_storage(storage_key.as_ref(), key).map(|x| x.map(|x| x.to_vec())).unwrap_or_else(|| + self.backend.child_storage(storage_key.as_ref(), key).expect(EXT_NOT_ALLOWED_TO_FAIL)); + trace!(target: "state-trace", "{:04x}: GetChild({}) {}={:?}", + self.id, + HexDisplay::from(&storage_key.as_ref()), + HexDisplay::from(&key), + result.as_ref().map(HexDisplay::from) + ); + result } fn child_storage_hash(&self, storage_key: ChildStorageKey, key: &[u8]) -> Option { let _guard = panic_handler::AbortGuard::force_abort(); - self.overlay.child_storage(storage_key.as_ref(), key).map(|x| x.map(|x| H::hash(x))).unwrap_or_else(|| - self.backend.storage_hash(key).expect(EXT_NOT_ALLOWED_TO_FAIL)) + let result = self.overlay.child_storage(storage_key.as_ref(), key).map(|x| x.map(|x| H::hash(x))).unwrap_or_else(|| + self.backend.storage_hash(key).expect(EXT_NOT_ALLOWED_TO_FAIL)); + trace!(target: "state-trace", "{:04x}: ChildHash({}) {}={:?}", + self.id, + HexDisplay::from(&storage_key.as_ref()), + HexDisplay::from(&key), + result, + ); + result } fn original_child_storage(&self, storage_key: ChildStorageKey, key: &[u8]) -> Option> { let _guard = panic_handler::AbortGuard::force_abort(); - self.backend.child_storage(storage_key.as_ref(), key).expect(EXT_NOT_ALLOWED_TO_FAIL) + let result = self.backend.child_storage(storage_key.as_ref(), key).expect(EXT_NOT_ALLOWED_TO_FAIL); + trace!(target: "state-trace", "{:04x}: ChildOriginal({}) {}={:?}", + self.id, + HexDisplay::from(&storage_key.as_ref()), + HexDisplay::from(&key), + result.as_ref().map(HexDisplay::from), + ); + result } fn original_child_storage_hash(&self, storage_key: ChildStorageKey, key: &[u8]) -> Option { let _guard = panic_handler::AbortGuard::force_abort(); - self.backend.child_storage_hash(storage_key.as_ref(), key).expect(EXT_NOT_ALLOWED_TO_FAIL) + let result = self.backend.child_storage_hash(storage_key.as_ref(), key).expect(EXT_NOT_ALLOWED_TO_FAIL); + trace!(target: "state-trace", "{}: ChildHashOriginal({}) {}={:?}", + self.id, + HexDisplay::from(&storage_key.as_ref()), + HexDisplay::from(&key), + result, + ); + result } fn exists_storage(&self, key: &[u8]) -> bool { let _guard = panic_handler::AbortGuard::force_abort(); - match self.overlay.storage(key) { + let result = match self.overlay.storage(key) { Some(x) => x.is_some(), _ => self.backend.exists_storage(key).expect(EXT_NOT_ALLOWED_TO_FAIL), - } + }; + trace!(target: "state-trace", "{:04x}: Exists {}={:?}", + self.id, + HexDisplay::from(&key), + result, + ); + result + } fn exists_child_storage(&self, storage_key: ChildStorageKey, key: &[u8]) -> bool { let _guard = panic_handler::AbortGuard::force_abort(); - match self.overlay.child_storage(storage_key.as_ref(), key) { + let result = match self.overlay.child_storage(storage_key.as_ref(), key) { Some(x) => x.is_some(), _ => self.backend.exists_child_storage(storage_key.as_ref(), key).expect(EXT_NOT_ALLOWED_TO_FAIL), - } + }; + trace!(target: "state-trace", "{:04x}: ChildExists({}) {}={:?}", + self.id, + HexDisplay::from(&storage_key.as_ref()), + HexDisplay::from(&key), + result, + ); + result } fn place_storage(&mut self, key: Vec, value: Option>) { + trace!(target: "state-trace", "{:04x}: Put {}={:?}", + self.id, + HexDisplay::from(&key), + value.as_ref().map(HexDisplay::from) + ); let _guard = panic_handler::AbortGuard::force_abort(); if is_child_storage_key(&key) { warn!(target: "trie", "Refuse to directly set child storage key"); @@ -254,6 +329,12 @@ where H: Hasher, } fn place_child_storage(&mut self, storage_key: ChildStorageKey, key: Vec, value: Option>) { + trace!(target: "state-trace", "{:04x}: PutChild({}) {}={:?}", + self.id, + HexDisplay::from(&storage_key.as_ref()), + HexDisplay::from(&key), + value.as_ref().map(HexDisplay::from) + ); let _guard = panic_handler::AbortGuard::force_abort(); self.mark_dirty(); @@ -261,6 +342,10 @@ where H: Hasher, } fn kill_child_storage(&mut self, storage_key: ChildStorageKey) { + trace!(target: "state-trace", "{:04x}: KillChild({})", + self.id, + HexDisplay::from(&storage_key.as_ref()), + ); let _guard = panic_handler::AbortGuard::force_abort(); self.mark_dirty(); @@ -271,6 +356,10 @@ where H: Hasher, } fn clear_prefix(&mut self, prefix: &[u8]) { + trace!(target: "state-trace", "{:04x}: ClearPrefix {}", + self.id, + HexDisplay::from(&prefix), + ); let _guard = panic_handler::AbortGuard::force_abort(); if is_child_storage_key(prefix) { warn!(target: "trie", "Refuse to directly clear prefix that is part of child storage key"); @@ -285,6 +374,11 @@ where H: Hasher, } fn clear_child_prefix(&mut self, storage_key: ChildStorageKey, prefix: &[u8]) { + trace!(target: "state-trace", "{:04x}: ClearChildPrefix({}) {}", + self.id, + HexDisplay::from(&storage_key.as_ref()), + HexDisplay::from(&prefix), + ); let _guard = panic_handler::AbortGuard::force_abort(); self.mark_dirty(); @@ -301,6 +395,10 @@ where H: Hasher, fn storage_root(&mut self) -> H::Out { let _guard = panic_handler::AbortGuard::force_abort(); if let Some((_, ref root)) = self.storage_transaction { + trace!(target: "state-trace", "{:04x}: Root (cached) {}", + self.id, + HexDisplay::from(&root.as_ref()), + ); return root.clone(); } @@ -322,17 +420,27 @@ where H: Hasher, let (root, transaction) = self.backend.full_storage_root(delta, child_delta_iter); self.storage_transaction = Some((transaction, root)); + trace!(target: "state-trace", "{:04x}: Root {}", + self.id, + HexDisplay::from(&root.as_ref()), + ); root } fn child_storage_root(&mut self, storage_key: ChildStorageKey) -> Vec { let _guard = panic_handler::AbortGuard::force_abort(); if self.storage_transaction.is_some() { - self + let root = self .storage(storage_key.as_ref()) .unwrap_or( default_child_trie_root::>(storage_key.as_ref()) - ) + ); + trace!(target: "state-trace", "{:04x}: ChildRoot({}) (cached) {}", + self.id, + HexDisplay::from(&storage_key.as_ref()), + HexDisplay::from(&root.as_ref()), + ); + root } else { let storage_key = storage_key.as_ref(); @@ -347,6 +455,11 @@ where H: Hasher, self.overlay.set_storage(storage_key.to_vec(), Some(root.to_vec())); + trace!(target: "state-trace", "{:04x}: ChildRoot({}) {}", + self.id, + HexDisplay::from(&storage_key.as_ref()), + HexDisplay::from(&root.as_ref()), + ); root } @@ -360,7 +473,13 @@ where H: Hasher, self.overlay, parent_hash, )?; - Ok(self.changes_trie_transaction.as_ref().map(|(_, root, _)| root.clone())) + let result = Ok(self.changes_trie_transaction.as_ref().map(|(_, root, _)| root.clone())); + trace!(target: "state-trace", "{:04x}: ChangesRoot({}) {:?}", + self.id, + HexDisplay::from(&parent_hash.as_ref()), + result, + ); + result } fn offchain(&mut self) -> Option<&mut dyn offchain::Externalities> { diff --git a/substrate/core/state-machine/src/lib.rs b/substrate/core/state-machine/src/lib.rs index 7b9dc6ac84..92dd813b89 100644 --- a/substrate/core/state-machine/src/lib.rs +++ b/substrate/core/state-machine/src/lib.rs @@ -22,12 +22,13 @@ use std::{ fmt, result, collections::HashMap, marker::PhantomData, panic::UnwindSafe, }; -use log::warn; +use log::{warn, trace}; use hash_db::Hasher; use codec::{Decode, Encode}; use primitives::{ storage::well_known_keys, NativeOrEncoded, NeverNativeValue, offchain::{self, NeverOffchainExt}, traits::{BareCryptoStorePtr, CodeExecutor}, + hexdisplay::HexDisplay, }; pub mod backend; @@ -258,6 +259,13 @@ impl<'a, B, H, N, T, O, Exec> StateMachine<'a, B, H, N, T, O, Exec> where self.offchain_ext.as_mut().map(|x| &mut **x), self.keystore.clone(), ); + let id = externalities.id; + trace!(target: "state-trace", "{:04x}: Call {} at {:?}. Input={:?}", + id, + self.method, + self.backend, + HexDisplay::from(&self.call_data), + ); let (result, was_native) = self.exec.call( &mut externalities, self.method, @@ -271,6 +279,11 @@ impl<'a, B, H, N, T, O, Exec> StateMachine<'a, B, H, N, T, O, Exec> where } else { (None, None) }; + trace!(target: "state-trace", "{:04x}: Return. Native={:?}, Result={:?}", + id, + was_native, + result, + ); (result, was_native, storage_delta, changes_delta) } diff --git a/substrate/core/state-machine/src/proving_backend.rs b/substrate/core/state-machine/src/proving_backend.rs index 64ec7de81b..3908f62eaa 100644 --- a/substrate/core/state-machine/src/proving_backend.rs +++ b/substrate/core/state-machine/src/proving_backend.rs @@ -139,6 +139,12 @@ impl<'a, S: 'a + TrieBackendStorage, H: 'a + Hasher> ProvingBackend<'a, S, H> } } +impl<'a, S: 'a + TrieBackendStorage, H: 'a + Hasher> std::fmt::Debug for ProvingBackend<'a, S, H> { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!(f, "ProvingBackend") + } +} + impl<'a, S, H> Backend for ProvingBackend<'a, S, H> where S: 'a + TrieBackendStorage, diff --git a/substrate/core/state-machine/src/trie_backend.rs b/substrate/core/state-machine/src/trie_backend.rs index 105e20c9b7..ce5773c0b7 100644 --- a/substrate/core/state-machine/src/trie_backend.rs +++ b/substrate/core/state-machine/src/trie_backend.rs @@ -57,6 +57,12 @@ impl, H: Hasher> TrieBackend { } } +impl, H: Hasher> std::fmt::Debug for TrieBackend { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!(f, "TrieBackend") + } +} + impl, H: Hasher> Backend for TrieBackend where H::Out: Ord, {