Skip to content
This repository was archived by the owner on Nov 15, 2023. It is now read-only.
Merged
Show file tree
Hide file tree
Changes from 4 commits
Commits
Show all changes
59 commits
Select commit Hold shift + click to select a range
0c480ef
Add filter reload handle
mattrutherford Oct 30, 2020
767f61a
add RPC, move logging module from cli to tracing
mattrutherford Oct 30, 2020
5643e7e
remove dup fn
mattrutherford Oct 30, 2020
cd8815e
working example
mattrutherford Oct 31, 2020
eb429e1
Update client/rpc-api/src/system/mod.rs
dvdplm Nov 2, 2020
884c1db
Prefer "set" to "reload"
dvdplm Nov 3, 2020
57ae457
Re-enable the commented out features of the logger
dvdplm Nov 4, 2020
297e75f
Merge branch 'master' into log-reloading
dvdplm Nov 4, 2020
7960ebb
Remove duplicate code
dvdplm Nov 4, 2020
8ca1301
cleanup
dvdplm Nov 4, 2020
2b11d45
unneeded lvar
dvdplm Nov 8, 2020
86ad90a
Merge branch 'master' into log-reloading
dvdplm Nov 9, 2020
1406207
Bump to latest patch release
dvdplm Nov 9, 2020
2d8dfa0
Add new CLI option to disable log filter reloading,
mattrutherford Nov 9, 2020
992e69c
Merge branch 'log-reloading' of github.com:paritytech/substrate into …
mattrutherford Nov 9, 2020
65ad10d
Apply suggestions from code review
mattrutherford Nov 9, 2020
d9a815a
Applied suggestions from reviews
mattrutherford Nov 10, 2020
f2c57fb
Fix calls to init_logger()
dvdplm Nov 11, 2020
1906cc9
Handle errors when parsing logging directives
dvdplm Nov 11, 2020
714eb48
Deny `system_setLogFilter` RPC by default
dvdplm Nov 11, 2020
3d7d458
One more time
dvdplm Nov 11, 2020
d82a74a
Don't ignore parse errors for log directives set via CLI or RPC
mattrutherford Nov 18, 2020
437295b
Merge branch 'log-reloading' of github.com:paritytech/substrate into …
mattrutherford Nov 18, 2020
ae4a0ac
Improve docs
mattrutherford Nov 18, 2020
f81577f
Apply suggestions from code review
mattrutherford Nov 18, 2020
b18002d
Update client/cli/src/config.rs
mattrutherford Nov 18, 2020
57bc9ac
Merge branch 'master' into log-reloading
mattrutherford Nov 18, 2020
1e8b115
fix merge errors
mattrutherford Nov 19, 2020
dbd3a12
include default directives with system_setLogFilter RPC,
mattrutherford Nov 19, 2020
8f4810f
Merge branch 'log-reloading' of github.com:paritytech/substrate into …
mattrutherford Nov 19, 2020
fd82f68
docs etc...
mattrutherford Nov 19, 2020
89f615d
update test
mattrutherford Nov 19, 2020
65f58b7
refactor: rename fn
mattrutherford Nov 19, 2020
4c51a08
Add a test for system_set_log_filter – NOTE: the code should likely c…
dvdplm Nov 20, 2020
04e1786
Update client/cli/src/lib.rs
dvdplm Nov 24, 2020
c0996c5
Address review grumbles
dvdplm Nov 24, 2020
68f208e
Merge branch 'log-reloading' of github.com:paritytech/substrate into …
dvdplm Nov 24, 2020
cd51835
Add doc note on panicking behaviour
dvdplm Nov 24, 2020
f41b93f
print all invalid directives before panic
mattrutherford Nov 24, 2020
23938a4
change RPCs to: addLogFilter and resetLogFilter
mattrutherford Nov 24, 2020
f90443a
make CLI log directives default
mattrutherford Nov 24, 2020
37565c1
add comments
mattrutherford Nov 24, 2020
d827037
restore previous behaviour to panic when hard-coded directives are in…
mattrutherford Nov 25, 2020
08c8753
change/refactor directive parsing
mattrutherford Nov 25, 2020
59ad63e
fix line width
mattrutherford Nov 25, 2020
2d96c18
add test for log filter reloading
mattrutherford Nov 27, 2020
3d49c2a
Apply suggestions from code review
mattrutherford Nov 30, 2020
098e730
finish up suggestions from code review
mattrutherford Nov 30, 2020
b5d4378
improve test
mattrutherford Nov 30, 2020
5da34f0
change expect message
mattrutherford Nov 30, 2020
728ed21
change fn name
mattrutherford Nov 30, 2020
990c0c9
Apply suggestions from code review
mattrutherford Nov 30, 2020
1a7cf5c
Apply suggestions from code review
mattrutherford Nov 30, 2020
b941066
add docs, remove unused fn
mattrutherford Nov 30, 2020
1207ef7
propagate Err on invalid log directive
mattrutherford Dec 1, 2020
042e4fe
Merge branch 'master' into log-reloading
mattrutherford Dec 1, 2020
397b09c
Update tracing-subscriber version
mattrutherford Dec 1, 2020
0489d8a
Improve docs for `disable_log_reloading` CLI param
mattrutherford Dec 2, 2020
5baa021
Merge branch 'master' into log-reloading
mattrutherford Dec 2, 2020
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
39 changes: 35 additions & 4 deletions Cargo.lock

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

