[FRAME] Custom log level for the runtime benchmarks

Cargo.toml

@@ -787,6 +787,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" }

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

substrate/utils/frame/benchmarking-cli/Cargo.toml

@@ -24,6 +24,7 @@ codec = { workspace = true, default-features = true }
 comfy-table = { workspace = true }
 cumulus-client-parachain-inherent = { workspace = true, default-features = true }
 cumulus-primitives-proof-size-hostfunction = { workspace = true, default-features = true }
+env_filter = { workspace = true }
 frame-benchmarking = { workspace = true, default-features = true }
 frame-storage-access-test-runtime = { workspace = true, default-features = true }
 frame-support = { workspace = true, default-features = true }
@@ -61,6 +62,7 @@ sp-inherents = { workspace = true, default-features = true }
 sp-io = { workspace = true, default-features = true }
 sp-keystore = { workspace = true, default-features = true }
 sp-runtime = { workspace = true, default-features = true }
+sp-runtime-interface = { workspace = true, default-features = true }
 sp-state-machine = { workspace = true, default-features = true }
 sp-storage = { workspace = true, default-features = true }
 sp-timestamp = { workspace = true, default-features = true }

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<T> =
-	(sp_io::SubstrateHostFunctions, frame_benchmarking::benchmarking::HostFunctions, T);
+type SubstrateAndExtraHF<T> = (
+	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 {
@@ -252,6 +254,7 @@ impl PalletCmd {
 			};
 			return self.output_from_results(&batches)
 		}
+		super::logging::init(self.runtime_log.clone());
 
 		let state_handler =
 			self.state_handler_from_cli::<SubstrateAndExtraHF<ExtraHostFunctions>>(chain_spec)?;
@@ -716,7 +719,7 @@ impl PalletCmd {
 		state: &'a BenchmarkingState<H>,
 	) -> Result<FetchedCode<'a, BenchmarkingState<H>, 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: {}",

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<env_filter::Filter> = OnceCell::new();
+}
+
+/// Init runtime logger with the following priority (high to low):
+/// - CLI argument
+/// - Environment variable
+/// - Default logger settings
+pub fn init(arg: Option<String>) {
+	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<RuntimeInterfaceLogLevel, u8>,
+		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<LogLevelFilter, u8> {
+		RUNTIME_LOG
+			// .filter() gives us the max level of this filter
+			.with(|filter| filter.get().expect("Must be set by host").filter())
+			.into()
+	}
+}

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<String, String> {
@@ -187,6 +191,13 @@ pub struct PalletCmd {
 	#[arg(long, conflicts_with = "chain", required_if_eq("genesis_builder", "runtime"))]
 	pub runtime: Option<PathBuf>,
 
+	/// 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<String>,
+
 	/// Do not fail if there are unknown but also unused host functions in the runtime.
 	#[arg(long)]
 	pub allow_missing_host_functions: bool,

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");
 		}