From 374f1b1b6258cc77d69513cd2f25e5bd7e0d4979 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Thu, 7 Oct 2021 22:45:34 +0200 Subject: [PATCH 1/5] Disable log reloading by default This disables the log reloading that was enabled by default. The problem is that the log reload implementation of `tracing` is using a lock to make the layer replaceable. This lock needs to be locked every time we need to check if a particular target is enabled (assuming the log level is high enough). This kills the performance when for example `sometarget=trace` logging is enabled. --- client/cli/src/config.rs | 10 +++++----- client/cli/src/params/shared_params.rs | 18 ++++++++++-------- client/tracing/src/logging/mod.rs | 2 +- 3 files changed, 16 insertions(+), 14 deletions(-) diff --git a/client/cli/src/config.rs b/client/cli/src/config.rs index 59fc6bd438a1c..7178611b58e40 100644 --- a/client/cli/src/config.rs +++ b/client/cli/src/config.rs @@ -522,7 +522,7 @@ pub trait CliConfiguration: Sized { dev_key_seed: self.dev_key_seed(is_dev)?, tracing_targets: self.tracing_targets()?, tracing_receiver: self.tracing_receiver()?, - disable_log_reloading: self.is_log_filter_reloading_disabled()?, + disable_log_reloading: self.enable_log_reloading()?, chain_spec, max_runtime_instances, announce_block: self.announce_block()?, @@ -542,9 +542,9 @@ pub trait CliConfiguration: Sized { Ok(self.shared_params().log_filters().join(",")) } - /// Is log reloading disabled (enabled by default) - fn is_log_filter_reloading_disabled(&self) -> Result { - Ok(self.shared_params().is_log_filter_reloading_disabled()) + /// Is log reloading enabled? + fn enable_log_reloading(&self) -> Result { + Ok(self.shared_params().enable_log_reloading()) } /// Should the log color output be disabled? @@ -563,7 +563,7 @@ pub trait CliConfiguration: Sized { sp_panic_handler::set(&C::support_url(), &C::impl_version()); let mut logger = LoggerBuilder::new(self.log_filters()?); - logger.with_log_reloading(!self.is_log_filter_reloading_disabled()?); + logger.with_log_reloading(!self.enable_log_reloading()?); if let Some(tracing_targets) = self.tracing_targets()? { let tracing_receiver = self.tracing_receiver()?; diff --git a/client/cli/src/params/shared_params.rs b/client/cli/src/params/shared_params.rs index 41472387d2639..8f22070800fc0 100644 --- a/client/cli/src/params/shared_params.rs +++ b/client/cli/src/params/shared_params.rs @@ -50,13 +50,15 @@ pub struct SharedParams { #[structopt(long)] pub disable_log_color: bool, - /// Disable feature to dynamically update and reload the log filter. + /// Enable feature to dynamically update and reload the log filter. + /// + /// Be aware that enabling this feature can lead to a performance decrease up to factor six or + /// more. Depending on the global logging level the performance decrease changes. /// - /// By default this feature is enabled, however it leads to a small performance decrease. /// The `system_addLogFilter` and `system_resetLogFilter` RPCs will have no effect with this - /// option set. - #[structopt(long = "disable-log-reloading")] - pub disable_log_reloading: bool, + /// option not being set. + #[structopt(long)] + pub enable_log_reloading: bool, /// Sets a custom profiling filter. Syntax is the same as for logging: = #[structopt(long = "tracing-targets", value_name = "TARGETS")] @@ -107,9 +109,9 @@ impl SharedParams { self.disable_log_color } - /// Is log reloading disabled - pub fn is_log_filter_reloading_disabled(&self) -> bool { - self.disable_log_reloading + /// Is log reloading enabled + pub fn enable_log_reloading(&self) -> bool { + self.enable_log_reloading } /// Receiver to process tracing messages. diff --git a/client/tracing/src/logging/mod.rs b/client/tracing/src/logging/mod.rs index dd0f7a5d8ae49..c6a4f070176e8 100644 --- a/client/tracing/src/logging/mod.rs +++ b/client/tracing/src/logging/mod.rs @@ -197,7 +197,7 @@ impl LoggerBuilder { Self { directives: directives.into(), profiling: None, - log_reloading: true, + log_reloading: false, force_colors: None, } } From 7a84ad24f727c146365df04f713f07b1560dd699 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Thu, 7 Oct 2021 22:54:09 +0200 Subject: [PATCH 2/5] :facepalm: --- client/cli/src/config.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/cli/src/config.rs b/client/cli/src/config.rs index 7178611b58e40..9a1bb241510ed 100644 --- a/client/cli/src/config.rs +++ b/client/cli/src/config.rs @@ -563,7 +563,7 @@ pub trait CliConfiguration: Sized { sp_panic_handler::set(&C::support_url(), &C::impl_version()); let mut logger = LoggerBuilder::new(self.log_filters()?); - logger.with_log_reloading(!self.enable_log_reloading()?); + logger.with_log_reloading(self.enable_log_reloading()?); if let Some(tracing_targets) = self.tracing_targets()? { let tracing_receiver = self.tracing_receiver()?; From 6acfaf697337c940d5f35dd028ac740175d6149a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Fri, 8 Oct 2021 09:45:10 +0200 Subject: [PATCH 3/5] Remove unused parameter --- client/cli/src/config.rs | 1 - client/service/src/config.rs | 2 -- client/service/test/src/lib.rs | 1 - test-utils/test-runner/src/utils.rs | 1 - 4 files changed, 5 deletions(-) diff --git a/client/cli/src/config.rs b/client/cli/src/config.rs index 9a1bb241510ed..05a3f2f3c168a 100644 --- a/client/cli/src/config.rs +++ b/client/cli/src/config.rs @@ -522,7 +522,6 @@ pub trait CliConfiguration: Sized { dev_key_seed: self.dev_key_seed(is_dev)?, tracing_targets: self.tracing_targets()?, tracing_receiver: self.tracing_receiver()?, - disable_log_reloading: self.enable_log_reloading()?, chain_spec, max_runtime_instances, announce_block: self.announce_block()?, diff --git a/client/service/src/config.rs b/client/service/src/config.rs index a98a34b473cee..b4f6bf70e05b0 100644 --- a/client/service/src/config.rs +++ b/client/service/src/config.rs @@ -118,8 +118,6 @@ pub struct Configuration { pub dev_key_seed: Option, /// Tracing targets pub tracing_targets: Option, - /// Is log filter reloading disabled - pub disable_log_reloading: bool, /// Tracing receiver pub tracing_receiver: sc_tracing::TracingReceiver, /// The size of the instances cache. diff --git a/client/service/test/src/lib.rs b/client/service/test/src/lib.rs index 8000c536cdf93..d85ad8d36111b 100644 --- a/client/service/test/src/lib.rs +++ b/client/service/test/src/lib.rs @@ -274,7 +274,6 @@ fn node_config< announce_block: true, base_path: Some(BasePath::new(root)), informant_output_format: Default::default(), - disable_log_reloading: false, } } diff --git a/test-utils/test-runner/src/utils.rs b/test-utils/test-runner/src/utils.rs index 8e8c84e6b4f8a..3ab77af96c16c 100644 --- a/test-utils/test-runner/src/utils.rs +++ b/test-utils/test-runner/src/utils.rs @@ -108,7 +108,6 @@ pub fn default_config(tokio_handle: Handle, mut chain_spec: Box) base_path: Some(base_path), wasm_runtime_overrides: None, informant_output_format, - disable_log_reloading: false, keystore_remote: None, keep_blocks: KeepBlocks::All, state_pruning: Default::default(), From 6fa1fe8591c3fc04ec814fabc91bd1f789cd222b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Fri, 8 Oct 2021 12:34:22 +0200 Subject: [PATCH 4/5] Fix test --- client/rpc/src/system/tests.rs | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/client/rpc/src/system/tests.rs b/client/rpc/src/system/tests.rs index 14997545031df..c64449ff13aa2 100644 --- a/client/rpc/src/system/tests.rs +++ b/client/rpc/src/system/tests.rs @@ -308,7 +308,10 @@ fn test_add_reset_log_filter() { // Enter log generation / filter reload if std::env::var("TEST_LOG_FILTER").is_ok() { - sc_tracing::logging::LoggerBuilder::new("test_before_add=debug").init().unwrap(); + let mut builder = sc_tracing::logging::LoggerBuilder::new("test_before_add=debug"); + builder.with_log_reloading(true); + builder.init().unwrap(); + for line in std::io::stdin().lock().lines() { let line = line.expect("Failed to read bytes"); if line.contains("add_reload") { From a50c29f84352842c67938ba3bd86153549479ce2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Fri, 8 Oct 2021 12:47:43 +0200 Subject: [PATCH 5/5] Fix --- bin/node/cli/benches/transaction_pool.rs | 1 - 1 file changed, 1 deletion(-) diff --git a/bin/node/cli/benches/transaction_pool.rs b/bin/node/cli/benches/transaction_pool.rs index c435012e9f86f..3b0ee26d7d597 100644 --- a/bin/node/cli/benches/transaction_pool.rs +++ b/bin/node/cli/benches/transaction_pool.rs @@ -99,7 +99,6 @@ fn new_node(tokio_handle: Handle) -> node_cli::service::NewFullBase { base_path: Some(base_path), informant_output_format: Default::default(), wasm_runtime_overrides: None, - disable_log_reloading: false, }; node_cli::service::new_full_base(config, |_, _| ()).expect("Creates node")