From 541692c4a80864f01b7dbbf65be43059318a73dc Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Fri, 23 Apr 2021 15:22:39 +0200 Subject: [PATCH] Use host max log level when initializing the `RuntimeLogger` (#8655) * Use host max log level when initializing the `RuntimeLogger` This should fix performance problems introduced by logging under certain circumstances. Before we always called into the host and the host was doing the log filtering, now as the correct max log level is set, we don't call into the host for every log line to check if it should be logged. However, we would still call into the host to determine if something should be logged when `something=trace` is given as we don't forward the log targets that are enabled. * Finish the pr --- substrate/primitives/core/src/lib.rs | 49 ++++++++++++++++++- substrate/primitives/io/src/lib.rs | 7 ++- .../primitives/runtime/src/runtime_logger.rs | 43 ++++++++-------- substrate/test-utils/runtime/src/lib.rs | 2 +- 4 files changed, 75 insertions(+), 26 deletions(-) diff --git a/substrate/primitives/core/src/lib.rs b/substrate/primitives/core/src/lib.rs index 1f1b88fe2f..8f97d59f21 100644 --- a/substrate/primitives/core/src/lib.rs +++ b/substrate/primitives/core/src/lib.rs @@ -281,7 +281,7 @@ pub trait TypeId { /// A log level matching the one from `log` crate. /// -/// Used internally by `sp_io::log` method. +/// Used internally by `sp_io::logging::log` method. #[derive(Encode, Decode, PassByEnum, Copy, Clone)] pub enum LogLevel { /// `Error` log level. @@ -334,6 +334,53 @@ impl From for log::Level { } } +/// Log level filter that expresses which log levels should be filtered. +/// +/// This enum matches the [`log::LogLevelFilter`] enum. +#[derive(Encode, Decode, PassByEnum, Copy, Clone)] +pub enum LogLevelFilter { + /// `Off` log level filter. + Off = 0, + /// `Error` log level filter. + Error = 1, + /// `Warn` log level filter. + Warn = 2, + /// `Info` log level filter. + Info = 3, + /// `Debug` log level filter. + Debug = 4, + /// `Trace` log level filter. + Trace = 5, +} + +impl From for log::LevelFilter { + fn from(l: LogLevelFilter) -> Self { + use self::LogLevelFilter::*; + match l { + Off => Self::Off, + Error => Self::Error, + Warn => Self::Warn, + Info => Self::Info, + Debug => Self::Debug, + Trace => Self::Trace, + } + } +} + +impl From for LogLevelFilter { + fn from(l: log::LevelFilter) -> Self { + use log::LevelFilter::*; + match l { + Off => Self::Off, + Error => Self::Error, + Warn => Self::Warn, + Info => Self::Info, + Debug => Self::Debug, + Trace => Self::Trace, + } + } +} + /// Encodes the given value into a buffer and returns the pointer and the length as a single `u64`. /// /// When Substrate calls into Wasm it expects a fixed signature for functions exported diff --git a/substrate/primitives/io/src/lib.rs b/substrate/primitives/io/src/lib.rs index e123008e5a..a7ad4c16c3 100644 --- a/substrate/primitives/io/src/lib.rs +++ b/substrate/primitives/io/src/lib.rs @@ -47,7 +47,7 @@ use sp_core::{ use sp_keystore::{KeystoreExt, SyncCryptoStore}; use sp_core::{ - OpaquePeerId, crypto::KeyTypeId, ed25519, sr25519, ecdsa, H256, LogLevel, + OpaquePeerId, crypto::KeyTypeId, ed25519, sr25519, ecdsa, H256, LogLevel, LogLevelFilter, offchain::{ Timestamp, HttpRequestId, HttpRequestStatus, HttpError, StorageKind, OpaqueNetworkState, }, @@ -1082,6 +1082,11 @@ pub trait Logging { ) } } + + /// Returns the max log level used by the host. + fn max_level() -> LogLevelFilter { + log::max_level().into() + } } #[derive(Encode, Decode)] diff --git a/substrate/primitives/runtime/src/runtime_logger.rs b/substrate/primitives/runtime/src/runtime_logger.rs index e27dc828cd..f747043901 100644 --- a/substrate/primitives/runtime/src/runtime_logger.rs +++ b/substrate/primitives/runtime/src/runtime_logger.rs @@ -40,22 +40,15 @@ impl RuntimeLogger { static LOGGER: RuntimeLogger = RuntimeLogger; let _ = log::set_logger(&LOGGER); - // Set max level to `TRACE` to ensure we propagate - // all log entries to the native side that will do the - // final filtering on what should be printed. - // - // If we don't set any level, logging is disabled - // completly. - log::set_max_level(log::LevelFilter::Trace); + // Use the same max log level as used by the host. + log::set_max_level(sp_io::logging::max_level().into()); } } impl log::Log for RuntimeLogger { - fn enabled(&self, _metadata: &log::Metadata) -> bool { - // to avoid calling to host twice, we pass everything - // and let the host decide what to print. - // If someone is initializing the logger they should - // know what they are doing. + fn enabled(&self, _: &log::Metadata) -> bool { + // The final filtering is done by the host. This is not perfect, as we would still call into + // the host for log lines that will be thrown away. true } @@ -81,11 +74,13 @@ mod tests { TestClientBuilder, runtime::TestAPI, }; use sp_api::{ProvideRuntimeApi, BlockId}; + use std::{env, str::FromStr}; #[test] - fn ensure_runtime_logger_works() { - if std::env::var("RUN_TEST").is_ok() { + fn ensure_runtime_logger_respects_host_max_log_level() { + if env::var("RUN_TEST").is_ok() { sp_tracing::try_init_simple(); + log::set_max_level(log::LevelFilter::from_str(&env::var("RUST_LOG").unwrap()).unwrap()); let client = TestClientBuilder::new() .set_execution_strategy(ExecutionStrategy::AlwaysWasm).build(); @@ -93,16 +88,18 @@ mod tests { let block_id = BlockId::Number(0); runtime_api.do_trace_log(&block_id).expect("Logging should not fail"); } else { - let executable = std::env::current_exe().unwrap(); - let output = std::process::Command::new(executable) - .env("RUN_TEST", "1") - .env("RUST_LOG", "trace") - .args(&["--nocapture", "ensure_runtime_logger_works"]) - .output() - .unwrap(); + for (level, should_print) in &[("trace", true), ("info", false)] { + let executable = std::env::current_exe().unwrap(); + let output = std::process::Command::new(executable) + .env("RUN_TEST", "1") + .env("RUST_LOG", level) + .args(&["--nocapture", "ensure_runtime_logger_respects_host_max_log_level"]) + .output() + .unwrap(); - let output = dbg!(String::from_utf8(output.stderr).unwrap()); - assert!(output.contains("Hey I'm runtime")); + let output = String::from_utf8(output.stderr).unwrap(); + assert!(output.contains("Hey I'm runtime") == *should_print); + } } } } diff --git a/substrate/test-utils/runtime/src/lib.rs b/substrate/test-utils/runtime/src/lib.rs index 150bc40373..dfd0ee6ae1 100644 --- a/substrate/test-utils/runtime/src/lib.rs +++ b/substrate/test-utils/runtime/src/lib.rs @@ -1019,7 +1019,7 @@ cfg_if! { } fn do_trace_log() { - log::error!("Hey I'm runtime: {}", log::STATIC_MAX_LEVEL); + log::trace!("Hey I'm runtime: {}", log::STATIC_MAX_LEVEL); } }