diff --git a/Cargo.lock b/Cargo.lock index 6cf96d8e81b69..b2480d3aec9a0 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -20128,6 +20128,7 @@ version = "0.29.0" dependencies = [ "polkavm 0.26.0", "sc-allocator", + "sp-crypto-hashing 0.1.0", "sp-maybe-compressed-blob", "sp-wasm-interface 20.0.0", "thiserror 1.0.65", diff --git a/prdoc/pr_9363.prdoc b/prdoc/pr_9363.prdoc new file mode 100644 index 0000000000000..67b08ea5501b6 --- /dev/null +++ b/prdoc/pr_9363.prdoc @@ -0,0 +1,13 @@ +title: 'executor: log host alloc/dealloc' +doc: +- audience: Node Dev + description: |- + Testing allocation patterns in the context of #8992 required adding some debug logs to trace the calls into host allocator `allocate` or `deallocate` functions, while also tracking which runtime did the call (as code hash), which instance of the runtime, and a `call_id` to determine an approximate order of the allocator calls (since the logs associated to allocator calls could pottentially show up out of order in the node logs). + +crates: +- name: sc-executor-common + bump: major +- name: sc-executor-wasmtime + bump: major +- name: sc-service + bump: major diff --git a/substrate/client/executor/common/Cargo.toml b/substrate/client/executor/common/Cargo.toml index aaf13a8ae7688..508aedfdf8972 100644 --- a/substrate/client/executor/common/Cargo.toml +++ b/substrate/client/executor/common/Cargo.toml @@ -19,6 +19,7 @@ targets = ["x86_64-unknown-linux-gnu"] [dependencies] polkavm = { workspace = true } sc-allocator = { workspace = true, default-features = true } +sp-crypto-hashing = { workspace = true } sp-maybe-compressed-blob = { workspace = true, default-features = true } sp-wasm-interface = { workspace = true, default-features = true } thiserror = { workspace = true } diff --git a/substrate/client/executor/common/src/runtime_blob/runtime_blob.rs b/substrate/client/executor/common/src/runtime_blob/runtime_blob.rs index e3f4b4ad97745..75174be845204 100644 --- a/substrate/client/executor/common/src/runtime_blob/runtime_blob.rs +++ b/substrate/client/executor/common/src/runtime_blob/runtime_blob.rs @@ -25,7 +25,12 @@ use wasm_instrument::parity_wasm::elements::{ /// A program blob containing a Substrate runtime. #[derive(Clone)] -pub struct RuntimeBlob(BlobKind); +pub struct RuntimeBlob { + // Note that the hash can be different than the hash of the blob if the runtime code is + // compressed. + runtime_code_hash: Option>, + blob_kind: BlobKind, +} #[derive(Clone)] enum BlobKind { @@ -39,9 +44,10 @@ impl RuntimeBlob { /// See [`sp_maybe_compressed_blob`] for details about decompression. pub fn uncompress_if_needed(wasm_code: &[u8]) -> Result { use sp_maybe_compressed_blob::CODE_BLOB_BOMB_LIMIT; + let runtime_code_hash = sp_crypto_hashing::blake2_256(wasm_code); let wasm_code = sp_maybe_compressed_blob::decompress(wasm_code, CODE_BLOB_BOMB_LIMIT) .map_err(|e| WasmError::Other(format!("Decompression error: {:?}", e)))?; - Self::new(&wasm_code) + Self::new_with_runtime_code_hash(&wasm_code, Some(runtime_code_hash.to_vec())) } /// Create `RuntimeBlob` from the given WASM or PolkaVM program blob. @@ -51,11 +57,20 @@ impl RuntimeBlob { /// Will only accept a PolkaVM program if the `SUBSTRATE_ENABLE_POLKAVM` environment /// variable is set to `1`. pub fn new(raw_blob: &[u8]) -> Result { + Self::new_with_runtime_code_hash(raw_blob, None) + } + + /// Create `RuntimeBlob` from the given WASM or PolkaVM program blob, + /// but initialize the runtime code hash too. + fn new_with_runtime_code_hash( + raw_blob: &[u8], + runtime_code_hash: Option>, + ) -> Result { if raw_blob.starts_with(b"PVM\0") { if crate::is_polkavm_enabled() { let raw = ArcBytes::from(raw_blob); let blob = polkavm::ProgramBlob::parse(raw.clone())?; - return Ok(Self(BlobKind::PolkaVM((blob, raw)))); + return Ok(Self { blob_kind: BlobKind::PolkaVM((blob, raw)), runtime_code_hash }); } else { return Err(WasmError::Other("expected a WASM runtime blob, found a PolkaVM runtime blob; set the 'SUBSTRATE_ENABLE_POLKAVM' environment variable to enable the experimental PolkaVM-based executor".to_string())); } @@ -63,7 +78,7 @@ impl RuntimeBlob { let raw_module: Module = deserialize_buffer(raw_blob) .map_err(|e| WasmError::Other(format!("cannot deserialize module: {:?}", e)))?; - Ok(Self(BlobKind::WebAssembly(raw_module))) + Ok(Self { blob_kind: BlobKind::WebAssembly(raw_module), runtime_code_hash }) } /// Run a pass that instrument this module so as to introduce a deterministic stack height @@ -79,13 +94,14 @@ impl RuntimeBlob { /// /// Only valid for WASM programs; will return an error if the blob is a PolkaVM program. pub fn inject_stack_depth_metering(self, stack_depth_limit: u32) -> Result { + let runtime_code_hash = self.runtime_code_hash.clone(); let injected_module = wasm_instrument::inject_stack_limiter(self.into_webassembly_blob()?, stack_depth_limit) .map_err(|e| { WasmError::Other(format!("cannot inject the stack limiter: {:?}", e)) })?; - Ok(Self(BlobKind::WebAssembly(injected_module))) + Ok(Self { blob_kind: BlobKind::WebAssembly(injected_module), runtime_code_hash }) } /// Converts a WASM memory import into a memory section and exports it. @@ -190,7 +206,7 @@ impl RuntimeBlob { /// Consumes this runtime blob and serializes it. pub fn serialize(self) -> Vec { - match self.0 { + match self.blob_kind { BlobKind::WebAssembly(raw_module) => serialize(raw_module).expect("serializing into a vec should succeed; qed"), BlobKind::PolkaVM(ref blob) => blob.1.to_vec(), @@ -198,7 +214,7 @@ impl RuntimeBlob { } fn as_webassembly_blob(&self) -> Result<&Module, WasmError> { - match self.0 { + match self.blob_kind { BlobKind::WebAssembly(ref raw_module) => Ok(raw_module), BlobKind::PolkaVM(..) => Err(WasmError::Other( "expected a WebAssembly program; found a PolkaVM program blob".into(), @@ -207,7 +223,7 @@ impl RuntimeBlob { } fn as_webassembly_blob_mut(&mut self) -> Result<&mut Module, WasmError> { - match self.0 { + match self.blob_kind { BlobKind::WebAssembly(ref mut raw_module) => Ok(raw_module), BlobKind::PolkaVM(..) => Err(WasmError::Other( "expected a WebAssembly program; found a PolkaVM program blob".into(), @@ -216,7 +232,7 @@ impl RuntimeBlob { } fn into_webassembly_blob(self) -> Result { - match self.0 { + match self.blob_kind { BlobKind::WebAssembly(raw_module) => Ok(raw_module), BlobKind::PolkaVM(..) => Err(WasmError::Other( "expected a WebAssembly program; found a PolkaVM program blob".into(), @@ -226,9 +242,17 @@ impl RuntimeBlob { /// Gets a reference to the inner PolkaVM program blob, if this is a PolkaVM program. pub fn as_polkavm_blob(&self) -> Option<&polkavm::ProgramBlob> { - match self.0 { + match self.blob_kind { BlobKind::WebAssembly(..) => None, BlobKind::PolkaVM((ref blob, _)) => Some(blob), } } + + /// Return the runtime code hash associated to the blob. + /// + /// Note: the runtime code hash can be different from the blob + /// hash if the blob was built via `uncompress_if_needed`. + pub fn runtime_code_hash(&self) -> Option<&Vec> { + self.runtime_code_hash.as_ref() + } } diff --git a/substrate/client/executor/wasmtime/src/host.rs b/substrate/client/executor/wasmtime/src/host.rs index f8c78cbb660ee..781c6c0118796 100644 --- a/substrate/client/executor/wasmtime/src/host.rs +++ b/substrate/client/executor/wasmtime/src/host.rs @@ -19,6 +19,8 @@ //! This module defines `HostState` and `HostContext` structs which provide logic and state //! required for execution of host. +use std::sync::atomic::{AtomicU64, Ordering}; + use wasmtime::Caller; use sc_allocator::{AllocationStats, FreeingBumpHeapAllocator}; @@ -37,12 +39,25 @@ pub struct HostState { /// once. allocator: Option, panic_message: Option, + instance_id: u64, + runtime_code_hash: Option>, + allocator_call_id: AtomicU64, } impl HostState { /// Constructs a new `HostState`. - pub fn new(allocator: FreeingBumpHeapAllocator) -> Self { - HostState { allocator: Some(allocator), panic_message: None } + pub fn new( + allocator: FreeingBumpHeapAllocator, + instance_id: u64, + runtime_code_hash: Option>, + ) -> Self { + HostState { + allocator: Some(allocator), + panic_message: None, + instance_id, + runtime_code_hash, + allocator_call_id: AtomicU64::new(1), + } } /// Takes the error message out of the host state, leaving a `None` in its place. @@ -55,6 +70,11 @@ impl HostState { .expect("Allocator is always set and only unavailable when doing an allocation/deallocation; qed") .stats() } + + /// Increment the call id atomically and return the previous value before incrementing. + pub(crate) fn increment_call_id(&mut self) -> u64 { + self.allocator_call_id.fetch_add(1, Ordering::Relaxed) + } } /// A `HostContext` implements `FunctionContext` for making host calls from a Wasmtime @@ -71,6 +91,13 @@ impl<'a> HostContext<'a> { .host_state_mut() .expect("host state is not empty when calling a function in wasm; qed") } + + fn host_state(&mut self) -> &HostState { + self.caller + .data() + .host_state() + .expect("host state is not empty when calling a function in wasm; qed") + } } impl<'a> sp_wasm_interface::FunctionContext for HostContext<'a> { @@ -97,10 +124,18 @@ impl<'a> sp_wasm_interface::FunctionContext for HostContext<'a> { // We can not return on error early, as we need to store back allocator. let res = allocator .allocate(&mut MemoryWrapper(&memory, &mut self.caller), size) + .inspect(|ptr| { + let call_id = self.host_state_mut().increment_call_id(); + let instance_id = self.host_state().instance_id; + let runtime_code_hash = &self.host_state().runtime_code_hash; + runtime_code_hash.as_ref().inspect(|code_hash| { + let display_ptr = u64::from(*ptr); + log::debug!(target: "runtime_host_allocator", "allocation: code_hash={code_hash:x?}, instance_id={instance_id}, call_id={call_id}, size={size}, ptr=0x{display_ptr:x?}") + }); + }) .map_err(|e| e.to_string()); self.host_state_mut().allocator = Some(allocator); - res } @@ -115,10 +150,18 @@ impl<'a> sp_wasm_interface::FunctionContext for HostContext<'a> { // We can not return on error early, as we need to store back allocator. let res = allocator .deallocate(&mut MemoryWrapper(&memory, &mut self.caller), ptr) + .inspect(|_| { + let call_id = self.host_state_mut().increment_call_id(); + let instance_id = self.host_state().instance_id; + let runtime_code_hash = &self.host_state().runtime_code_hash; + runtime_code_hash.as_ref().inspect(|code_hash| { + let display_ptr = u64::from(ptr); + log::debug!(target: "runtime_host_allocator", "deallocation: code_hash={code_hash:x?}, instance_id={instance_id}, call_id={call_id}, ptr=0x{display_ptr:x?}"); + }); + }) .map_err(|e| e.to_string()); self.host_state_mut().allocator = Some(allocator); - res } diff --git a/substrate/client/executor/wasmtime/src/instance_wrapper.rs b/substrate/client/executor/wasmtime/src/instance_wrapper.rs index 4f67d1df9c5f3..d019aa75a0c5b 100644 --- a/substrate/client/executor/wasmtime/src/instance_wrapper.rs +++ b/substrate/client/executor/wasmtime/src/instance_wrapper.rs @@ -118,7 +118,7 @@ pub struct InstanceWrapper { // NOTE: We want to decrement the instance counter *after* the store has been dropped // to avoid a potential race condition, so this field must always be kept // as the last field in the struct! - _release_instance_handle: ReleaseInstanceHandle, + release_instance_handle: ReleaseInstanceHandle, } impl InstanceWrapper { @@ -127,7 +127,7 @@ impl InstanceWrapper { instance_pre: &InstancePre, instance_counter: Arc, ) -> Result { - let _release_instance_handle = instance_counter.acquire_instance(); + let release_instance_handle = instance_counter.acquire_instance(); let mut store = Store::new(engine, Default::default()); let instance = instance_pre.instantiate(&mut store).map_err(|error| { WasmError::Other(format!( @@ -140,7 +140,7 @@ impl InstanceWrapper { store.data_mut().memory = Some(memory); - Ok(InstanceWrapper { instance, store, _release_instance_handle }) + Ok(InstanceWrapper { instance, store, release_instance_handle }) } /// Resolves a substrate entrypoint by the given name. @@ -181,6 +181,18 @@ impl InstanceWrapper { Ok(heap_base as u32) } + + /// Return the runtime code hash of the underlying instance. + /// + /// Note: the runtime code hash might correspond to a compressed runtime. + pub fn runtime_code_hash(&self) -> Option<&Vec> { + self.release_instance_handle.runtime_code_hash() + } + + /// Return the instance id. + pub fn id(&self) -> u64 { + self.release_instance_handle.id() + } } /// Extract linear memory instance from the given instance. diff --git a/substrate/client/executor/wasmtime/src/runtime.rs b/substrate/client/executor/wasmtime/src/runtime.rs index fd2b2f9ead5d2..49675bbb61bf3 100644 --- a/substrate/client/executor/wasmtime/src/runtime.rs +++ b/substrate/client/executor/wasmtime/src/runtime.rs @@ -37,7 +37,7 @@ use sp_wasm_interface::{HostFunctions, Pointer, WordSize}; use std::{ path::{Path, PathBuf}, sync::{ - atomic::{AtomicBool, Ordering}, + atomic::{AtomicBool, AtomicU64, Ordering}, Arc, }, }; @@ -59,6 +59,11 @@ impl StoreData { self.host_state.as_mut() } + /// Returns a reference to the host state. + pub fn host_state(&self) -> Option<&HostState> { + self.host_state.as_ref() + } + /// Returns the host memory. pub fn memory(&self) -> Memory { self.memory.expect("memory is always set; qed") @@ -86,6 +91,24 @@ impl InstanceCreator { /// A handle for releasing an instance acquired by [`InstanceCounter::acquire_instance`]. pub(crate) struct ReleaseInstanceHandle { counter: Arc, + runtime_code_hash: Option>, + id: u64, +} + +impl ReleaseInstanceHandle { + /// Return the runtime code hash of the instance. + /// + /// Note: the hash might correspond to a compressed runtime. + pub(crate) fn runtime_code_hash(&self) -> Option<&Vec> { + self.runtime_code_hash.as_ref() + } + + /// Return the unique instance id. + /// + /// Note: this id is incremented with every runtime instantiation. + pub(crate) fn id(&self) -> u64 { + self.id + } } impl Drop for ReleaseInstanceHandle { @@ -109,6 +132,8 @@ impl Drop for ReleaseInstanceHandle { pub(crate) struct InstanceCounter { counter: Mutex, wait_for_instance: parking_lot::Condvar, + current_instance_id: AtomicU64, + runtime_code_hash: Option>, } impl InstanceCounter { @@ -126,7 +151,21 @@ impl InstanceCounter { } *counter += 1; - ReleaseInstanceHandle { counter: self.clone() } + // Increment the id with every runtime instantiation. + self.current_instance_id.fetch_add(1, Ordering::Relaxed); + + ReleaseInstanceHandle { + counter: self.clone(), + runtime_code_hash: self.runtime_code_hash.clone(), + id: self.current_instance_id.load(Ordering::Relaxed), + } + } + + /// Create an instance counter that holds a specific runtime code hash. + pub(crate) fn new_with_runtime_code_hash(runtime_code_hash: Option>) -> Self { + let mut counter = Self::default(); + counter.runtime_code_hash = runtime_code_hash; + counter } } @@ -569,7 +608,7 @@ where let engine = Engine::new(&wasmtime_config) .map_err(|e| WasmError::Other(format!("cannot create the wasmtime engine: {:#}", e)))?; - let (module, instantiation_strategy) = match code_supply_mode { + let (instance_counter, module, instantiation_strategy) = match code_supply_mode { CodeSupplyMode::Fresh(blob) => { let blob = prepare_blob_for_compilation(blob, &config.semantics)?; let serialized_blob = blob.clone().serialize(); @@ -581,8 +620,13 @@ where InstantiationStrategy::Pooling | InstantiationStrategy::PoolingCopyOnWrite | InstantiationStrategy::RecreateInstance | - InstantiationStrategy::RecreateInstanceCopyOnWrite => - (module, InternalInstantiationStrategy::Builtin), + InstantiationStrategy::RecreateInstanceCopyOnWrite => ( + InstanceCounter::new_with_runtime_code_hash( + blob.runtime_code_hash().map(|hash| hash.clone()), + ), + module, + InternalInstantiationStrategy::Builtin, + ), } }, CodeSupplyMode::Precompiled(compiled_artifact_path) => { @@ -593,7 +637,7 @@ where let module = wasmtime::Module::deserialize_file(&engine, compiled_artifact_path) .map_err(|e| WasmError::Other(format!("cannot deserialize module: {:#}", e)))?; - (module, InternalInstantiationStrategy::Builtin) + (InstanceCounter::default(), module, InternalInstantiationStrategy::Builtin) }, CodeSupplyMode::PrecompiledBytes(compiled_artifact_bytes) => { // SAFETY: The unsafety of `deserialize` is covered by this function. The @@ -603,7 +647,7 @@ where let module = wasmtime::Module::deserialize(&engine, compiled_artifact_bytes) .map_err(|e| WasmError::Other(format!("cannot deserialize module: {:#}", e)))?; - (module, InternalInstantiationStrategy::Builtin) + (InstanceCounter::default(), module, InternalInstantiationStrategy::Builtin) }, }; @@ -618,7 +662,7 @@ where engine, instance_pre: Arc::new(instance_pre), instantiation_strategy, - instance_counter: Default::default(), + instance_counter: instance_counter.into(), }) } @@ -668,7 +712,9 @@ fn perform_call( ) -> Result> { let (data_ptr, data_len) = inject_input_data(instance_wrapper, &mut allocator, data)?; - let host_state = HostState::new(allocator); + let runtime_code_hash = instance_wrapper.runtime_code_hash().cloned(); + let instance_id = instance_wrapper.id(); + let host_state = HostState::new(allocator, instance_id, runtime_code_hash); // Set the host state before calling into wasm. instance_wrapper.store_mut().data_mut().host_state = Some(host_state); @@ -698,6 +744,11 @@ fn inject_input_data( let memory = ctx.data().memory(); let data_len = data.len() as WordSize; let data_ptr = allocator.allocate(&mut MemoryWrapper(&memory, &mut ctx), data_len)?; + + let instance_id = instance.id(); + let display_ptr = u64::from(data_ptr); + instance.runtime_code_hash().inspect(|code_hash| log::debug!(target: "runtime_host_allocator", "inject_input_data: code_hash={code_hash:x?}, instance_id={instance_id}, call_id=0, size={data_len}, ptr=0x{display_ptr:x?}")); + util::write_memory_from(instance.store_mut(), data_ptr, data)?; Ok((data_ptr, data_len)) } diff --git a/substrate/client/service/src/client/wasm_override.rs b/substrate/client/service/src/client/wasm_override.rs index 678ae22bec111..df9063699f796 100644 --- a/substrate/client/service/src/client/wasm_override.rs +++ b/substrate/client/service/src/client/wasm_override.rs @@ -38,13 +38,15 @@ use sc_executor::RuntimeVersionOf; use sp_blockchain::Result; -use sp_core::traits::{FetchRuntimeCode, RuntimeCode, WrappedRuntimeCode}; +use sp_core::{ + traits::{FetchRuntimeCode, RuntimeCode, WrappedRuntimeCode}, + Hasher, +}; use sp_state_machine::BasicExternalities; use sp_version::RuntimeVersion; use std::{ - collections::{hash_map::DefaultHasher, HashMap}, + collections::HashMap, fs, - hash::Hasher as _, path::{Path, PathBuf}, time::{Duration, Instant}, }; @@ -79,13 +81,6 @@ impl WasmBlob { } } -/// Make a hash out of a byte string using the default rust hasher -fn make_hash(val: &K) -> Vec { - let mut state = DefaultHasher::new(); - val.hash(&mut state); - state.finish().to_le_bytes().to_vec() -} - impl FetchRuntimeCode for WasmBlob { fn fetch_runtime_code(&self) -> Option> { Some(self.code.as_slice().into()) @@ -188,16 +183,25 @@ impl WasmOverride { let path = entry.path(); if let Some("wasm") = path.extension().and_then(|e| e.to_str()) { let code = fs::read(&path).map_err(handle_err)?; - let code_hash = make_hash(&code); - let version = Self::runtime_version(executor, &code, &code_hash, Some(128))?; + // Blake2_256 is used accross the board for hashing the code, and it is important + // to use same hashing everywhere to be able to track unique instances of the code. + let code_hash = sp_core::Blake2Hasher::hash(&code); + let version = + Self::runtime_version(executor, &code, code_hash.as_bytes(), Some(128))?; tracing::info!( target: "wasm_overrides", version = %version, file = %path.display(), + ?code_hash, "Found wasm override.", ); - let wasm = WasmBlob::new(code, code_hash, path.clone(), version.clone()); + let wasm = WasmBlob::new( + code, + code_hash.as_bytes().to_vec(), + path.clone(), + version.clone(), + ); if let Some(other) = overrides.insert(version.spec_version, wasm) { tracing::info!( diff --git a/substrate/client/service/src/client/wasm_substitutes.rs b/substrate/client/service/src/client/wasm_substitutes.rs index 07ca6c9606283..941a2bbbe57d2 100644 --- a/substrate/client/service/src/client/wasm_substitutes.rs +++ b/substrate/client/service/src/client/wasm_substitutes.rs @@ -21,15 +21,14 @@ use sc_client_api::backend; use sc_executor::RuntimeVersionOf; use sp_blockchain::{HeaderBackend, Result}; -use sp_core::traits::{FetchRuntimeCode, RuntimeCode, WrappedRuntimeCode}; +use sp_core::{ + traits::{FetchRuntimeCode, RuntimeCode, WrappedRuntimeCode}, + Hasher, +}; use sp_runtime::traits::{Block as BlockT, NumberFor}; use sp_state_machine::BasicExternalities; use sp_version::RuntimeVersion; -use std::{ - collections::{hash_map::DefaultHasher, HashMap}, - hash::Hasher as _, - sync::Arc, -}; +use std::{collections::HashMap, sync::Arc}; /// A wasm substitute for the on chain wasm. #[derive(Debug)] @@ -43,8 +42,8 @@ struct WasmSubstitute { impl WasmSubstitute { fn new(code: Vec, block_number: NumberFor, version: RuntimeVersion) -> Self { - let hash = make_hash(&code); - Self { code, hash, block_number, version } + let hash = sp_core::Blake2Hasher::hash(&code); + Self { code, hash: hash.as_bytes().to_vec(), block_number, version } } fn runtime_code(&self, heap_pages: Option) -> RuntimeCode { @@ -63,13 +62,6 @@ impl WasmSubstitute { } } -/// Make a hash out of a byte string using the default rust hasher -fn make_hash(val: &K) -> Vec { - let mut state = DefaultHasher::new(); - val.hash(&mut state); - state.finish().to_le_bytes().to_vec() -} - impl FetchRuntimeCode for WasmSubstitute { fn fetch_runtime_code(&self) -> Option> { Some(self.code.as_slice().into()) @@ -123,10 +115,11 @@ where let substitutes = substitutes .into_iter() .map(|(block_number, code)| { + let code_hash = sp_core::Blake2Hasher::hash(&code); let runtime_code = RuntimeCode { code_fetcher: &WrappedRuntimeCode((&code).into()), heap_pages: None, - hash: make_hash(&code), + hash: code_hash.as_bytes().to_vec(), }; let version = Self::runtime_version(&executor, &runtime_code)?; let spec_version = version.spec_version;