enabling any debug level, doubles block proposing time

[alexggh]

I was trying to measure proposing time for this #7540, and noticed that if you start your node with debug level enable for any target, even a non existent one, the proposing time of block doubles.

Starting collator with -linfo,alexggh=debug

2025-06-05 16:53:07.364  INFO tokio-runtime-worker sc_basic_authorship::basic_authorship: [Parachain] 🎁 Prepared block for proposing at 21492 (1351 ms) hash: 0x59ee96f72d1a1c317e68ae248f18159548ccbca46adf1b1f85a34b60f83c3218; parent_hash: 0xa8ba…b418; end: HitBlockWeightLimit; extrinsics_count: 1357    
2025-06-05 16:53:13.458  INFO tokio-runtime-worker sc_basic_authorship::basic_authorship: [Parachain] 🎁 Prepared block for proposing at 21493 (1417 ms) hash: 0x32a35c89858c9443c0794a14157a234b626b320b4479d5083a8b7147e1c3eea1; parent_hash: 0x5b3d…87c4; end: HitBlockWeightLimit; extrinsics_count: 1357    
2025-06-05 16:53:18.601  INFO tokio-runtime-worker sc_basic_authorship::basic_authorship: [Parachain] 🎁 Prepared block for proposing at 21494 (588 ms) hash: 0xa972a9beeddcfc5b5214b222497a6dab9802485e9e306b5df31be20481c30140; parent_hash: 0x4b76…c0d5; end: NoMoreTransactions; extrinsics_count: 582  

Starting collator with -linfo

2025-06-05 16:34:36 [Parachain] 🎁 Prepared block for proposing at 21347 (665 ms) hash: 0x7ca153243d29cfc121c0a92a6372763b47056c1b6cac8b7e1f279530203459db; parent_hash: 0x5acc…7c39; end: NoMoreTransactions; extrinsics_count: 1357    
2025-06-05 16:34:37 [Parachain] 🎁 Prepared block for proposing at 21347 (675 ms) hash: 0x2e1368df1588e6ac7383992ed5eb57fa820e1d10cb31824f124eb9edce581eec; parent_hash: 0x5acc…7c39; end: NoMoreTransactions; extrinsics_count: 1357    
2025-06-05 16:34:42 [Parachain] 🎁 Prepared block for proposing at 21348 (259 ms) hash: 0x363ac67af2ede1a931f6cf14888fa9cd578c2a4f824340376b5cbfb52bb16467; parent_hash: 0x8157…c721; end: NoMoreTransactions; extrinsics_count: 582  

Note!! I've tested both scenarios at least five times, to exclude other caching related impact and seems to happened both if you run with a trie-cache enabled or not.

This seems like a super weird side effect to me and it is probably a configuration mistake anyone can do.

It seems to be triggered by the fact that we are setting the tracing log to the maximum level, here

polkadot-sdk/substrate/client/tracing/src/logging/mod.rs

Line 177 in d054ac7

tracing_log::LogTracer::builder().with_max_level(max_level).init()?;

.

Another thing that might be worth checking is if this is a generic performance penalty or if it is just related to the call path for proposing a block.

[lexnv]

cc

• Fix max log level substrate#7851
• Logging takes quite some CPU time substrate#7800

[michalkucharczyk]

Just a thought: isn't it because tracing subscriber need to dynamically check the every tracing event? And match it against all the enabled modules?

It think about this code:
https://github.com/tokio-rs/tracing/blob/6e70c571d319a033d5f37c885ccf99aa675a9eac/tracing-subscriber/src/filter/env/mod.rs#L478

Not sure about exact configuration - so cannot reason about exact flow in this function. Also statics (at the end of the function) is just vec: https://github.com/tokio-rs/tracing/blob/d08e7a6eea1833810ea527e18ea03b08cd402c9d/tracing-subscriber/src/filter/directive.rs#L31

[skunert]

Looks like @koute dealt with similar issues some time ago: tokio-rs/tracing#1636

Are just missing the feature interest-cache here?

polkadot-sdk/Cargo.toml

Line 1419 in d54947d

tracing-log = { version = "0.2.0" }

[skunert]

As always, life is not so easy apparently:

• Disable the interest cache substrate#11854
• sc-tracing may not print log in some case after the tracing-log update to v0.1.3 with feature interest-cache substrate#11691

We will enable it again, when it is fixed upstream.

Okay, so maybe its time. TODO for this issue is to check the current status upstream, then enable this feature again.

[bkchr]

Upstream never moved 🙈 tokio-rs/tracing#2165

It seems to be triggered by the fact that we are setting the tracing log to the maximum level, here

This is how logging works. You have a global maximum log level and if this is enabled, you need to look into the individual target.