4 changes: 2 additions & 2 deletions client/cli/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -44,9 +44,9 @@ structopt = "0.3.8"
sc-tracing = { version = "2.0.0", path = "../tracing" }
chrono = "0.4.10"
serde = "1.0.111"
tracing = "0.1.10"
tracing = "0.1.21"
tracing-log = "0.1.1"
tracing-subscriber = "0.2.10"
tracing-subscriber = "0.2.14"
sc-cli-proc-macro = { version = "2.0.0", path = "./proc-macro" }
thiserror = "1.0.21"

Expand Down
47 changes: 26 additions & 21 deletions client/cli/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -27,7 +27,6 @@ pub mod arg_enums;
mod commands;
mod config;
mod error;
mod logging;
mod params;
mod runner;

Expand All @@ -50,10 +49,14 @@ use structopt::{
#[doc(hidden)]
pub use tracing;
use tracing_subscriber::{
filter::Directive, fmt::time::ChronoLocal, layer::SubscriberExt, FmtSubscriber, Layer,
filter::Directive, fmt::time::ChronoLocal, layer::SubscriberExt, FmtSubscriber, Layer, fmt::Formatter, reload::Handle, EnvFilter
};
pub use sc_tracing::logging;

pub use logging::PREFIX_LOG_SPAN;
use tracing_subscriber::layer::Layered;
use crate::logging::{NodeNameLayer, EventFormat};
use tracing_subscriber::fmt::format::DefaultFields;

/// Substrate client CLI
///
Expand Down Expand Up @@ -243,21 +246,17 @@ pub fn init_logger(
pattern: &str,
tracing_receiver: sc_tracing::TracingReceiver,
profiling_targets: Option<String>,
) -> std::result::Result<(), String> {
fn parse_directives(dirs: impl AsRef<str>) -> Vec<Directive> {
dirs.as_ref()
.split(',')
.filter_map(|s| s.parse().ok())
.collect()
}
) -> std::result::Result<(), String>
{
use sc_tracing::parse_directives;

if let Err(e) = tracing_log::LogTracer::init() {
return Err(format!(
"Registering Substrate logger failed: {:}!", e
))
}

let mut env_filter = tracing_subscriber::EnvFilter::default()
let mut env_filter: EnvFilter = tracing_subscriber::EnvFilter::default()
// Disable info logging by default for some modules.
.add_directive("ws=off".parse().expect("provided directive is valid"))
.add_directive("yamux=off".parse().expect("provided directive is valid"))
Expand Down Expand Up @@ -316,18 +315,24 @@ pub fn init_logger(
"%Y-%m-%d %H:%M:%S%.3f".to_string()
});

let subscriber = FmtSubscriber::builder()
let subscriber_builder = FmtSubscriber::builder()
.with_env_filter(env_filter)
.with_writer(std::io::stderr)
.event_format(logging::EventFormat {
timer,
ansi: enable_color,
display_target: !simple,
display_level: !simple,
display_thread_name: !simple,
})
.finish().with(logging::NodeNameLayer);

// TODO: Q - There's a small cost to this, do we make it opt-in/out with cli flag?
.with_filter_reloading();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I investigated this and I think we should enable this by default until it can be proven to be significant for our use-case. In an artificial context the performance impact is significant: it's twice as slow, but we're talking about ~35ns –> ~70ns for the worst case. Once you add in all the filtering and other options we use the impact is negligible.

Benchmarks for a "complex" setup very similar to our own (but using a noop writer):

reload/complex-collector                                                                             
                        time:   [1.8996 us 1.9034 us 1.9076 us]
                        change: [-3.5626% -3.1266% -2.7425%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 1 outliers among 100 measurements (1.00%)
  1 (1.00%) high mild
reload/complex-collector-reloadable                                                                             
                        time:   [1.9313 us 1.9382 us 1.9456 us]
                        change: [-1.9828% -1.7096% -1.4540%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 1 outliers among 100 measurements (1.00%)
  1 (1.00%) high mild

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

OK - nice to have some figures for that. In that case I'll just add an opt-out CLI option --disable-log-reloading or similar

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One reason for leaving it on by default is that making it optional is nasty; the reloading changes the types such that I think we'd have to duplicate a lot of code (essentially everything from here to the end of the method). I don't think it's worth it.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

OK, that's a good point. But if it's not too ugly then IMO I think it's worth having - simply because if it's an optional performance configuration option implemented in tracing then I think we should mirror it.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'll try it out and we can see in review

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I just added a commit to do this - it worked out OK, only requiring 2 lines of duplicated code - one to finish the builder, another to call a new function that accepts a generic Subscriber. I don't think there is any downside to having this feature.

let handle = subscriber_builder.reload_handle();
let subscriber = subscriber_builder
// TODO: re-enable this
// .with_writer(std::io::stderr)
// .event_format(logging::EventFormat {
// timer,
// ansi: enable_color,
// display_target: !simple,
// display_level: !simple,
// display_thread_name: !simple,
// })
.finish()
.with(logging::NodeNameLayer);
sc_tracing::set_reload_handle(handle);
if let Some(profiling_targets) = profiling_targets {
let profiling = sc_tracing::ProfilingLayer::new(tracing_receiver, &profiling_targets);

Expand Down
5 changes: 5 additions & 0 deletions client/rpc-api/src/system/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -108,4 +108,9 @@ pub trait SystemApi<Hash, Number> {
/// known block.
#[rpc(name = "system_syncState", returns = "SyncState<Number>")]
fn system_sync_state(&self) -> Receiver<SyncState<Number>>;

/// Reloads the logging filter, replacing current with the supplied directives
#[rpc(name = "system_reloadLogFilter", returns = "()")]
fn system_reload_log_filter(&self, directives: String)
-> Result<(), jsonrpc_core::Error>;
}
1 change: 1 addition & 0 deletions client/rpc/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -37,6 +37,7 @@ sc-block-builder = { version = "0.8.0", path = "../../client/block-builder" }
sc-keystore = { version = "2.0.0", path = "../keystore" }
sp-transaction-pool = { version = "2.0.0", path = "../../primitives/transaction-pool" }
sp-blockchain = { version = "2.0.0", path = "../../primitives/blockchain" }
sc-tracing = { version = "2.0.0", path = "../../client/tracing" }
hash-db = { version = "0.15.2", default-features = false }
parking_lot = "0.10.0"
lazy_static = { version = "1.4.0", optional = true }
Expand Down
4 changes: 4 additions & 0 deletions client/rpc/src/system/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -197,4 +197,8 @@ impl<B: traits::Block> SystemApi<B::Hash, <B::Header as HeaderT>::Number> for Sy
let _ = self.send_back.unbounded_send(Request::SyncState(tx));
Receiver(Compat::new(rx))
}

fn system_reload_log_filter(&self, directives: String)-> std::result::Result<(), rpc::Error> {
sc_tracing::reload_filter(directives).map_err(|e| rpc::Error::internal_error())
}
}
5 changes: 4 additions & 1 deletion client/tracing/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -13,15 +13,18 @@ readme = "README.md"
targets = ["x86_64-unknown-linux-gnu"]

[dependencies]
ansi_term = "0.12.1"
tracing-log = "0.1.1"
erased-serde = "0.3.9"
log = { version = "0.4.8" }
once_cell = "1.4.1"
parking_lot = "0.10.0"
rustc-hash = "1.1.0"
serde = "1.0.101"
serde_json = "1.0.41"
slog = { version = "2.5.2", features = ["nested-values"] }
tracing = "0.1.21"
tracing-core = "0.1.17"
tracing-subscriber = "0.2.13"
tracing-subscriber = "0.2.14"
sp-tracing = { version = "2.0.0", path = "../../primitives/tracing" }
sc-telemetry = { version = "2.0.0", path = "../telemetry" }
35 changes: 34 additions & 1 deletion client/tracing/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@
//! See `sp-tracing` for examples on how to use tracing.
//!
//! Currently we provide `Log` (default), `Telemetry` variants for `Receiver`
pub mod logging;

use rustc_hash::FxHashMap;
use std::fmt;
Expand All @@ -37,12 +38,44 @@ use tracing::{
span::{Attributes, Id, Record},
subscriber::Subscriber,
};
use tracing_subscriber::{CurrentSpan, layer::{Layer, Context}};
use tracing_subscriber::{CurrentSpan, layer::{Layer, Context}, EnvFilter};

use sc_telemetry::{telemetry, SUBSTRATE_INFO};
use sp_tracing::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER};
use tracing_subscriber::reload::Handle;
use tracing_subscriber::fmt::Formatter;
use once_cell::sync::OnceCell;
use tracing_subscriber::filter::Directive;

const ZERO_DURATION: Duration = Duration::from_nanos(0);

static FILTER_RELOAD_HANDLE: OnceCell<Handle<EnvFilter, Formatter>> = OnceCell::new();

/// Initialize FILTER_RELOAD_HANDLE, only possible once
pub fn set_reload_handle(handle: Handle<EnvFilter, Formatter>) {
let _ = FILTER_RELOAD_HANDLE.set(handle);
}

/// Reload the logging filter with the supplied directives
pub fn reload_filter(directives: String) -> Result<(), String> {
let mut env_filter = tracing_subscriber::EnvFilter::default();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This means we oerride the default filters we always set in cli or not?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This should be fixed.

Copy link
Contributor Author

@mattrutherford mattrutherford Nov 18, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think the most sane way to do this is to get rid of all current filters and then supply all new ones required; from the POV of user practicality this makes sense to me (rather than have to submit multiple RPC calls to add or remove directives) - also it is the way the underlying tracing system works - there is no way to do this piecemeal in tracing_subscriber.

I think an RPC to get the current log directives could be useful.

If you think it's worth having we could also add 2 new RPCs add_directive and remove_directive. However would prefer this in a follow-up PR if possible.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Or we can have a raw_reload_log_filter and a reload_log_filter which uses the defaults.

And this should be done in this pr.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok that sounds good, I'll try it out...

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This should be resolved now

for directive in parse_directives(directives) {
env_filter = env_filter.add_directive(directive);
}
FILTER_RELOAD_HANDLE.get()
.ok_or("No reload handle present".to_string())?
.reload(env_filter)
.map_err(|e| format!("{}", e))
}

/// Parse the supplied text directives into `Vec<tracing_subscriber::filter::Directive>`
pub fn parse_directives(dirs: impl AsRef<str>) -> Vec<Directive> {
dirs.as_ref()
.split(',')
.filter_map(|s| s.parse().ok())
.collect()
}

/// Responsible for assigning ids to new spans, which are not re-used.
pub struct ProfilingLayer {
targets: Vec<(String, Level)>,
Expand Down
Loading