diff --git a/Cargo.lock b/Cargo.lock index ad15a4bd8827e..c1973dad29b53 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5878,9 +5878,9 @@ dependencies = [ [[package]] name = "env_filter" -version = "0.1.0" +version = "0.1.3" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a009aa4810eb158359dda09d0c87378e4bbb89b5a801f016885a4707ba24f7ea" +checksum = "186e05a59d4c50738528153b83b0b0194d3a29507dfec16eccd4b342903397d0" dependencies = [ "log", "regex", @@ -6446,6 +6446,7 @@ dependencies = [ "cumulus-client-parachain-inherent", "cumulus-primitives-proof-size-hostfunction", "cumulus-test-runtime", + "env_filter", "frame-benchmarking", "frame-support", "frame-system", @@ -6481,6 +6482,7 @@ dependencies = [ "sp-io 40.0.1", "sp-keystore 0.42.0", "sp-runtime 41.1.0", + "sp-runtime-interface 29.0.1", "sp-state-machine 0.45.0", "sp-storage 22.0.0", "sp-timestamp", diff --git a/Cargo.toml b/Cargo.toml index b52a9897c3261..aa020a62925c5 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -763,6 +763,7 @@ either = { version = "1.8.1", default-features = false } emulated-integration-tests-common = { path = "cumulus/parachains/integration-tests/emulated/common", default-features = false } enumflags2 = { version = "0.7.11" } enumn = { version = "0.1.13" } +env_filter = { version = "0.1.3" } env_logger = { version = "0.11.2" } environmental = { version = "1.1.4", default-features = false } equivocation-detector = { path = "bridges/relays/equivocation" } diff --git a/prdoc/pr_8857.prdoc b/prdoc/pr_8857.prdoc new file mode 100644 index 0000000000000..b6f57c1cd2e8d --- /dev/null +++ b/prdoc/pr_8857.prdoc @@ -0,0 +1,12 @@ +title: "[FRAME] Custom log level for the runtime benchmarks" +doc: +- audience: Runtime Dev + description: |- + Changes: + - Add `--runtime-log` option to omni-bencher CLI + - Read env var `RUNTIME_LOG` as fallback to the `--runtime-log` option + - Set custom log level for runtime benchmarks that can be different form CLI level + - Fix issue where old runtimes have a space in the pallet or instance name from breaking change in `quote` macro +crates: +- name: frame-benchmarking-cli + bump: minor diff --git a/substrate/utils/frame/benchmarking-cli/Cargo.toml b/substrate/utils/frame/benchmarking-cli/Cargo.toml index f404c15eab9fb..e0888312ac82c 100644 --- a/substrate/utils/frame/benchmarking-cli/Cargo.toml +++ b/substrate/utils/frame/benchmarking-cli/Cargo.toml @@ -26,6 +26,7 @@ cumulus-client-parachain-inherent.default-features = true cumulus-client-parachain-inherent.workspace = true cumulus-primitives-proof-size-hostfunction.default-features = true cumulus-primitives-proof-size-hostfunction.workspace = true +env_filter = { workspace = true } frame-benchmarking.default-features = true frame-benchmarking.workspace = true frame-support.default-features = true @@ -84,6 +85,8 @@ sp-keystore.default-features = true sp-keystore.workspace = true sp-runtime.default-features = true sp-runtime.workspace = true +sp-runtime-interface.default-features = true +sp-runtime-interface.workspace = true sp-state-machine.default-features = true sp-state-machine.workspace = true sp-storage.default-features = true diff --git a/substrate/utils/frame/benchmarking-cli/src/pallet/command.rs b/substrate/utils/frame/benchmarking-cli/src/pallet/command.rs index 39a2070b7b4ef..2674b7ea71b2f 100644 --- a/substrate/utils/frame/benchmarking-cli/src/pallet/command.rs +++ b/substrate/utils/frame/benchmarking-cli/src/pallet/command.rs @@ -17,7 +17,7 @@ use super::{ types::{ComponentRange, ComponentRangeMap}, - writer, ListOutput, PalletCmd, + writer, ListOutput, PalletCmd, LOG_TARGET, }; use crate::{ pallet::{types::FetchedCode, GenesisBuilderPolicy}, @@ -50,7 +50,7 @@ use sp_keystore::{testing::MemoryKeystore, KeystoreExt}; use sp_runtime::traits::Hash; use sp_state_machine::StateMachine; use sp_trie::{proof_size_extension::ProofSizeExt, recorder::Recorder}; -use sp_wasm_interface::HostFunctions; +use sp_wasm_interface::{ExtendedHostFunctions, HostFunctions}; use std::{ borrow::Cow, collections::{BTreeMap, BTreeSet, HashMap}, @@ -60,11 +60,13 @@ use std::{ time, }; -/// Logging target -const LOG_TARGET: &'static str = "polkadot_sdk_frame::benchmark::pallet"; - -type SubstrateAndExtraHF = - (sp_io::SubstrateHostFunctions, frame_benchmarking::benchmarking::HostFunctions, T); +type SubstrateAndExtraHF = ( + ExtendedHostFunctions< + (sp_io::SubstrateHostFunctions, frame_benchmarking::benchmarking::HostFunctions), + super::logging::logging::HostFunctions, + >, + T, +); /// How the PoV size of a storage item should be estimated. #[derive(clap::ValueEnum, Debug, Eq, PartialEq, Clone, Copy)] pub enum PovEstimationMode { @@ -267,6 +269,7 @@ impl PalletCmd { }; return self.output_from_results(&batches) } + super::logging::init(self.runtime_log.clone()); let state_handler = self.state_handler_from_cli::>(chain_spec)?; @@ -730,7 +733,7 @@ impl PalletCmd { state: &'a BenchmarkingState, ) -> Result, H>> { if let Some(runtime) = self.runtime.as_ref() { - log::info!(target: LOG_TARGET, "Loading WASM from file"); + log::debug!(target: LOG_TARGET, "Loading WASM from file {}", runtime.display()); let code = fs::read(runtime).map_err(|e| { format!( "Could not load runtime file from path: {}, error: {}", diff --git a/substrate/utils/frame/benchmarking-cli/src/pallet/logging.rs b/substrate/utils/frame/benchmarking-cli/src/pallet/logging.rs new file mode 100644 index 0000000000000..f6a3c82d49dbb --- /dev/null +++ b/substrate/utils/frame/benchmarking-cli/src/pallet/logging.rs @@ -0,0 +1,89 @@ +// This file is part of Substrate. + +// Copyright (C) Parity Technologies (UK) Ltd. +// SPDX-License-Identifier: Apache-2.0 + +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +use super::LOG_TARGET; +use sp_core::{LogLevelFilter, RuntimeInterfaceLogLevel}; +use sp_runtime_interface::{ + pass_by::{PassAs, PassFatPointerAndRead, ReturnAs}, + runtime_interface, +}; +use std::cell::OnceCell; + +thread_local! { + /// Log level filter that the runtime will use. + /// + /// Must be initialized by the host before invoking the runtime executor. You may use `init` for + /// this or set it manually. The that can be set are either levels directly or filter like + // `warn,runtime=info`. + pub static RUNTIME_LOG: OnceCell = OnceCell::new(); +} + +/// Init runtime logger with the following priority (high to low): +/// - CLI argument +/// - Environment variable +/// - Default logger settings +pub fn init(arg: Option) { + let filter_str = arg.unwrap_or_else(|| { + if let Ok(env) = std::env::var("RUNTIME_LOG") { + env + } else { + log::max_level().to_string() + } + }); + + let filter = env_filter::Builder::new() + .try_parse(&filter_str) + .expect("Invalid runtime log filter") + .build(); + + RUNTIME_LOG.with(|cell| { + cell.set(filter).expect("Can be set by host"); + log::info!(target: LOG_TARGET, "Initialized runtime log filter to '{}'", filter_str); + }); +} + +/// Alternative implementation to `sp_runtime_interface::logging::HostFunctions` for benchmarking. +#[runtime_interface] +pub trait Logging { + #[allow(dead_code)] + fn log( + level: PassAs, + target: PassFatPointerAndRead<&str>, + message: PassFatPointerAndRead<&[u8]>, + ) { + let Ok(message) = core::str::from_utf8(message) else { + log::error!(target: LOG_TARGET, "Runtime tried to log invalid UTF-8 data"); + return; + }; + + let level = log::Level::from(level); + let metadata = log::MetadataBuilder::new().level(level).target(target).build(); + + if RUNTIME_LOG.with(|filter| filter.get().expect("Must be set by host").enabled(&metadata)) + { + log::log!(target: target, level, "{}", message); + } + } + + #[allow(dead_code)] + fn max_level() -> ReturnAs { + RUNTIME_LOG + // .filter() gives us the max level of this filter + .with(|filter| filter.get().expect("Must be set by host").filter()) + .into() + } +} diff --git a/substrate/utils/frame/benchmarking-cli/src/pallet/mod.rs b/substrate/utils/frame/benchmarking-cli/src/pallet/mod.rs index 5cb353059988c..7ac5c4436837a 100644 --- a/substrate/utils/frame/benchmarking-cli/src/pallet/mod.rs +++ b/substrate/utils/frame/benchmarking-cli/src/pallet/mod.rs @@ -16,6 +16,7 @@ // limitations under the License. mod command; +mod logging; mod types; mod writer; @@ -28,6 +29,9 @@ use sc_cli::{ }; use std::{fmt::Debug, path::PathBuf}; +/// Logging target +const LOG_TARGET: &'static str = "frame::benchmark::pallet"; + // Add a more relaxed parsing for pallet names by allowing pallet directory names with `-` to be // used like crate names with `_` fn parse_pallet_name(pallet: &str) -> std::result::Result { @@ -187,6 +191,13 @@ pub struct PalletCmd { #[arg(long, conflicts_with = "chain", required_if_eq("genesis_builder", "runtime"))] pub runtime: Option, + /// Set the runtime log level. + /// + /// This will overwrite the `RUNTIME_LOG` environment variable. If neither is set, the CLI + /// default set by `RUST_LOG` setting is used. + #[arg(long)] + pub runtime_log: Option, + /// Do not fail if there are unknown but also unused host functions in the runtime. #[arg(long)] pub allow_missing_host_functions: bool, diff --git a/substrate/utils/frame/benchmarking-cli/src/pallet/writer.rs b/substrate/utils/frame/benchmarking-cli/src/pallet/writer.rs index 28918dd4e6a39..e9312023611b9 100644 --- a/substrate/utils/frame/benchmarking-cli/src/pallet/writer.rs +++ b/substrate/utils/frame/benchmarking-cli/src/pallet/writer.rs @@ -467,7 +467,10 @@ pub(crate) fn write_results( file_name = format!("{}_{}", file_name, instance.to_snake_case()); } // "mod::pallet_name.rs" becomes "mod_pallet_name.rs". - file_path.push(file_name.replace("::", "_")); + file_name = file_name.replace("::", "_"); + // Some old runtimes have a bug with the pallet and instance name containing a space + file_name = file_name.replace(" ", ""); + file_path.push(file_name); file_path.set_extension("rs"); }