From 5e5341da9b28e472a9a3cf8d286d7b9c871f589a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexander=20Thei=C3=9Fen?= Date: Fri, 26 Jan 2024 23:33:33 +0100 Subject: [PATCH] contracts: Fix printing the `Schedule` (#3021) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Printing the `Schedule` is a useful debugging tool and general sanity check. It is much more easy to interpret than the raw weights. The printing relied on using `println` and hence was only available from the native runtime. This is no longer available. This is why in this PR we switch to using `log` which works from Wasm. I made sure that the `WeightDebug` is only derived when `runtime-benchmarks` is set so that we don't increase the size of the binary. Some other changes were necessary to make this actually work inside the runtime. For example, I needed to remove `format!` and usage of floats. Please note that this removed the decimal from the number because truncating the fraction without using floats would not be easy and would require custom code. I think the precision here is sufficient. This is how the output looks like now: ``` Schedule { limits: Limits { event_topics: 4, globals: 256, locals: 1024, parameters: 128, memory_pages: 16, table_size: 4096, br_table_size: 256, subject_len: 32, payload_len: 16384, runtime_memory: 134217728, }, instruction_weights: InstructionWeights { base: 2565, _phantom: PhantomData, }, host_fn_weights: HostFnWeights { caller: 322 ns, 6 bytes, is_contract: 28 µs, 2684 bytes, code_hash: 29 µs, 2688 bytes, own_code_hash: 400 ns, 6 bytes, caller_is_origin: 176 ns, 3 bytes, caller_is_root: 158 ns, 3 bytes, address: 315 ns, 6 bytes, gas_left: 355 ns, 6 bytes, balance: 1 µs, 6 bytes, value_transferred: 314 ns, 6 bytes, minimum_balance: 318 ns, 6 bytes, block_number: 313 ns, 6 bytes, now: 325 ns, 6 bytes, weight_to_fee: 1 µs, 14 bytes, input: 263 ns, 6 bytes, input_per_byte: 989 ps, 0 bytes, r#return: 0 ps, 45 bytes, return_per_byte: 320 ps, 0 bytes, terminate: 1 ms, 5266 bytes, random: 1 µs, 10 bytes, deposit_event: 1 µs, 10 bytes, deposit_event_per_topic: 127 µs, 2508 bytes, deposit_event_per_byte: 501 ps, 0 bytes, debug_message: 226 ns, 7 bytes, debug_message_per_byte: 1 ns, 0 bytes, set_storage: 131 µs, 293 bytes, set_storage_per_new_byte: 576 ps, 0 bytes, set_storage_per_old_byte: 184 ps, 1 bytes, set_code_hash: 297 µs, 3090 bytes, clear_storage: 131 µs, 289 bytes, clear_storage_per_byte: 92 ps, 1 bytes, contains_storage: 29 µs, 289 bytes, contains_storage_per_byte: 213 ps, 1 bytes, get_storage: 29 µs, 297 bytes, get_storage_per_byte: 980 ps, 1 bytes, take_storage: 131 µs, 297 bytes, take_storage_per_byte: 921 ps, 1 bytes, transfer: 156 µs, 2520 bytes, call: 484 µs, 2721 bytes, delegate_call: 406 µs, 2637 bytes, call_transfer_surcharge: 607 µs, 5227 bytes, call_per_cloned_byte: 970 ps, 0 bytes, instantiate: 1 ms, 2731 bytes, instantiate_transfer_surcharge: 131 µs, 2549 bytes, instantiate_per_input_byte: 1 ns, 0 bytes, instantiate_per_salt_byte: 1 ns, 0 bytes, hash_sha2_256: 377 ns, 8 bytes, hash_sha2_256_per_byte: 1 ns, 0 bytes, hash_keccak_256: 767 ns, 8 bytes, hash_keccak_256_per_byte: 3 ns, 0 bytes, hash_blake2_256: 443 ns, 8 bytes, hash_blake2_256_per_byte: 1 ns, 0 bytes, hash_blake2_128: 440 ns, 8 bytes, hash_blake2_128_per_byte: 1 ns, 0 bytes, ecdsa_recover: 45 µs, 77 bytes, ecdsa_to_eth_address: 11 µs, 42 bytes, sr25519_verify: 41 µs, 112 bytes, sr25519_verify_per_byte: 5 ns, 1 bytes, reentrance_count: 174 ns, 3 bytes, account_reentrance_count: 248 ns, 40 bytes, instantiation_nonce: 154 ns, 3 bytes, add_delegate_dependency: 131 µs, 2606 bytes, remove_delegate_dependency: 130 µs, 2568 bytes, }, } ############################################### Lazy deletion weight per key: Weight(ref_time: 126109302, proof_size: 70) Lazy deletion keys per block: 15859 ``` --- substrate/frame/contracts/Cargo.toml | 1 - substrate/frame/contracts/README.md | 13 ++ .../frame/contracts/mock-network/Cargo.toml | 1 - .../frame/contracts/proc-macro/Cargo.toml | 6 - .../frame/contracts/proc-macro/src/lib.rs | 135 +++++++----------- .../frame/contracts/src/benchmarking/mod.rs | 26 ++-- substrate/frame/contracts/src/schedule.rs | 26 ++-- 7 files changed, 80 insertions(+), 128 deletions(-) diff --git a/substrate/frame/contracts/Cargo.toml b/substrate/frame/contracts/Cargo.toml index 0adaeb829610..de49983a4b3f 100644 --- a/substrate/frame/contracts/Cargo.toml +++ b/substrate/frame/contracts/Cargo.toml @@ -86,7 +86,6 @@ std = [ "frame-system/std", "log/std", "pallet-balances?/std", - "pallet-contracts-proc-macro/full", "pallet-insecure-randomness-collective-flip/std", "pallet-proxy/std", "pallet-timestamp/std", diff --git a/substrate/frame/contracts/README.md b/substrate/frame/contracts/README.md index 0b6548cf6414..6e817292e66c 100644 --- a/substrate/frame/contracts/README.md +++ b/substrate/frame/contracts/README.md @@ -34,6 +34,19 @@ calls are reverted. Assuming correct error handling by contract A, A's other cal One `ref_time` `Weight` is defined as one picosecond of execution time on the runtime's reference machine. +#### Schedule + +The `Schedule` is where, among other things, the cost of every action a contract can do is defined. These costs are derived +from the benchmarks of this pallet. Instead of looking at the raw benchmark results it is advised to look at the `Schedule` +if one wants to manually inspect the performance characteristics. The `Schedule` can be printed like this: + +```sh +RUST_LOG=runtime::contracts=info cargo run --features runtime-benchmarks --bin substrate-node -- benchmark pallet --extra -p pallet_contracts -e print_schedule +``` + +Please note that the `Schedule` will be printed multiple times. This is because we are (ab)using a benchmark to print +the struct. + ### Revert Behaviour Contract call failures are not cascading. When failures occur in a sub-call, they do not "bubble up", and the call will diff --git a/substrate/frame/contracts/mock-network/Cargo.toml b/substrate/frame/contracts/mock-network/Cargo.toml index f0dbe6527aeb..0c4cd1356f4d 100644 --- a/substrate/frame/contracts/mock-network/Cargo.toml +++ b/substrate/frame/contracts/mock-network/Cargo.toml @@ -55,7 +55,6 @@ std = [ "frame-support/std", "frame-system/std", "pallet-balances/std", - "pallet-contracts-proc-macro/full", "pallet-contracts/std", "pallet-insecure-randomness-collective-flip/std", "pallet-proxy/std", diff --git a/substrate/frame/contracts/proc-macro/Cargo.toml b/substrate/frame/contracts/proc-macro/Cargo.toml index ef4e391e9abc..ed6175ee8cdf 100644 --- a/substrate/frame/contracts/proc-macro/Cargo.toml +++ b/substrate/frame/contracts/proc-macro/Cargo.toml @@ -21,9 +21,3 @@ proc-macro = true proc-macro2 = "1.0.56" quote = "1.0.28" syn = { version = "2.0.48", features = ["full"] } - -[dev-dependencies] - -[features] -# If set the full output is generated. Do NOT set when generating for wasm runtime. -full = [] diff --git a/substrate/frame/contracts/proc-macro/src/lib.rs b/substrate/frame/contracts/proc-macro/src/lib.rs index 9dc34d5223b2..403db15ac2cb 100644 --- a/substrate/frame/contracts/proc-macro/src/lib.rs +++ b/substrate/frame/contracts/proc-macro/src/lib.rs @@ -20,23 +20,13 @@ //! Most likely you should use the [`#[define_env]`][`macro@define_env`] attribute macro which hides //! boilerplate of defining external environment for a wasm module. -#![no_std] - -extern crate alloc; - -use alloc::{ - collections::BTreeMap, - format, - string::{String, ToString}, - vec::Vec, -}; use core::cmp::Reverse; use proc_macro::TokenStream; use proc_macro2::{Span, TokenStream as TokenStream2}; use quote::{quote, quote_spanned, ToTokens}; use syn::{ parse_macro_input, punctuated::Punctuated, spanned::Spanned, token::Comma, Data, DeriveInput, - FnArg, Ident, + Fields, FnArg, Ident, }; /// This derives `Debug` for a struct where each field must be of some numeric type. @@ -44,17 +34,6 @@ use syn::{ /// it is readable by humans. #[proc_macro_derive(WeightDebug)] pub fn derive_weight_debug(input: TokenStream) -> TokenStream { - derive_debug(input, format_weight) -} - -/// This is basically identical to the std libs Debug derive but without adding any -/// bounds to existing generics. -#[proc_macro_derive(ScheduleDebug)] -pub fn derive_schedule_debug(input: TokenStream) -> TokenStream { - derive_debug(input, format_default) -} - -fn derive_debug(input: TokenStream, fmt: impl Fn(&Ident) -> TokenStream2) -> TokenStream { let input = parse_macro_input!(input as DeriveInput); let name = &input.ident; let (impl_generics, ty_generics, where_clause) = input.generics.split_for_impl(); @@ -68,45 +47,15 @@ fn derive_debug(input: TokenStream, fmt: impl Fn(&Ident) -> TokenStream2) -> Tok .into() }; - #[cfg(feature = "full")] - let fields = iterate_fields(data, fmt); - - #[cfg(not(feature = "full"))] - let fields = { - drop(fmt); - let _ = data; - TokenStream2::new() - }; - - let tokens = quote! { - impl #impl_generics core::fmt::Debug for #name #ty_generics #where_clause { - fn fmt(&self, formatter: &mut core::fmt::Formatter<'_>) -> core::fmt::Result { - use ::sp_runtime::{FixedPointNumber, FixedU128 as Fixed}; - let mut formatter = formatter.debug_struct(stringify!(#name)); - #fields - formatter.finish() - } - } - }; - - tokens.into() -} - -/// This is only used then the `full` feature is activated. -#[cfg(feature = "full")] -fn iterate_fields(data: &syn::DataStruct, fmt: impl Fn(&Ident) -> TokenStream2) -> TokenStream2 { - use syn::Fields; - - match &data.fields { + let fields = match &data.fields { Fields::Named(fields) => { let recurse = fields.named.iter().filter_map(|f| { let name = f.ident.as_ref()?; if name.to_string().starts_with('_') { return None } - let value = fmt(name); let ret = quote_spanned! { f.span() => - formatter.field(stringify!(#name), #value); + formatter.field(stringify!(#name), &HumanWeight(self.#name)); }; Some(ret) }); @@ -119,39 +68,53 @@ fn iterate_fields(data: &syn::DataStruct, fmt: impl Fn(&Ident) -> TokenStream2) compile_error!("Unnamed fields are not supported") }, Fields::Unit => quote!(), - } -} + }; -fn format_weight(field: &Ident) -> TokenStream2 { - quote_spanned! { field.span() => - &if self.#field.ref_time() > 1_000_000_000 { - format!( - "{:.1?} ms, {} bytes", - Fixed::saturating_from_rational(self.#field.ref_time(), 1_000_000_000).to_float(), - self.#field.proof_size() - ) - } else if self.#field.ref_time() > 1_000_000 { - format!( - "{:.1?} µs, {} bytes", - Fixed::saturating_from_rational(self.#field.ref_time(), 1_000_000).to_float(), - self.#field.proof_size() - ) - } else if self.#field.ref_time() > 1_000 { - format!( - "{:.1?} ns, {} bytes", - Fixed::saturating_from_rational(self.#field.ref_time(), 1_000).to_float(), - self.#field.proof_size() - ) - } else { - format!("{} ps, {} bytes", self.#field.ref_time(), self.#field.proof_size()) + let tokens = quote! { + impl #impl_generics ::core::fmt::Debug for #name #ty_generics #where_clause { + fn fmt(&self, formatter: &mut ::core::fmt::Formatter<'_>) -> core::fmt::Result { + use ::sp_runtime::{FixedPointNumber, FixedU128 as Fixed}; + use ::core::{fmt, write}; + + struct HumanWeight(Weight); + + impl fmt::Debug for HumanWeight { + fn fmt(&self, formatter: &mut fmt::Formatter<'_>) -> fmt::Result { + if self.0.ref_time() > 1_000_000_000 { + write!( + formatter, + "{} ms, {} bytes", + Fixed::saturating_from_rational(self.0.ref_time(), 1_000_000_000).into_inner() / Fixed::accuracy(), + self.0.proof_size() + ) + } else if self.0.ref_time() > 1_000_000 { + write!( + formatter, + "{} µs, {} bytes", + Fixed::saturating_from_rational(self.0.ref_time(), 1_000_000).into_inner() / Fixed::accuracy(), + self.0.proof_size() + ) + } else if self.0.ref_time() > 1_000 { + write!( + formatter, + "{} ns, {} bytes", + Fixed::saturating_from_rational(self.0.ref_time(), 1_000).into_inner() / Fixed::accuracy(), + self.0.proof_size() + ) + } else { + write!(formatter, "{} ps, {} bytes", self.0.ref_time(), self.0.proof_size()) + } + } + } + + let mut formatter = formatter.debug_struct(stringify!(#name)); + #fields + formatter.finish() + } } - } -} + }; -fn format_default(field: &Ident) -> TokenStream2 { - quote_spanned! { field.span() => - &self.#field - } + tokens.into() } /// Parsed environment definition. @@ -480,7 +443,7 @@ fn expand_func_doc(func: &HostFn) -> TokenStream2 { fn expand_docs(def: &EnvDef) -> TokenStream2 { // Create the `Current` trait with only the newest versions // we sort so that only the newest versions make it into `docs` - let mut current_docs = BTreeMap::new(); + let mut current_docs = std::collections::HashMap::new(); let mut funcs: Vec<_> = def.host_funcs.iter().filter(|f| f.alias_to.is_none()).collect(); funcs.sort_unstable_by_key(|func| Reverse(func.version)); for func in funcs { @@ -493,7 +456,7 @@ fn expand_docs(def: &EnvDef) -> TokenStream2 { // Create the `legacy` module with all functions // Maps from version to list of functions that have this version - let mut legacy_doc = BTreeMap::>::new(); + let mut legacy_doc = std::collections::BTreeMap::>::new(); for func in def.host_funcs.iter() { legacy_doc.entry(func.version).or_default().push(expand_func_doc(&func)); } diff --git a/substrate/frame/contracts/src/benchmarking/mod.rs b/substrate/frame/contracts/src/benchmarking/mod.rs index f68f51c29066..e387c28b6714 100644 --- a/substrate/frame/contracts/src/benchmarking/mod.rs +++ b/substrate/frame/contracts/src/benchmarking/mod.rs @@ -2628,25 +2628,19 @@ benchmarks! { } // This is no benchmark. It merely exist to have an easy way to pretty print the currently - // configured `Schedule` during benchmark development. - // It can be outputted using the following command: - // cargo run --manifest-path=bin/node/cli/Cargo.toml \ - // --features runtime-benchmarks -- benchmark pallet --extra --dev --execution=native \ - // -p pallet_contracts -e print_schedule --no-median-slopes --no-min-squares + // configured `Schedule` during benchmark development. Check the README on how to print this. #[extra] #[pov_mode = Ignored] print_schedule { - #[cfg(feature = "std")] - { - let max_weight = ::BlockWeights::get().max_block; - let (weight_per_key, key_budget) = ContractInfo::::deletion_budget(max_weight); - println!("{:#?}", Schedule::::default()); - println!("###############################################"); - println!("Lazy deletion weight per key: {weight_per_key}"); - println!("Lazy deletion throughput per block: {key_budget}"); - } - #[cfg(not(feature = "std"))] - Err("Run this bench with a native runtime in order to see the schedule.")?; + let max_weight = ::BlockWeights::get().max_block; + let (weight_per_key, key_budget) = ContractInfo::::deletion_budget(max_weight); + let schedule = T::Schedule::get(); + log::info!(target: LOG_TARGET, " + {schedule:#?} + ############################################### + Lazy deletion weight per key: {weight_per_key} + Lazy deletion keys per block: {key_budget} + "); }: {} // Execute one erc20 transfer using the ink! erc20 example contract. diff --git a/substrate/frame/contracts/src/schedule.rs b/substrate/frame/contracts/src/schedule.rs index 9fa5217da43f..51c7c0bd9dd1 100644 --- a/substrate/frame/contracts/src/schedule.rs +++ b/substrate/frame/contracts/src/schedule.rs @@ -22,11 +22,9 @@ use crate::{weights::WeightInfo, Config}; use codec::{Decode, Encode}; use frame_support::{weights::Weight, DefaultNoBound}; -use pallet_contracts_proc_macro::{ScheduleDebug, WeightDebug}; use scale_info::TypeInfo; #[cfg(feature = "std")] use serde::{Deserialize, Serialize}; -use sp_runtime::RuntimeDebug; use sp_std::marker::PhantomData; /// Definition of the cost schedule and other parameterizations for the wasm vm. @@ -57,7 +55,8 @@ use sp_std::marker::PhantomData; /// ``` #[cfg_attr(feature = "std", derive(Serialize, Deserialize))] #[cfg_attr(feature = "std", serde(bound(serialize = "", deserialize = "")))] -#[derive(Clone, Encode, Decode, PartialEq, Eq, ScheduleDebug, DefaultNoBound, TypeInfo)] +#[cfg_attr(feature = "runtime-benchmarks", derive(frame_support::DebugNoBound))] +#[derive(Clone, Encode, Decode, PartialEq, Eq, DefaultNoBound, TypeInfo)] #[scale_info(skip_type_params(T))] pub struct Schedule { /// Describes the upper limits on various metrics. @@ -72,7 +71,8 @@ pub struct Schedule { /// Describes the upper limits on various metrics. #[cfg_attr(feature = "std", derive(Serialize, Deserialize))] -#[derive(Clone, Encode, Decode, PartialEq, Eq, RuntimeDebug, TypeInfo)] +#[cfg_attr(feature = "runtime-benchmarks", derive(Debug))] +#[derive(Clone, Encode, Decode, PartialEq, Eq, TypeInfo)] pub struct Limits { /// The maximum number of topics supported by an event. pub event_topics: u32, @@ -130,7 +130,8 @@ impl Limits { /// Gas metering of Wasm executed instructions is being done on the engine side. /// This struct holds a reference value used to gas units scaling between host and engine. #[cfg_attr(feature = "std", derive(Serialize, Deserialize))] -#[derive(Clone, Encode, Decode, PartialEq, Eq, ScheduleDebug, TypeInfo)] +#[cfg_attr(feature = "runtime-benchmarks", derive(frame_support::DebugNoBound))] +#[derive(Clone, Encode, Decode, PartialEq, Eq, TypeInfo)] #[scale_info(skip_type_params(T))] pub struct InstructionWeights { /// Base instruction `ref_time` Weight. @@ -143,7 +144,8 @@ pub struct InstructionWeights { /// Describes the weight for each imported function that a contract is allowed to call. #[cfg_attr(feature = "std", derive(Serialize, Deserialize))] -#[derive(Clone, Encode, Decode, PartialEq, Eq, WeightDebug, TypeInfo)] +#[cfg_attr(feature = "runtime-benchmarks", derive(pallet_contracts_proc_macro::WeightDebug))] +#[derive(Clone, Encode, Decode, PartialEq, Eq, TypeInfo)] #[scale_info(skip_type_params(T))] pub struct HostFnWeights { /// Weight of calling `seal_caller`. @@ -478,15 +480,3 @@ impl Default for HostFnWeights { } } } - -#[cfg(test)] -mod test { - use super::*; - use crate::tests::Test; - - #[test] - fn print_test_schedule() { - let schedule = Schedule::::default(); - println!("{:#?}", schedule); - } -}